-
Notifications
You must be signed in to change notification settings - Fork 3.8k
Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
61247: tracing: improve testing of shadow tracers and fix logging regression r=knz a=tbg Rearrange the existing test, and test the Zipkin tracer as well. Phase out the mockTracer; we can just use a zipkin tracer with an in-mem collector. Note that the updated tests also verify that if we create a span from a tracer configured with a shadow tracer (zipkin), that span does indeed record verbose log messages (cc @andreimatei). Release justification: testing improvement Release note: None Previously (i.e. pre the current cycle's tracing work), a trace that had a shadow trace attached to it was always regarded as verbose (and there was no explicit notion of verbosity; the span was recording, which equalled it being verbose). Now, verbose spans are those that collect all log messages in the crdb-internal span. The log package had not been updated to reflect this, so when a non-verbose span was set up with, say, a zipkin trace, it was not regarded as worth logging into by `log.Event` and friends. This commit fixes this as follows: - a span that has a shadow span but isn't explicitly set to verbose remains *non-verbose*, but - the logging framework (`ExpensiveLogEnabled`) asks the tracer whether an auxiliary logging sink is currently set up; if so it does relay all log messages to the trace span nevertheless, in effect restoring the old behavior. As a nice improvement, we are now giving log messages *only* to the shadow span. It used to be such that the messages were added to the shadow span *and* duplicated in the crdb-internal span, for no good reason. This alone should cut the memory overhead of running with an external trace collector by around 50%. Release justification: fixes a recent regression in tracing functionality Release note: None Co-authored-by: Tobias Grieger <[email protected]>
- Loading branch information
Showing
12 changed files
with
302 additions
and
263 deletions.
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,17 @@ | ||
| // Copyright 2021 The Cockroach Authors. | ||
| // | ||
| // Use of this software is governed by the Business Source License | ||
| // included in the file licenses/BSL.txt. | ||
| // | ||
| // As of the Change Date specified in that file, in accordance with | ||
| // the Business Source License, use of this software will be governed | ||
| // by the Apache License, Version 2.0, included in the file | ||
| // licenses/APL.txt. | ||
|
|
||
| package log | ||
|
|
||
| // NoLogV returns a verbosity level that will not result in VEvents and | ||
| // VErrEvents being logged. | ||
| func NoLogV() Level { | ||
| return logging.vmoduleConfig.verbosity.get() + 1 | ||
| } |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,119 @@ | ||
| // Copyright 2021 The Cockroach Authors. | ||
| // | ||
| // Use of this software is governed by the Business Source License | ||
| // included in the file licenses/BSL.txt. | ||
| // | ||
| // As of the Change Date specified in that file, in accordance with | ||
| // the Business Source License, use of this software will be governed | ||
| // by the Apache License, Version 2.0, included in the file | ||
| // licenses/APL.txt. | ||
|
|
||
| package log_test | ||
|
|
||
| import ( | ||
| "context" | ||
| "testing" | ||
|
|
||
| "github.com/cockroachdb/cockroach/pkg/settings/cluster" | ||
| "github.com/cockroachdb/cockroach/pkg/util/log" | ||
| "github.com/cockroachdb/cockroach/pkg/util/tracing" | ||
| "github.com/cockroachdb/logtags" | ||
| "github.com/stretchr/testify/require" | ||
| ) | ||
|
|
||
| func TestTrace(t *testing.T) { | ||
|
|
||
| for _, tc := range []struct { | ||
| name string | ||
| init func(context.Context) (context.Context, *tracing.Span) | ||
| check func(*testing.T, context.Context, *tracing.Span) | ||
| }{ | ||
| { | ||
| name: "verbose", | ||
| init: func(ctx context.Context) (context.Context, *tracing.Span) { | ||
| tracer := tracing.NewTracer() | ||
| sp := tracer.StartSpan("s", tracing.WithForceRealSpan()) | ||
| sp.SetVerbose(true) | ||
| ctxWithSpan := tracing.ContextWithSpan(ctx, sp) | ||
| return ctxWithSpan, sp | ||
| }, | ||
| check: func(t *testing.T, _ context.Context, sp *tracing.Span) { | ||
| if err := tracing.TestingCheckRecordedSpans(sp.GetRecording(), ` | ||
| span: s | ||
| tags: _verbose=1 | ||
| event: test1 | ||
| event: test2 | ||
| event: testerr | ||
| event: log | ||
| `); err != nil { | ||
| t.Fatal(err) | ||
| } | ||
| }, | ||
| }, | ||
| { | ||
| name: "zipkin", | ||
| init: func(ctx context.Context) (context.Context, *tracing.Span) { | ||
| tr := tracing.NewTracer() | ||
| st := cluster.MakeTestingClusterSettings() | ||
| tracing.ZipkinCollector.Override(&st.SV, "127.0.0.1:9000000") | ||
| tr.Configure(&st.SV) | ||
| return tr.StartSpanCtx(context.Background(), "foo") | ||
| }, | ||
| check: func(t *testing.T, ctx context.Context, sp *tracing.Span) { | ||
| // This isn't quite a real end-to-end-check, but it is good enough | ||
| // to give us confidence that we're really passing log events to | ||
| // the span, and the tracing package in turn has tests that verify | ||
| // that a span so configured will actually log them to the external | ||
| // trace. | ||
| require.True(t, sp.Tracer().HasExternalSink()) | ||
| require.True(t, log.HasSpanOrEvent(ctx)) | ||
| require.True(t, log.ExpensiveLogEnabled(ctx, 0 /* level */)) | ||
| }, | ||
| }, | ||
| } { | ||
| t.Run(tc.name, func(t *testing.T) { | ||
| ctx := context.Background() | ||
| // Events to context without a trace should be no-ops. | ||
| log.Event(ctx, "should-not-show-up") | ||
|
|
||
| ctxWithSpan, sp := tc.init(ctx) | ||
| log.Event(ctxWithSpan, "test1") | ||
| log.VEvent(ctxWithSpan, log.NoLogV(), "test2") | ||
| log.VErrEvent(ctxWithSpan, log.NoLogV(), "testerr") | ||
| log.Info(ctxWithSpan, "log") | ||
|
|
||
| // Events to parent context should still be no-ops. | ||
| log.Event(ctx, "should-not-show-up") | ||
|
|
||
| sp.Finish() | ||
| tc.check(t, ctxWithSpan, sp) | ||
| }) | ||
| } | ||
| } | ||
|
|
||
| func TestTraceWithTags(t *testing.T) { | ||
| ctx := context.Background() | ||
| ctx = logtags.AddTag(ctx, "tag", 1) | ||
|
|
||
| tracer := tracing.NewTracer() | ||
| sp := tracer.StartSpan("s", tracing.WithForceRealSpan()) | ||
| ctxWithSpan := tracing.ContextWithSpan(ctx, sp) | ||
| sp.SetVerbose(true) | ||
|
|
||
| log.Event(ctxWithSpan, "test1") | ||
| log.VEvent(ctxWithSpan, log.NoLogV(), "test2") | ||
| log.VErrEvent(ctxWithSpan, log.NoLogV(), "testerr") | ||
| log.Info(ctxWithSpan, "log") | ||
|
|
||
| sp.Finish() | ||
| if err := tracing.TestingCheckRecordedSpans(sp.GetRecording(), ` | ||
| span: s | ||
| tags: _verbose=1 | ||
| event: [tag=1] test1 | ||
| event: [tag=1] test2 | ||
| event: [tag=1] testerr | ||
| event: [tag=1] log | ||
| `); err != nil { | ||
| t.Fatal(err) | ||
| } | ||
| } |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Oops, something went wrong.