diff --git a/cmd/overlaybd-snapshotter/main.go b/cmd/overlaybd-snapshotter/main.go index 5fa909e6..c47dd07d 100644 --- a/cmd/overlaybd-snapshotter/main.go +++ b/cmd/overlaybd-snapshotter/main.go @@ -28,16 +28,14 @@ import ( "strings" "time" - mylog "github.com/containerd/accelerated-container-image/internal/log" "github.com/containerd/accelerated-container-image/pkg/metrics" overlaybd "github.com/containerd/accelerated-container-image/pkg/snapshot" "github.com/containerd/accelerated-container-image/pkg/tracing" - snapshotsapi "github.com/containerd/containerd/api/services/snapshots/v1" "github.com/containerd/containerd/v2/contrib/snapshotservice" - "github.com/containerd/log" "github.com/pkg/errors" "github.com/sirupsen/logrus" + "go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc" "golang.org/x/sys/unix" "google.golang.org/grpc" ) @@ -47,18 +45,18 @@ const defaultConfigPath = "/etc/overlaybd-snapshotter/config.json" var pconfig *overlaybd.BootConfig var commitID string = "unknown" -func requestIDInterceptor(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) { - requestID := tracing.GetRequestID(ctx) - if requestID == "" { - requestID = mylog.GenerateRequestID() - ctx = tracing.SetRequestID(ctx, requestID) - } +// func requestIDInterceptor(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) { +// requestID := tracing.GetRequestID(ctx) +// if requestID == "" { +// requestID = mylog.GenerateRequestID() +// ctx = tracing.SetRequestID(ctx, requestID) +// } - ctx = mylog.WithRequestID(ctx, requestID) - ctx = log.WithLogger(ctx, log.G(ctx).WithField("req_id", requestID)) +// ctx = mylog.WithRequestID(ctx, requestID) +// ctx = log.WithLogger(ctx, log.G(ctx).WithField("req_id", requestID)) - return handler(ctx, req) -} +// return handler(ctx, req) +// } func parseConfig(fpath string) error { logrus.Info("parse config file: ", fpath) @@ -79,13 +77,13 @@ func main() { ctx := context.Background() // Initialize OpenTelemetry - shutdown, err := tracing.InitTracer(ctx) + tracerShutdown, err := tracing.InitTracer(ctx) if err != nil { logrus.Errorf("Failed to initialize tracer: %v", err) os.Exit(1) } defer func() { - if err := shutdown(ctx); err != nil { + if err := tracerShutdown(ctx); err != nil { logrus.Errorf("Failed to shutdown tracer: %v", err) } }() @@ -139,10 +137,9 @@ func main() { // Initialize random seed for request ID generation rand.Seed(time.Now().UnixNano()) - // Use simplified tracing with request ID interceptor + // Chain both OpenTelemetry and request ID interceptors srv := grpc.NewServer( - tracing.WithServerTracing(), - grpc.UnaryInterceptor(requestIDInterceptor), + grpc.StatsHandler(otelgrpc.NewServerHandler()), ) snapshotsapi.RegisterSnapshotsServer(srv, tracing.WithTracing(snapshotservice.FromSnapshotter(sn))) diff --git a/go.mod b/go.mod index 4e262f2a..3bfc5f58 100644 --- a/go.mod +++ b/go.mod @@ -25,6 +25,7 @@ require ( github.com/sirupsen/logrus v1.9.3 github.com/spf13/cobra v1.8.1 github.com/urfave/cli/v2 v2.27.6 + go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc v0.62.0 go.opentelemetry.io/otel v1.37.0 go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.35.0 go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.35.0 @@ -37,8 +38,6 @@ require ( oras.land/oras-go/v2 v2.5.0 ) -require go.opentelemetry.io/otel/sdk/metric v1.37.0 // indirect - require ( filippo.io/edwards25519 v1.1.0 // indirect github.com/Microsoft/go-winio v0.6.2 // indirect @@ -107,8 +106,8 @@ require ( go.etcd.io/bbolt v1.4.0 // indirect go.opencensus.io v0.24.0 // indirect go.opentelemetry.io/auto/sdk v1.1.0 // indirect - go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc v0.62.0 // indirect go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.60.0 // indirect + go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.37.0 // indirect go.opentelemetry.io/otel/metric v1.37.0 // indirect go.opentelemetry.io/proto/otlp v1.5.0 // indirect golang.org/x/exp v0.0.0-20241108190413-2d47ceb2692f // indirect diff --git a/go.sum b/go.sum index 01616ef1..e8772e12 100644 --- a/go.sum +++ b/go.sum @@ -287,6 +287,8 @@ go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.35.0 h1:1fTNlAIJZGWLP5FVu0f go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.35.0/go.mod h1:zjPK58DtkqQFn+YUMbx0M2XV3QgKU0gS9LeGohREyK4= go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.35.0 h1:m639+BofXTvcY1q8CGs4ItwQarYtJPOWmVobfM1HpVI= go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.35.0/go.mod h1:LjReUci/F4BUyv+y4dwnq3h/26iNOeC3wAIqgvTIZVo= +go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.37.0 h1:SNhVp/9q4Go/XHBkQ1/d5u9P/U+L1yaGPoi0x+mStaI= +go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.37.0/go.mod h1:tx8OOlGH6R4kLV67YaYO44GFXloEjGPZuMjEkaaqIp4= go.opentelemetry.io/otel/metric v1.37.0 h1:mvwbQS5m0tbmqML4NqK+e3aDiO02vsf/WgbsdpcPoZE= go.opentelemetry.io/otel/metric v1.37.0/go.mod h1:04wGrZurHYKOc+RKeye86GwKiTb9FKm1WHtO+4EVr2E= go.opentelemetry.io/otel/sdk v1.37.0 h1:ItB0QUqnjesGRvNcmAcU0LyvkVyGJ2xftD29bWdDvKI= diff --git a/pkg/tracing/README.md b/pkg/tracing/README.md index 0a3ec1dd..1e189c30 100644 --- a/pkg/tracing/README.md +++ b/pkg/tracing/README.md @@ -95,10 +95,57 @@ export OTEL_SERVICE_NAME="accelerated-container-image" # OTLP endpoint (e.g., Jaeger collector) export OTEL_EXPORTER_OTLP_ENDPOINT="http://localhost:4317" +# Enable console trace output (for development/debugging) +export OTEL_TRACES_CONSOLE="true" + # Environment tag export ENVIRONMENT="production" ``` +### Console Trace Output + +For development and debugging, you can enable console trace output by setting: + +```bash +export OTEL_TRACES_CONSOLE=true +``` + +This will output traces to stdout in a pretty-printed JSON format alongside sending them to any configured OTLP collector. This is useful for: + +- **Development**: See traces immediately without setting up a collector +- **Debugging**: Verify trace data is being generated correctly +- **Testing**: Validate trace attributes and structure +- **CI/CD**: Capture traces in build logs + +Example console output: +```json +{ + "Name": "snapshots.Prepare", + "SpanContext": { + "TraceID": "4bf92f3577b34da6a3ce929d0e0e4736", + "SpanID": "00f067aa0ba902b7" + }, + "Parent": { + "TraceID": "4bf92f3577b34da6a3ce929d0e0e4736", + "SpanID": "78547c8c5c564e1a" + }, + "SpanKind": 2, + "StartTime": "2024-01-01T12:00:00Z", + "EndTime": "2024-01-01T12:00:01Z", + "Attributes": [ + { + "Key": "rpc.system", + "Value": { + "Type": "STRING", + "Value": "grpc" + } + } + ] +} +``` + +**Note**: Console output works alongside OTLP export - traces are sent to both destinations when both are configured. + ## Baggage API Usage The implementation includes full support for OpenTelemetry Baggage, allowing you to propagate key-value pairs across service boundaries. diff --git a/pkg/tracing/snapshotter.go b/pkg/tracing/snapshotter.go index 1ea48510..49242a12 100644 --- a/pkg/tracing/snapshotter.go +++ b/pkg/tracing/snapshotter.go @@ -18,16 +18,66 @@ package tracing import ( "context" + "fmt" + "os" + "time" snapshotsapi "github.com/containerd/containerd/api/services/snapshots/v1" ptypes "github.com/containerd/containerd/v2/pkg/protobuf/types" "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/trace" + "google.golang.org/grpc/metadata" ) const tracerName = "accelerated-container-image/snapshotter" +// logTraceInfo logs parent trace ID and span information from the context to a file +func logTraceInfo(ctx context.Context, method string) { + span := trace.SpanFromContext(ctx) + + // Create or append to trace log file + file, err := os.OpenFile("/tmp/grpc_trace_info.log", os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644) + if err != nil { + return // Silent failure to not disrupt gRPC operations + } + defer file.Close() + + timestamp := time.Now().Format("2006-01-02 15:04:05.000") + + if span.SpanContext().IsValid() { + spanCtx := span.SpanContext() + traceInfo := fmt.Sprintf("[%s] Method: %s | TraceID: %s | SpanID: %s | TraceFlags: %d | IsRemote: %t", + timestamp, + method, + spanCtx.TraceID().String(), + spanCtx.SpanID().String(), + spanCtx.TraceFlags(), + spanCtx.IsRemote(), + ) + file.WriteString(traceInfo) + } else { + traceInfo := fmt.Sprintf("[%s] Method: %s | No valid trace context", timestamp, method) + file.WriteString(traceInfo) + } + + // Log trace propagation headers + if md, ok := metadata.FromIncomingContext(ctx); ok { + if traceHeaders := md.Get("traceparent"); len(traceHeaders) > 0 { + file.WriteString(fmt.Sprintf(" | TraceParent: %s", traceHeaders[0])) + } + if traceState := md.Get("tracestate"); len(traceState) > 0 { + file.WriteString(fmt.Sprintf(" | TraceState: %s", traceState[0])) + } + if otHeaders := md.Get("grpc-trace-bin"); len(otHeaders) > 0 { + file.WriteString(fmt.Sprintf(" | OT-Binary: present")) + } + } else { + file.WriteString(" | No metadata") + } + file.WriteString("\n") +} + // TracingSnapshotter wraps a snapshotter service with OpenTelemetry tracing type TracingSnapshotter struct { server snapshotsapi.SnapshotsServer @@ -45,6 +95,8 @@ func WithTracing(server snapshotsapi.SnapshotsServer) snapshotsapi.SnapshotsServ } func (s *TracingSnapshotter) Prepare(ctx context.Context, pr *snapshotsapi.PrepareSnapshotRequest) (*snapshotsapi.PrepareSnapshotResponse, error) { + logTraceInfo(ctx, "Prepare") + ctx, span := otel.GetTracerProvider().Tracer(tracerName).Start(ctx, "snapshotter.Prepare", trace.WithAttributes( attribute.String("key", pr.Key), attribute.String("parent", pr.Parent), @@ -59,6 +111,9 @@ func (s *TracingSnapshotter) Prepare(ctx context.Context, pr *snapshotsapi.Prepa } func (s *TracingSnapshotter) View(ctx context.Context, pr *snapshotsapi.ViewSnapshotRequest) (*snapshotsapi.ViewSnapshotResponse, error) { + logTraceInfo(ctx, "View") + + // Create a child span within the existing trace context from gRPC ctx, span := otel.GetTracerProvider().Tracer(tracerName).Start(ctx, "snapshotter.View", trace.WithAttributes( attribute.String("key", pr.Key), attribute.String("parent", pr.Parent), @@ -73,6 +128,8 @@ func (s *TracingSnapshotter) View(ctx context.Context, pr *snapshotsapi.ViewSnap } func (s *TracingSnapshotter) Mounts(ctx context.Context, mr *snapshotsapi.MountsRequest) (*snapshotsapi.MountsResponse, error) { + logTraceInfo(ctx, "Mounts") + ctx, span := otel.GetTracerProvider().Tracer(tracerName).Start(ctx, "snapshotter.Mounts", trace.WithAttributes( attribute.String("key", mr.Key), )) @@ -86,6 +143,8 @@ func (s *TracingSnapshotter) Mounts(ctx context.Context, mr *snapshotsapi.Mounts } func (s *TracingSnapshotter) Commit(ctx context.Context, cr *snapshotsapi.CommitSnapshotRequest) (*ptypes.Empty, error) { + logTraceInfo(ctx, "Commit") + ctx, span := otel.GetTracerProvider().Tracer(tracerName).Start(ctx, "snapshotter.Commit", trace.WithAttributes( attribute.String("name", cr.Name), attribute.String("key", cr.Key), @@ -100,6 +159,8 @@ func (s *TracingSnapshotter) Commit(ctx context.Context, cr *snapshotsapi.Commit } func (s *TracingSnapshotter) Remove(ctx context.Context, rr *snapshotsapi.RemoveSnapshotRequest) (*ptypes.Empty, error) { + logTraceInfo(ctx, "Remove") + ctx, span := otel.GetTracerProvider().Tracer(tracerName).Start(ctx, "snapshotter.Remove", trace.WithAttributes( attribute.String("key", rr.Key), )) @@ -113,6 +174,8 @@ func (s *TracingSnapshotter) Remove(ctx context.Context, rr *snapshotsapi.Remove } func (s *TracingSnapshotter) Stat(ctx context.Context, sr *snapshotsapi.StatSnapshotRequest) (*snapshotsapi.StatSnapshotResponse, error) { + logTraceInfo(ctx, "Stat") + ctx, span := otel.GetTracerProvider().Tracer(tracerName).Start(ctx, "snapshotter.Stat", trace.WithAttributes( attribute.String("key", sr.Key), )) @@ -126,6 +189,8 @@ func (s *TracingSnapshotter) Stat(ctx context.Context, sr *snapshotsapi.StatSnap } func (s *TracingSnapshotter) Update(ctx context.Context, sr *snapshotsapi.UpdateSnapshotRequest) (*snapshotsapi.UpdateSnapshotResponse, error) { + logTraceInfo(ctx, "Update") + ctx, span := otel.GetTracerProvider().Tracer(tracerName).Start(ctx, "snapshotter.Update", trace.WithAttributes( attribute.String("name", sr.Info.Name), )) @@ -139,6 +204,8 @@ func (s *TracingSnapshotter) Update(ctx context.Context, sr *snapshotsapi.Update } func (s *TracingSnapshotter) List(sr *snapshotsapi.ListSnapshotsRequest, ss snapshotsapi.Snapshots_ListServer) error { + logTraceInfo(ss.Context(), "List") + ctx, span := otel.GetTracerProvider().Tracer(tracerName).Start(ss.Context(), "snapshotter.List") defer span.End() @@ -162,6 +229,8 @@ func (t *tracingListServer) Context() context.Context { } func (s *TracingSnapshotter) Usage(ctx context.Context, ur *snapshotsapi.UsageRequest) (*snapshotsapi.UsageResponse, error) { + logTraceInfo(ctx, "Usage") + ctx, span := otel.GetTracerProvider().Tracer(tracerName).Start(ctx, "snapshotter.Usage", trace.WithAttributes( attribute.String("key", ur.Key), )) @@ -181,6 +250,8 @@ func (s *TracingSnapshotter) Usage(ctx context.Context, ur *snapshotsapi.UsageRe } func (s *TracingSnapshotter) Cleanup(ctx context.Context, cr *snapshotsapi.CleanupRequest) (*ptypes.Empty, error) { + logTraceInfo(ctx, "Cleanup") + ctx, span := otel.GetTracerProvider().Tracer(tracerName).Start(ctx, "snapshotter.Cleanup") defer span.End() diff --git a/pkg/tracing/tracing.go b/pkg/tracing/tracing.go index 7f2813f0..01306f54 100644 --- a/pkg/tracing/tracing.go +++ b/pkg/tracing/tracing.go @@ -6,9 +6,9 @@ import ( "os" "go.opentelemetry.io/otel" - "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/exporters/otlp/otlptrace" "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc" + "go.opentelemetry.io/otel/exporters/stdout/stdouttrace" "go.opentelemetry.io/otel/propagation" "go.opentelemetry.io/otel/sdk/resource" sdktrace "go.opentelemetry.io/otel/sdk/trace" @@ -25,30 +25,48 @@ func InitTracer(ctx context.Context) (func(context.Context) error, error) { serviceName = "accelerated-container-image" } - // Create OTLP exporter - client := otlptracegrpc.NewClient() - exporter, err := otlptrace.New(ctx, client) - if err != nil { - return nil, fmt.Errorf("creating OTLP trace exporter: %w", err) - } - // Create resource with service information res, err := resource.New(ctx, resource.WithAttributes( semconv.ServiceName(serviceName), - attribute.String("environment", os.Getenv("ENVIRONMENT")), ), ) if err != nil { return nil, fmt.Errorf("creating resource: %w", err) } - // Create trace provider - tp := sdktrace.NewTracerProvider( - sdktrace.WithBatcher(exporter), - sdktrace.WithResource(res), - sdktrace.WithSampler(sdktrace.AlwaysSample()), + var exporters []sdktrace.SpanExporter + + // Create OTLP exporter (default) + client := otlptracegrpc.NewClient() + otlpExporter, err := otlptrace.New(ctx, client) + if err != nil { + return nil, fmt.Errorf("creating OTLP trace exporter: %w", err) + } + exporters = append(exporters, otlpExporter) + + // Add console exporter if enabled + //if os.Getenv("OTEL_TRACES_CONSOLE") == "true" { + consoleExporter, err := stdouttrace.New( + stdouttrace.WithPrettyPrint(), ) + if err != nil { + return nil, fmt.Errorf("creating console trace exporter: %w", err) + } + exporters = append(exporters, consoleExporter) + //} + + // Create trace provider options + var opts []sdktrace.TracerProviderOption + opts = append(opts, sdktrace.WithResource(res)) + opts = append(opts, sdktrace.WithSampler(sdktrace.AlwaysSample())) + + // Add batch processors for each exporter + for _, exp := range exporters { + opts = append(opts, sdktrace.WithBatcher(exp)) + } + + tp := sdktrace.NewTracerProvider(opts...) // Set global trace provider otel.SetTracerProvider(tp)