Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix OTEL logging in HotRod example #4556

Merged
merged 12 commits into from
Jul 2, 2023
Merged

Fix OTEL logging in HotRod example #4556

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
12 commits
Select commit Hold shift + click to select a range
0f3ae40
Add minimal fix to log otel spans
albertteoh Jun 25, 2023
db458f8
Remove debug logging
albertteoh Jun 25, 2023
6e3b0c0
Fix import grouping
albertteoh Jun 25, 2023
09faf15
Minor cleanup
albertteoh Jun 25, 2023
bf37a8a
Merge branch 'main' into afzal-fix-otel-logging
albertteoh Jun 25, 2023
b374d26
Remove ot span extract
albertteoh Jul 1, 2023
a1f9468
Only use single spanlogger for both otel and ot
albertteoh Jul 1, 2023
9f3d302
Remove debug print
albertteoh Jul 1, 2023
5517348
Update comment
albertteoh Jul 1, 2023
9422c8a
Merge branch 'main' into fix-otel-logging-hotrod
albertteoh Jul 1, 2023
b1d21a1
Invoke conversion directly
albertteoh Jul 1, 2023
a31b067
Add log level as an log attribute
albertteoh Jul 1, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 5 additions & 10 deletions examples/hotrod/pkg/log/factory.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,7 +18,6 @@ package log
import (
"context"

ot "github.com/opentracing/opentracing-go"
"go.opentelemetry.io/otel/trace"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
Expand All @@ -44,16 +43,12 @@ func (b Factory) Bg() Logger {
// contains an OpenTracing span, all logging calls are also
// echo-ed into the span.
func (b Factory) For(ctx context.Context) Logger {
if otSpan := ot.SpanFromContext(ctx); otSpan != nil {
logger := spanLogger{span: otSpan, logger: b.logger}

if otelSpan := trace.SpanFromContext(ctx); otelSpan != nil {
logger.spanFields = []zapcore.Field{
zap.String("trace_id", otelSpan.SpanContext().TraceID().String()),
zap.String("span_id", otelSpan.SpanContext().SpanID().String()),
}
if otelSpan := trace.SpanFromContext(ctx); otelSpan != nil {
logger := spanLogger{span: otelSpan, logger: b.logger}
logger.spanFields = []zapcore.Field{
zap.String("trace_id", otelSpan.SpanContext().TraceID().String()),
zap.String("span_id", otelSpan.SpanContext().SpanID().String()),
}

return logger
}
return b.Bg()
Expand Down
143 changes: 82 additions & 61 deletions examples/hotrod/pkg/log/spanlogger.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,23 +16,24 @@
package log

import (
"fmt"
"time"

"github.com/opentracing/opentracing-go"
tag "github.com/opentracing/opentracing-go/ext"
"github.com/opentracing/opentracing-go/log"
"go.opentelemetry.io/otel/attribute"
"go.opentelemetry.io/otel/codes"
"go.opentelemetry.io/otel/trace"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
)

type spanLogger struct {
logger *zap.Logger
span opentracing.Span
span trace.Span
spanFields []zapcore.Field
}

func (sl spanLogger) Debug(msg string, fields ...zapcore.Field) {
sl.logToSpan("Debug", msg, fields...)
yurishkuro marked this conversation as resolved.
Show resolved Hide resolved
sl.logToSpan("debug", msg, fields...)
sl.logger.Debug(msg, append(sl.spanFields, fields...)...)
}

Expand All @@ -48,7 +49,7 @@ func (sl spanLogger) Error(msg string, fields ...zapcore.Field) {

func (sl spanLogger) Fatal(msg string, fields ...zapcore.Field) {
sl.logToSpan("fatal", msg, fields...)
tag.Error.Set(sl.span, true)
sl.span.SetStatus(codes.Error, msg)
sl.logger.Fatal(msg, append(sl.spanFields, fields...)...)
}

Expand All @@ -57,99 +58,119 @@ func (sl spanLogger) With(fields ...zapcore.Field) Logger {
return spanLogger{logger: sl.logger.With(fields...), span: sl.span, spanFields: sl.spanFields}
}

func (sl spanLogger) logToSpan(level string, msg string, fields ...zapcore.Field) {
// TODO rather than always converting the fields, we could wrap them into a lazy logger
fa := fieldAdapter(make([]log.Field, 0, 2+len(fields)))
fa = append(fa, log.String("event", msg))
fa = append(fa, log.String("level", level))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Level was used!

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ha! Yes, you're right, my bad for this oversight and thanks for the callout. Added "level" as an attribute to the logs in: a31b067

Note that the MySQL spans are missing the log level:

Screenshot 2023-07-02 at 7 20 44 am

That's because LogFields is invoked directly from the active span here:

jaeger/examples/hotrod/pkg/tracing/mutex.go

Line 50 in 343fcc6

activeSpan.LogFields(
.

Is this something we should fix in this PR?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

looks fine as is. Level is not meaningful in the span logs, the only reason to transfer it when converting real logs is to keep data fidelity.

func (sl spanLogger) logToSpan(level, msg string, fields ...zapcore.Field) {
fields = append(fields, zap.String("level", level))
sl.span.AddEvent(
msg,
trace.WithAttributes(logFieldsToOTelAttrs(fields)...),
)
}

func logFieldsToOTelAttrs(fields []zapcore.Field) []attribute.KeyValue {
encoder := &bridgeFieldEncoder{}
for _, field := range fields {
field.AddTo(&fa)
field.AddTo(encoder)
}
sl.span.LogFields(fa...)
return encoder.pairs
}

type fieldAdapter []log.Field
type bridgeFieldEncoder struct {
pairs []attribute.KeyValue
}

func (fa *fieldAdapter) AddBool(key string, value bool) {
*fa = append(*fa, log.Bool(key, value))
func (e *bridgeFieldEncoder) AddArray(key string, marshaler zapcore.ArrayMarshaler) error {
e.pairs = append(e.pairs, attribute.String(key, fmt.Sprint(marshaler)))
return nil
}

func (fa *fieldAdapter) AddFloat64(key string, value float64) {
*fa = append(*fa, log.Float64(key, value))
func (e *bridgeFieldEncoder) AddObject(key string, marshaler zapcore.ObjectMarshaler) error {
e.pairs = append(e.pairs, attribute.String(key, fmt.Sprint(marshaler)))
return nil
}

func (fa *fieldAdapter) AddFloat32(key string, value float32) {
*fa = append(*fa, log.Float64(key, float64(value)))
func (e *bridgeFieldEncoder) AddBinary(key string, value []byte) {
e.pairs = append(e.pairs, attribute.String(key, fmt.Sprint(value)))
}

func (fa *fieldAdapter) AddInt(key string, value int) {
*fa = append(*fa, log.Int(key, value))
func (e *bridgeFieldEncoder) AddByteString(key string, value []byte) {
e.pairs = append(e.pairs, attribute.String(key, fmt.Sprint(value)))
}

func (fa *fieldAdapter) AddInt64(key string, value int64) {
*fa = append(*fa, log.Int64(key, value))
func (e *bridgeFieldEncoder) AddBool(key string, value bool) {
e.pairs = append(e.pairs, attribute.Bool(key, value))
}

func (fa *fieldAdapter) AddInt32(key string, value int32) {
*fa = append(*fa, log.Int64(key, int64(value)))
func (e *bridgeFieldEncoder) AddComplex128(key string, value complex128) {
e.pairs = append(e.pairs, attribute.String(key, fmt.Sprint(value)))
}

func (fa *fieldAdapter) AddInt16(key string, value int16) {
*fa = append(*fa, log.Int64(key, int64(value)))
func (e *bridgeFieldEncoder) AddComplex64(key string, value complex64) {
e.pairs = append(e.pairs, attribute.String(key, fmt.Sprint(value)))
}

func (fa *fieldAdapter) AddInt8(key string, value int8) {
*fa = append(*fa, log.Int64(key, int64(value)))
func (e *bridgeFieldEncoder) AddDuration(key string, value time.Duration) {
e.pairs = append(e.pairs, attribute.String(key, fmt.Sprint(value)))
}

func (fa *fieldAdapter) AddUint(key string, value uint) {
*fa = append(*fa, log.Uint64(key, uint64(value)))
func (e *bridgeFieldEncoder) AddFloat64(key string, value float64) {
e.pairs = append(e.pairs, attribute.Float64(key, value))
}

func (fa *fieldAdapter) AddUint64(key string, value uint64) {
*fa = append(*fa, log.Uint64(key, value))
func (e *bridgeFieldEncoder) AddFloat32(key string, value float32) {
e.pairs = append(e.pairs, attribute.Float64(key, float64(value)))
}

func (fa *fieldAdapter) AddUint32(key string, value uint32) {
*fa = append(*fa, log.Uint64(key, uint64(value)))
func (e *bridgeFieldEncoder) AddInt(key string, value int) {
e.pairs = append(e.pairs, attribute.Int(key, value))
}

func (fa *fieldAdapter) AddUint16(key string, value uint16) {
*fa = append(*fa, log.Uint64(key, uint64(value)))
func (e *bridgeFieldEncoder) AddInt64(key string, value int64) {
e.pairs = append(e.pairs, attribute.Int64(key, value))
}

func (fa *fieldAdapter) AddUint8(key string, value uint8) {
*fa = append(*fa, log.Uint64(key, uint64(value)))
func (e *bridgeFieldEncoder) AddInt32(key string, value int32) {
e.pairs = append(e.pairs, attribute.Int64(key, int64(value)))
}

func (fa *fieldAdapter) AddUintptr(key string, value uintptr) {}
func (fa *fieldAdapter) AddArray(key string, marshaler zapcore.ArrayMarshaler) error { return nil }
func (fa *fieldAdapter) AddComplex128(key string, value complex128) {}
func (fa *fieldAdapter) AddComplex64(key string, value complex64) {}
func (fa *fieldAdapter) AddObject(key string, value zapcore.ObjectMarshaler) error { return nil }
func (fa *fieldAdapter) AddReflected(key string, value interface{}) error { return nil }
func (fa *fieldAdapter) OpenNamespace(key string) {}
func (e *bridgeFieldEncoder) AddInt16(key string, value int16) {
e.pairs = append(e.pairs, attribute.Int64(key, int64(value)))
}

func (fa *fieldAdapter) AddDuration(key string, value time.Duration) {
// TODO inefficient
*fa = append(*fa, log.String(key, value.String()))
func (e *bridgeFieldEncoder) AddInt8(key string, value int8) {
e.pairs = append(e.pairs, attribute.Int64(key, int64(value)))
}

func (fa *fieldAdapter) AddTime(key string, value time.Time) {
// TODO inefficient
*fa = append(*fa, log.String(key, value.String()))
func (e *bridgeFieldEncoder) AddString(key, value string) {
e.pairs = append(e.pairs, attribute.String(key, value))
}

func (fa *fieldAdapter) AddBinary(key string, value []byte) {
*fa = append(*fa, log.Object(key, value))
func (e *bridgeFieldEncoder) AddTime(key string, value time.Time) {
e.pairs = append(e.pairs, attribute.String(key, fmt.Sprint(value)))
}

func (fa *fieldAdapter) AddByteString(key string, value []byte) {
*fa = append(*fa, log.Object(key, value))
func (e *bridgeFieldEncoder) AddUint(key string, value uint) {
e.pairs = append(e.pairs, attribute.String(key, fmt.Sprintf("%d", value)))
}

func (fa *fieldAdapter) AddString(key, value string) {
if key != "" && value != "" {
*fa = append(*fa, log.String(key, value))
}
func (e *bridgeFieldEncoder) AddUint64(key string, value uint64) {
e.pairs = append(e.pairs, attribute.String(key, fmt.Sprintf("%d", value)))
}

func (e *bridgeFieldEncoder) AddUint32(key string, value uint32) {
e.pairs = append(e.pairs, attribute.Int64(key, int64(value)))
}

func (e *bridgeFieldEncoder) AddUint16(key string, value uint16) {
e.pairs = append(e.pairs, attribute.Int64(key, int64(value)))
}

func (e *bridgeFieldEncoder) AddUint8(key string, value uint8) {
e.pairs = append(e.pairs, attribute.Int64(key, int64(value)))
}

func (e *bridgeFieldEncoder) AddUintptr(key string, value uintptr) {
e.pairs = append(e.pairs, attribute.String(key, fmt.Sprint(value)))
}

func (e *bridgeFieldEncoder) AddReflected(key string, value interface{}) error { return nil }
func (e *bridgeFieldEncoder) OpenNamespace(key string) {}