uptrace / opentelemetry-go-extra

OpenTelemetry instrumentations for Go
https://uptrace.dev/get/instrument/
BSD 2-Clause "Simplified" License
314 stars 72 forks source link

[otelzap] Spans not capturing log message data #86

Closed Rheisen closed 1 year ago

Rheisen commented 1 year ago

I'm trying to use otelzap as middleware for fiber, but I'm not seeing log messages provided with a span context showing up in the span output. Trace IDs also do not appear in the log message, despite the logger option being present. Also perhaps relevant, Fiber is being run with Immutable set to true.

Here is the middleware function with some additional code comments:

func (a *ManagementAPI) RequestLogging(c *fiber.Ctx) error {
    start := time.Now()

    c.Next()

        // c.UserContext() is set by an earlier middleware function that creates a "request" span
    ctx, span := a.config.Tracer(ServiceName).Start(c.UserContext(), "request_log")
    defer span.End()

        // a.logger has type *otelzap.Logger
    a.logger.Ctx(ctx).Info(
        fmt.Sprintf("%s", c.Path()),
        zap.Int("status", c.Response().StatusCode()),
        zap.String("method", c.Method()),
        zap.String("path", c.Path()),
        zap.String("ip", c.IP()),
        zap.ByteString("user_agent", c.Request().Header.UserAgent()),
        zap.Int64("latency_ns", time.Now().Sub(start).Nanoseconds()),
        // zap.String("trace_id", span.SpanContext().TraceID().String()),
    )

    return nil
}

The span context coming from c.UserContext() also appears to be valid, as it does link parent and child spans correctly.

The logger being used in the middleware function is created by this function:

func L(name string) *otelzap.Logger {
    return otelzap.New(zap.L().Named(name), otelzap.WithTraceIDField(true))
}

Before then, the global loggers are set up like so:

func InitializeGlobalLogger(c LoggingConfig) error {
    zapConfig, err := zapConfig(c)
    if err != nil {
        return fmt.Errorf("problem creating zap configuration: %w\n", err)
    }

    zapLogger := zap.Must(zapConfig.Build())
    zapLogger = zapLogger.With(zap.String("id", c.AppID()))
    defer zapLogger.Sync()

    otelLogger := otelzap.New(zapLogger, otelzap.WithTraceIDField(true))
    defer otelLogger.Sync()

    zap.ReplaceGlobals(zapLogger)
    otelzap.ReplaceGlobals(otelLogger)

    return nil
}

The project is using go 1.19, and these versions may be relevant:

    go.uber.org/zap v1.23.0
    github.com/uptrace/opentelemetry-go-extra/otelutil v0.1.17 // indirect
    github.com/uptrace/opentelemetry-go-extra/otelzap v0.1.17 // indirect
    go.opentelemetry.io/otel v1.11.2 // indirect
    go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.11.2 // indirect
    go.opentelemetry.io/otel/sdk v1.11.2 // indirect
    go.opentelemetry.io/otel/trace v1.11.2 // indirect

Any help would be greatly appreciated.

Rheisen commented 1 year ago

This is the output I receive from hitting a route:

{"level":"info","ts":"2022-12-07T17:18:51.281-0500","logger":"management_service","caller":"managementsvc/management_service.go:65","msg":"/management/status","id":"2IbY0KrI8hzwMAViMwopgno8ztb","status":200,"method":"GET","path":"/management/status","ip":"127.0.0.1","user_agent":"PostmanRuntime/7.29.2","latency_ms":2}
{
        "Name": "status_handler",
        "SpanContext": {
                "TraceID": "e7b83325a623496f6159bd1d5ad3e07d",
                "SpanID": "de1831d3e4852d00",
                "TraceFlags": "01",
                "TraceState": "",
                "Remote": false
        },
        "Parent": {
                "TraceID": "e7b83325a623496f6159bd1d5ad3e07d",
                "SpanID": "9a59ebfbcceefd4a",
                "TraceFlags": "01",
                "TraceState": "",
                "Remote": false
        },
        "SpanKind": 1,
        "StartTime": "0001-01-01T00:00:00Z",
        "EndTime": "0001-01-01T00:00:00Z",
        "Attributes": null,
        "Events": null,
        "Links": null,
        "Status": {
                "Code": "Ok",
                "Description": ""
        },
        "DroppedAttributes": 0,
        "DroppedEvents": 0,
        "DroppedLinks": 0,
        "ChildSpanCount": 0,
        "Resource": [
                {
                        "Key": "service.instance.id",
                        "Value": {
                                "Type": "STRING",
                                "Value": "2IbY0KrI8hzwMAViMwopgno8ztb"
                        }
                },
                {
                        "Key": "service.name",
                        "Value": {
                                "Type": "STRING",
                                "Value": "go_mini_build_template"
                        }
                },
                {
                        "Key": "telemetry.sdk.language",
                        "Value": {
                                "Type": "STRING",
                                "Value": "go"
                        }
                },
                {
                        "Key": "telemetry.sdk.name",
                        "Value": {
                                "Type": "STRING",
                                "Value": "opentelemetry"
                        }
                },
                {
                        "Key": "telemetry.sdk.version",
                        "Value": {
                                "Type": "STRING",
                                "Value": "1.11.2"
                        }
                }
        ],
        "InstrumentationLibrary": {
                "Name": "management_service",
                "Version": "",
                "SchemaURL": ""
        }
}
{
        "Name": "request_log",
        "SpanContext": {
                "TraceID": "e7b83325a623496f6159bd1d5ad3e07d",
                "SpanID": "bf6bf31a0a387cba",
                "TraceFlags": "01",
                "TraceState": "",
                "Remote": false
        },
        "Parent": {
                "TraceID": "e7b83325a623496f6159bd1d5ad3e07d",
                "SpanID": "9a59ebfbcceefd4a",
                "TraceFlags": "01",
                "TraceState": "",
                "Remote": false
        },
        "SpanKind": 1,
        "StartTime": "0001-01-01T00:00:00Z",
        "EndTime": "0001-01-01T00:00:00Z",
        "Attributes": null,
        "Events": null,
        "Links": null,
        "Status": {
                "Code": "Unset",
                "Description": ""
        },
        "DroppedAttributes": 0,
        "DroppedEvents": 0,
        "DroppedLinks": 0,
        "ChildSpanCount": 0,
        "Resource": [
                {
                        "Key": "service.instance.id",
                        "Value": {
                                "Type": "STRING",
                                "Value": "2IbY0KrI8hzwMAViMwopgno8ztb"
                        }
                },
                {
                        "Key": "service.name",
                        "Value": {
                                "Type": "STRING",
                                "Value": "go_mini_build_template"
                        }
                },
                {
                        "Key": "telemetry.sdk.language",
                        "Value": {
                                "Type": "STRING",
                                "Value": "go"
                        }
                },
                {
                        "Key": "telemetry.sdk.name",
                        "Value": {
                                "Type": "STRING",
                                "Value": "opentelemetry"
                        }
                },
                {
                        "Key": "telemetry.sdk.version",
                        "Value": {
                                "Type": "STRING",
                                "Value": "1.11.2"
                        }
                }
        ],
        "InstrumentationLibrary": {
                "Name": "management_service",
                "Version": "",
                "SchemaURL": ""
        }
}
{
        "Name": "request",
        "SpanContext": {
                "TraceID": "e7b83325a623496f6159bd1d5ad3e07d",
                "SpanID": "9a59ebfbcceefd4a",
                "TraceFlags": "01",
                "TraceState": "",
                "Remote": false
        },
        "Parent": {
                "TraceID": "00000000000000000000000000000000",
                "SpanID": "0000000000000000",
                "TraceFlags": "00",
                "TraceState": "",
                "Remote": false
        },
        "SpanKind": 1,
        "StartTime": "0001-01-01T00:00:00Z",
        "EndTime": "0001-01-01T00:00:00Z",
        "Attributes": null,
        "Events": null,
        "Links": null,
        "Status": {
                "Code": "Unset",
                "Description": ""
        },
        "DroppedAttributes": 0,
        "DroppedEvents": 0,
        "DroppedLinks": 0,
        "ChildSpanCount": 2,
        "Resource": [
                {
                        "Key": "service.instance.id",
                        "Value": {
                                "Type": "STRING",
                                "Value": "2IbY0KrI8hzwMAViMwopgno8ztb"
                        }
                },
                {
                        "Key": "service.name",
                        "Value": {
                                "Type": "STRING",
                                "Value": "go_mini_build_template"
                        }
                },
                {
                        "Key": "telemetry.sdk.language",
                        "Value": {
                                "Type": "STRING",
                                "Value": "go"
                        }
                },
                {
                        "Key": "telemetry.sdk.name",
                        "Value": {
                                "Type": "STRING",
                                "Value": "opentelemetry"
                        }
                },
                {
                        "Key": "telemetry.sdk.version",
                        "Value": {
                                "Type": "STRING",
                                "Value": "1.11.2"
                        }
                }
        ],
        "InstrumentationLibrary": {
                "Name": "management_service",
                "Version": "",
                "SchemaURL": ""
        }
}
vmihailenco commented 1 year ago

It could be that you need to use otelzap.WithMinLevel(zap.InfoLevel) to start record INFO logs.

Rheisen commented 1 year ago

Oh my goodness, that was it. Thank you very much @vmihailenco!