[WIP] Fix no parent

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)))
 

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

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=

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.

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()