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, time.Second)()
initialTime := time.Date(2015, 2, 1, 10, 10, 0, 0, time.UTC)
nowFn := testutils.NowStub(GetTimeNow(), initialTime)
defer testutils.ResetNowStub(GetTimeNow())
// 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.ChannelOpts{
StatsReporter: serverStats,
}
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.ChannelOpts{StatsReporter: clientStats})
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)
}