func TestStatsCalls(t *testing.T) {
defer testutils.SetTimeout(t, time.Second)()
initialTime := time.Date(2015, 2, 1, 10, 10, 0, 0, time.UTC)
clientNow, clientNowFn := testutils.NowStub(initialTime)
serverNow, serverNowFn := testutils.NowStub(initialTime)
clientNowFn(100 * time.Millisecond)
serverNowFn(50 * time.Millisecond)
clientStats := newRecordingStatsReporter()
serverStats := newRecordingStatsReporter()
serverOpts := testutils.NewOpts().
SetStatsReporter(serverStats).
SetTimeNow(serverNow)
WithVerifiedServer(t, serverOpts, func(serverCh *Channel, hostPort string) {
handler := raw.Wrap(newTestHandler(t))
serverCh.Register(handler, "echo")
serverCh.Register(handler, "app-error")
ch := testutils.NewClient(t, testutils.NewOpts().
SetStatsReporter(clientStats).
SetTimeNow(clientNow))
defer ch.Close()
ctx, cancel := NewContext(time.Second * 5)
defer cancel()
_, _, _, err := raw.Call(ctx, ch, hostPort, testServiceName, "echo", []byte("Headers"), []byte("Body"))
require.NoError(t, err)
outboundTags := tagsForOutboundCall(serverCh, ch, "echo")
clientStats.Expected.IncCounter("outbound.calls.send", outboundTags, 1)
clientStats.Expected.IncCounter("outbound.calls.success", outboundTags, 1)
clientStats.Expected.RecordTimer("outbound.calls.per-attempt.latency", outboundTags, 100*time.Millisecond)
clientStats.Expected.RecordTimer("outbound.calls.latency", outboundTags, 100*time.Millisecond)
inboundTags := tagsForInboundCall(serverCh, ch, "echo")
serverStats.Expected.IncCounter("inbound.calls.recvd", inboundTags, 1)
serverStats.Expected.IncCounter("inbound.calls.success", inboundTags, 1)
serverStats.Expected.RecordTimer("inbound.calls.latency", inboundTags, 50*time.Millisecond)
_, _, resp, err := raw.Call(ctx, ch, hostPort, testServiceName, "app-error", nil, nil)
require.NoError(t, err)
require.True(t, resp.ApplicationError(), "expected application error")
outboundTags = tagsForOutboundCall(serverCh, ch, "app-error")
clientStats.Expected.IncCounter("outbound.calls.send", outboundTags, 1)
clientStats.Expected.IncCounter("outbound.calls.per-attempt.app-errors", outboundTags, 1)
clientStats.Expected.IncCounter("outbound.calls.app-errors", outboundTags, 1)
clientStats.Expected.RecordTimer("outbound.calls.per-attempt.latency", outboundTags, 100*time.Millisecond)
clientStats.Expected.RecordTimer("outbound.calls.latency", outboundTags, 100*time.Millisecond)
inboundTags = tagsForInboundCall(serverCh, ch, "app-error")
serverStats.Expected.IncCounter("inbound.calls.recvd", inboundTags, 1)
serverStats.Expected.IncCounter("inbound.calls.app-errors", inboundTags, 1)
serverStats.Expected.RecordTimer("inbound.calls.latency", inboundTags, 50*time.Millisecond)
})
clientStats.Validate(t)
serverStats.Validate(t)
}
func TestStatsCalls(t *testing.T) {
defer testutils.SetTimeout(t, time.Second)()
initialTime := time.Date(2015, 2, 1, 10, 10, 0, 0, time.UTC)
nowStub, nowFn := testutils.NowStub(initialTime)
// time.Now will be called in this order for each call:
// sender records time they started sending
// receiver records time the request is sent to application
// receiver calculates application handler latency
// sender records call latency
// so expected inbound latency = incrementor, outbound = 3 * incrementor
clientStats := newRecordingStatsReporter()
serverStats := newRecordingStatsReporter()
serverOpts := testutils.NewOpts().
SetStatsReporter(serverStats).
SetTimeNow(nowStub)
WithVerifiedServer(t, serverOpts, func(serverCh *Channel, hostPort string) {
handler := raw.Wrap(newTestHandler(t))
serverCh.Register(handler, "echo")
serverCh.Register(handler, "app-error")
ch, err := testutils.NewClient(testutils.NewOpts().
SetStatsReporter(clientStats).
SetTimeNow(nowStub))
require.NoError(t, err)
ctx, cancel := NewContext(time.Second * 5)
defer cancel()
// Set now incrementor to 50ms, so expected Inbound latency is 50ms, outbound is 150ms.
nowFn(50 * time.Millisecond)
_, _, _, err = raw.Call(ctx, ch, hostPort, testServiceName, "echo", []byte("Headers"), []byte("Body"))
require.NoError(t, err)
outboundTags := tagsForOutboundCall(serverCh, ch, "echo")
clientStats.Expected.IncCounter("outbound.calls.send", outboundTags, 1)
clientStats.Expected.IncCounter("outbound.calls.success", outboundTags, 1)
clientStats.Expected.RecordTimer("outbound.calls.latency", outboundTags, 150*time.Millisecond)
inboundTags := tagsForInboundCall(serverCh, ch, "echo")
serverStats.Expected.IncCounter("inbound.calls.recvd", inboundTags, 1)
serverStats.Expected.IncCounter("inbound.calls.success", inboundTags, 1)
serverStats.Expected.RecordTimer("inbound.calls.latency", inboundTags, 50*time.Millisecond)
// Expected inbound latency = 70ms, outbound = 210ms.
nowFn(70 * time.Millisecond)
_, _, resp, err := raw.Call(ctx, ch, hostPort, testServiceName, "app-error", nil, nil)
require.NoError(t, err)
require.True(t, resp.ApplicationError(), "expected application error")
outboundTags = tagsForOutboundCall(serverCh, ch, "app-error")
clientStats.Expected.IncCounter("outbound.calls.send", outboundTags, 1)
clientStats.Expected.IncCounter("outbound.calls.app-errors", outboundTags, 1)
clientStats.Expected.RecordTimer("outbound.calls.latency", outboundTags, 210*time.Millisecond)
inboundTags = tagsForInboundCall(serverCh, ch, "app-error")
serverStats.Expected.IncCounter("inbound.calls.recvd", inboundTags, 1)
serverStats.Expected.IncCounter("inbound.calls.app-errors", inboundTags, 1)
serverStats.Expected.RecordTimer("inbound.calls.latency", inboundTags, 70*time.Millisecond)
})
clientStats.Validate(t)
serverStats.Validate(t)
}
func TestTraceReportingEnabled(t *testing.T) {
initialTime := time.Date(2015, 2, 1, 10, 10, 0, 0, time.UTC)
var gotCalls []traceReportArgs
var gotSpans []Span
testTraceReporter := TraceReporterFunc(func(span Span, annotations []Annotation, binaryAnnotations []BinaryAnnotation, targetEndpoint TargetEndpoint) {
gotCalls = append(gotCalls, traceReportArgs{annotations, binaryAnnotations, targetEndpoint})
gotSpans = append(gotSpans, span)
})
traceReporterOpts := &testutils.ChannelOpts{TraceReporter: testTraceReporter}
tests := []struct {
name string
serverOpts *testutils.ChannelOpts
clientOpts *testutils.ChannelOpts
expected []Annotation
}{
{
name: "inbound",
serverOpts: traceReporterOpts,
expected: []Annotation{
{Key: "sr", Timestamp: initialTime.Add(3 * time.Second)},
{Key: "ss", Timestamp: initialTime.Add(5 * time.Second)},
},
},
{
name: "outbound",
clientOpts: traceReporterOpts,
expected: []Annotation{
{Key: "cs", Timestamp: initialTime.Add(1 * time.Second)},
{Key: "cr", Timestamp: initialTime.Add(7 * time.Second)},
},
},
}
for _, tt := range tests {
gotCalls, gotSpans = nil, nil
addFn := testutils.NowStub(GetTimeNow(), initialTime)
defer testutils.ResetNowStub(GetTimeNow())
addFn(time.Second)
WithVerifiedServer(t, tt.serverOpts, func(ch *Channel, hostPort string) {
ch.Register(raw.Wrap(newTestHandler(t)), "echo")
clientCh, err := testutils.NewClient(tt.clientOpts)
require.NoError(t, err, "NewClient failed")
ctx, cancel := NewContext(time.Second)
defer cancel()
_, _, _, err = raw.Call(ctx, clientCh, hostPort, ch.PeerInfo().ServiceName, "echo", nil, []byte("arg3"))
require.NoError(t, err, "raw.Call failed")
binaryAnnotations := []BinaryAnnotation{
{"cn", clientCh.PeerInfo().ServiceName},
{"as", Raw.String()},
}
targetEndpoint := TargetEndpoint{
HostPort: hostPort,
ServiceName: ch.PeerInfo().ServiceName,
Operation: "echo",
}
expected := []traceReportArgs{{tt.expected, binaryAnnotations, targetEndpoint}}
assert.Equal(t, expected, gotCalls, "%v: Report args mismatch", tt.name)
curSpan := CurrentSpan(ctx)
assert.Equal(t, NewSpan(curSpan.TraceID(), 0, curSpan.TraceID()), gotSpans[0], "Span mismatch")
})
}
}
func TestStatsCalls(t *testing.T) {
defer testutils.SetTimeout(t, 2*time.Second)()
tests := []struct {
method string
wantErr bool
}{
{
method: "echo",
},
{
method: "app-error",
wantErr: true,
},
}
for _, tt := range tests {
initialTime := time.Date(2015, 2, 1, 10, 10, 0, 0, time.UTC)
clientNow, clientNowFn := testutils.NowStub(initialTime)
serverNow, serverNowFn := testutils.NowStub(initialTime)
clientNowFn(100 * time.Millisecond)
serverNowFn(50 * time.Millisecond)
clientStats := newRecordingStatsReporter()
serverStats := newRecordingStatsReporter()
serverOpts := testutils.NewOpts().
SetStatsReporter(serverStats).
SetTimeNow(serverNow)
WithVerifiedServer(t, serverOpts, func(serverCh *Channel, hostPort string) {
handler := raw.Wrap(newTestHandler(t))
serverCh.Register(handler, "echo")
serverCh.Register(handler, "app-error")
ch := testutils.NewClient(t, testutils.NewOpts().
SetStatsReporter(clientStats).
SetTimeNow(clientNow))
defer ch.Close()
ctx, cancel := NewContext(time.Second * 5)
defer cancel()
_, _, resp, err := raw.Call(ctx, ch, hostPort, testutils.DefaultServerName, tt.method, nil, nil)
require.NoError(t, err, "Call(%v) should fail", tt.method)
assert.Equal(t, tt.wantErr, resp.ApplicationError(), "Call(%v) check application error")
outboundTags := tagsForOutboundCall(serverCh, ch, tt.method)
inboundTags := tagsForInboundCall(serverCh, ch, tt.method)
clientStats.Expected.IncCounter("outbound.calls.send", outboundTags, 1)
clientStats.Expected.RecordTimer("outbound.calls.per-attempt.latency", outboundTags, 100*time.Millisecond)
clientStats.Expected.RecordTimer("outbound.calls.latency", outboundTags, 100*time.Millisecond)
serverStats.Expected.IncCounter("inbound.calls.recvd", inboundTags, 1)
serverStats.Expected.RecordTimer("inbound.calls.latency", inboundTags, 50*time.Millisecond)
if tt.wantErr {
clientStats.Expected.IncCounter("outbound.calls.per-attempt.app-errors", outboundTags, 1)
clientStats.Expected.IncCounter("outbound.calls.app-errors", outboundTags, 1)
serverStats.Expected.IncCounter("inbound.calls.app-errors", inboundTags, 1)
} else {
clientStats.Expected.IncCounter("outbound.calls.success", outboundTags, 1)
serverStats.Expected.IncCounter("inbound.calls.success", inboundTags, 1)
}
})
clientStats.Validate(t)
serverStats.Validate(t)
}
}
func TestStatsWithRetries(t *testing.T) {
defer testutils.SetTimeout(t, 2*time.Second)()
a := testutils.DurationArray
initialTime := time.Date(2015, 2, 1, 10, 10, 0, 0, time.UTC)
nowStub, nowFn := testutils.NowStub(initialTime)
clientStats := newRecordingStatsReporter()
ch := testutils.NewClient(t, testutils.NewOpts().
SetStatsReporter(clientStats).
SetTimeNow(nowStub))
defer ch.Close()
nowFn(10 * time.Millisecond)
ctx, cancel := NewContext(time.Second)
defer cancel()
// TODO why do we need this??
opts := testutils.NewOpts().NoRelay()
WithVerifiedServer(t, opts, func(serverCh *Channel, hostPort string) {
respErr := make(chan error, 1)
testutils.RegisterFunc(serverCh, "req", func(ctx context.Context, args *raw.Args) (*raw.Res, error) {
return &raw.Res{Arg2: args.Arg2, Arg3: args.Arg3}, <-respErr
})
ch.Peers().Add(serverCh.PeerInfo().HostPort)
// timeNow is called at:
// RunWithRetry start, per-attempt start, per-attempt end.
// Each attempt takes 2 * step.
tests := []struct {
expectErr error
numFailures int
numAttempts int
overallLatency time.Duration
perAttemptLatencies []time.Duration
}{
{
numFailures: 0,
numAttempts: 1,
perAttemptLatencies: a(10 * time.Millisecond),
overallLatency: 20 * time.Millisecond,
},
{
numFailures: 1,
numAttempts: 2,
perAttemptLatencies: a(10*time.Millisecond, 10*time.Millisecond),
overallLatency: 40 * time.Millisecond,
},
{
numFailures: 4,
numAttempts: 5,
perAttemptLatencies: a(10*time.Millisecond, 10*time.Millisecond, 10*time.Millisecond, 10*time.Millisecond, 10*time.Millisecond),
overallLatency: 100 * time.Millisecond,
},
{
numFailures: 5,
numAttempts: 5,
expectErr: ErrServerBusy,
perAttemptLatencies: a(10*time.Millisecond, 10*time.Millisecond, 10*time.Millisecond, 10*time.Millisecond, 10*time.Millisecond),
overallLatency: 100 * time.Millisecond,
},
}
for _, tt := range tests {
clientStats.Reset()
err := ch.RunWithRetry(ctx, func(ctx context.Context, rs *RequestState) error {
if rs.Attempt > tt.numFailures {
respErr <- nil
} else {
respErr <- ErrServerBusy
}
sc := ch.GetSubChannel(serverCh.ServiceName())
_, err := raw.CallV2(ctx, sc, raw.CArgs{
Method: "req",
CallOptions: &CallOptions{RequestState: rs},
})
return err
})
assert.Equal(t, tt.expectErr, err, "RunWithRetry unexpected error")
outboundTags := tagsForOutboundCall(serverCh, ch, "req")
if tt.expectErr == nil {
clientStats.Expected.IncCounter("outbound.calls.success", outboundTags, 1)
}
clientStats.Expected.IncCounter("outbound.calls.send", outboundTags, int64(tt.numAttempts))
for i, latency := range tt.perAttemptLatencies {
clientStats.Expected.RecordTimer("outbound.calls.per-attempt.latency", outboundTags, latency)
if i > 0 {
tags := tagsForOutboundCall(serverCh, ch, "req")
tags["retry-count"] = fmt.Sprint(i)
clientStats.Expected.IncCounter("outbound.calls.retries", tags, 1)
}
}
clientStats.Expected.RecordTimer("outbound.calls.latency", outboundTags, tt.overallLatency)
clientStats.Validate(t)
}
})
}
func TestTraceReportingEnabled(t *testing.T) {
initialTime := time.Date(2015, 2, 1, 10, 10, 0, 0, time.UTC)
var state struct {
signal chan struct{}
call TraceData
span Span
}
testTraceReporter := TraceReporterFunc(func(data TraceData) {
defer close(state.signal)
span := data.Span
data.Span = Span{}
state.call = data
state.span = span
})
traceReporterOpts := testutils.NewOpts().SetTraceReporter(testTraceReporter)
tests := []struct {
name string
serverOpts *testutils.ChannelOpts
clientOpts *testutils.ChannelOpts
expected []Annotation
fromServer bool
}{
{
name: "inbound",
serverOpts: traceReporterOpts,
expected: []Annotation{
{Key: "sr", Timestamp: initialTime.Add(2 * time.Second)},
{Key: "ss", Timestamp: initialTime.Add(3 * time.Second)},
},
fromServer: true,
},
{
name: "outbound",
clientOpts: traceReporterOpts,
expected: []Annotation{
{Key: "cs", Timestamp: initialTime.Add(time.Second)},
{Key: "cr", Timestamp: initialTime.Add(6 * time.Second)},
},
},
}
for _, tt := range tests {
state.signal = make(chan struct{})
serverNow, serverNowFn := testutils.NowStub(initialTime.Add(time.Second))
clientNow, clientNowFn := testutils.NowStub(initialTime)
serverNowFn(time.Second)
clientNowFn(time.Second)
tt.serverOpts = testutils.DefaultOpts(tt.serverOpts).SetTimeNow(serverNow)
tt.clientOpts = testutils.DefaultOpts(tt.clientOpts).SetTimeNow(clientNow)
WithVerifiedServer(t, tt.serverOpts, func(ch *Channel, hostPort string) {
testutils.RegisterEcho(ch, func() {
clientNowFn(5 * time.Second)
})
clientCh := testutils.NewClient(t, tt.clientOpts)
defer clientCh.Close()
ctx, cancel := NewContext(time.Second)
defer cancel()
_, _, _, err := raw.Call(ctx, clientCh, hostPort, ch.PeerInfo().ServiceName, "echo", nil, []byte("arg3"))
require.NoError(t, err, "raw.Call failed")
binaryAnnotations := []BinaryAnnotation{
{"cn", clientCh.PeerInfo().ServiceName},
{"as", Raw.String()},
}
target := TraceEndpoint{
HostPort: hostPort,
ServiceName: ch.ServiceName(),
}
source := target
if !tt.fromServer {
source = TraceEndpoint{
HostPort: "0.0.0.0:0",
ServiceName: clientCh.ServiceName(),
}
}
select {
case <-state.signal:
case <-time.After(time.Second):
t.Fatalf("Did not receive trace report within timeout")
}
expected := TraceData{Annotations: tt.expected, BinaryAnnotations: binaryAnnotations, Source: source, Target: target, Method: "echo"}
assert.Equal(t, expected, state.call, "%v: Report args mismatch", tt.name)
curSpan := CurrentSpan(ctx)
assert.Equal(t, NewSpan(curSpan.TraceID(), 0, curSpan.TraceID()), state.span, "Span mismatch")
})
}
}