Tracing: Add span logger

[oncilla]

This PR adds a span logger that implements the log.Logger interface.
The span logger logs to file and additionally attaches the log entry
to the current span in the context.

Additionally:

• Add tracing ID transfer in the sciond API
• Add tracing support to the cert_req and end2end integration tests
• Add log statements to the trust store
• Unify the logger setup between sciond API, quic and legacy msgr
• Update jaeger version

---

This change is 

[lukedirtwalker]

Reviewed 33 of 33 files at r1.
Reviewable status: all files reviewed, 10 unresolved discussions (waiting on @oncilla)

a discussion (no related file):

the a log entry
remove a in the description

---

a discussion (no related file):
Also add that this upgrades the jaeger version in the topology generator

---

a discussion (no related file):
good stuff 💯

---

---

go/integration/common.go, line 73 at r1 (raw file):

	}
	opentracing.SetGlobalTracer(tr)
	close := func() {

close is not a good name, there is a builtin function called close already

---

go/integration/cert_req/main.go, line 55 at r1 (raw file):

	integration.Setup()

	close, err := integration.InitTracer("cert_req")

close is not a good name, there is a builtin function called close already

---

go/integration/end2end/main.go, line 64 at r1 (raw file):

	validateFlags()

	close, err := integration.InitTracer("end_2_end")

ditto name

---

go/lib/infra/messenger/messenger.go, line 378 at r1 (raw file):

}

func traceId(ctx context.Context) common.RawBytes {

Remove this?

---

go/lib/log/span.go, line 31 at r1 (raw file):

// SpanFromCtx returns a span logger. The span is nil, if the context has no
// span attached.
func SpanFromCtx(ctx context.Context) Span {

Hm I wonder if it would make sense to just merge this with FromCtx:

func FromCtx(ctx context.Context) Logger {
	logger := fromCtx(ctx)
	if ctx == nil {
		return logger
	}
	span := opentracing.SpanFromContext(ctx)
	if span == nil {
		return logger
	}
	return Span{
		Logger: logger,
		Span:   span,
	}
}

then by default all existing apps get the new behavior :)
Note that Span will also need to implement GetHandler to be conformant to the logger interface.

---

go/lib/log/span.go, line 43 at r1 (raw file):

// Trace logs to the logger and span.
func (s Span) Trace(msg string, ctx ...interface{}) {

damn we should really get rid of a few of those levels

---

go/lib/scrypto/version.go, line 42 at r1 (raw file):

}

func (v Version) String() string {

Unrelated, but ok

---

go/lib/tracing/context.go, line 47 at r1 (raw file):

func IDFromCtx(ctx context.Context) []byte {
	span, tracer := opentracing.SpanFromContext(ctx), opentracing.GlobalTracer()
	if span != nil && tracer != nil {

I think it would be nicer if we do an early exit:

if span == nil || tracer == nil {
   return nil
}

Now that I think about it, tracer should never be nil, if tracing is disabled, a nooptracer will be set instead.

---

go/lib/tracing/context.go, line 51 at r1 (raw file):

		err := tracer.Inject(span.Context(), opentracing.Binary, &tracingBin)
		if err != nil {
			panic(err)

I guess we are reasonably sure that this can never happen? Maybe add a comment that this should never happen since opentracing.Binary is a builtin format and thus must be supported by all tracer implementations.

[oncilla]

Reviewable status: 20 of 35 files reviewed, 10 unresolved discussions (waiting on @lukedirtwalker)

a discussion (no related file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

the a log entry
remove a in the description

Done.

---

a discussion (no related file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

Also add that this upgrades the jaeger version in the topology generator

Done.

---

---

go/integration/common.go, line 73 at r1 (raw file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

close is not a good name, there is a builtin function called close already

very true.
Done.

---

go/integration/cert_req/main.go, line 55 at r1 (raw file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

close is not a good name, there is a builtin function called close already

Done.

---

go/integration/end2end/main.go, line 64 at r1 (raw file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

ditto name

Done.

---

go/lib/infra/messenger/messenger.go, line 378 at r1 (raw file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

Remove this?

Done.

---

go/lib/log/span.go, line 31 at r1 (raw file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

Hm I wonder if it would make sense to just merge this with FromCtx:

func FromCtx(ctx context.Context) Logger {
	logger := fromCtx(ctx)
	if ctx == nil {
		return logger
	}
	span := opentracing.SpanFromContext(ctx)
	if span == nil {
		return logger
	}
	return Span{
		Logger: logger,
		Span:   span,
	}
}

then by default all existing apps get the new behavior :)
Note that Span will also need to implement GetHandler to be conformant to the logger interface.

Hm, yeah. You are right.
I was worried at first about the performance hit. But then we don't use a high performance logging library in the first place 🤷‍♂️
And if the tracer is not enabled it is basically a noop.

---

go/lib/scrypto/version.go, line 42 at r1 (raw file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

Unrelated, but ok

I noticed during trace investigation.
To people not familiar, 0 does not really indicate a special case.

---

go/lib/tracing/context.go, line 47 at r1 (raw file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

I think it would be nicer if we do an early exit:

if span == nil || tracer == nil {
   return nil
}

Now that I think about it, tracer should never be nil, if tracing is disabled, a nooptracer will be set instead.

Done.

---

go/lib/tracing/context.go, line 51 at r1 (raw file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

I guess we are reasonably sure that this can never happen? Maybe add a comment that this should never happen since opentracing.Binary is a builtin format and thus must be supported by all tracer implementations.

Done.

[lukedirtwalker]

Reviewed 15 of 16 files at r2.
Reviewable status: all files reviewed, 3 unresolved discussions (waiting on @lukedirtwalker and @oncilla)

---

go/lib/tracing/context.go, line 35 at r2 (raw file):

	span, ctx := opentracing.StartSpanFromContext(parentCtx, operationName, opts...)
	if spanCtx, ok := span.Context().(jaeger.SpanContext); ok {
		return span, log.CtxWith(ctx, log.New("trace_id", spanCtx.TraceID()))

Why do we no longer set the debug id on the logger here?

[oncilla]

Reviewable status: all files reviewed, 1 unresolved discussion (waiting on @lukedirtwalker)

---

go/lib/tracing/context.go, line 35 at r2 (raw file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

Why do we no longer set the debug id on the logger here?

there is not really a point in setting one, because it trace_id is part of every log line anyway.
What I wanted to do initially was: "debug_id", spanCtx.TraceID().String()[:8]. I can add it again, if you prefer

[lukedirtwalker]

Reviewable status: all files reviewed, 1 unresolved discussion (waiting on @oncilla)

---

go/lib/tracing/context.go, line 35 at r2 (raw file):

Previously, Oncilla wrote…

there is not really a point in setting one, because it trace_id is part of every log line anyway.
What I wanted to do initially was: "debug_id", spanCtx.TraceID().String()[:8]. I can add it again, if you prefer

I see, I wonder whether it would be confusing to the reader that sometimes there is a trace_id and if tracing isn't enabled there is a debug_id. I think we should use a consistent naming.

[oncilla]

Reviewable status: 34 of 35 files reviewed, 1 unresolved discussion (waiting on @lukedirtwalker)

---

go/lib/tracing/context.go, line 35 at r2 (raw file):

Previously, lukedirtwalker (Lukas Vogel) wrote…

I see, I wonder whether it would be confusing to the reader that sometimes there is a trace_id and if tracing isn't enabled there is a debug_id. I think we should use a consistent naming.

Alright. Let's do the following: 8 char debug_id that consists of the 32 msb of the trace_id:

• consistent number of chars for the debug_id
• immediately obvious if there is a trace

[lukedirtwalker]

Reviewed 1 of 1 files at r3.
Reviewable status: complete! all files reviewed, all discussions resolved

[lukedirtwalker]

Reviewed 1 of 1 files at r4.
Reviewable status: complete! all files reviewed, all discussions resolved