fix: add more logs to help troubleshooting propagation of OpenTelemetry context from clients

Author: pdecat

fdw.go

@@ -19,6 +19,7 @@ import (
 	"net"
 	"net/http"
 	"os"
+	"strings"
 	"time"
 	"unsafe"
 
@@ -177,11 +178,23 @@ func goFdwGetRelSize(state *C.FdwPlanState, root *C.PlannerInfo, rows *C.double,
 	if state.trace_context_string != nil {
 		traceContext = C.GoString(state.trace_context_string)
 		log.Printf("[TRACE] Extracted trace context from session: %s", traceContext)
+
+		if len(traceContext) > 0 {
+			log.Printf("[DEBUG] Trace context length: %d characters", len(traceContext))
+			if strings.Contains(traceContext, "traceparent=") {
+				log.Printf("[DEBUG] Trace context contains traceparent field")
+			} else {
+				log.Printf("[WARN] Trace context missing traceparent field - may be malformed")
+			}
+		}
+	} else {
+		log.Printf("[DEBUG] No trace context found in session variables")
 	}
 
 	// Add trace context to options for hub layer
 	if traceContext != "" {
 		tableOpts["trace_context"] = traceContext
+		log.Printf("[DEBUG] Added trace context to table options")
 	}
 
 	// build columns

hub/hub_base.go

@@ -379,10 +379,15 @@ func (h *hubBase) traceContextForScan(table string, columns []string, limit int6
 
 	// Check if we have trace context from session variables
 	if traceContextStr, exists := opts["trace_context"]; exists && traceContextStr != "" {
+		log.Printf("[DEBUG] traceContextForScan received trace context: %s", traceContextStr)
 		if parentCtx := h.parseTraceContext(traceContextStr); parentCtx != nil {
 			baseCtx = parentCtx
 			log.Printf("[TRACE] Using parent trace context for scan of table: %s", table)
+		} else {
+			log.Printf("[WARN] Failed to parse trace context for table: %s", table)
 		}
+	} else {
+		log.Printf("[DEBUG] No trace context found in options for table: %s", table)
 	}
 
 	// Create span with potentially propagated context
@@ -396,28 +401,45 @@ func (h *hubBase) traceContextForScan(table string, columns []string, limit int6
 	if limit != -1 {
 		span.SetAttributes(attribute.Int64("limit", limit))
 	}
+
+	spanCtx := span.SpanContext()
+	if spanCtx.IsValid() {
+		log.Printf("[DEBUG] Created span for table %s - TraceID: %s, SpanID: %s",
+			table, spanCtx.TraceID().String(), spanCtx.SpanID().String())
+	}
+
 	return &telemetry.TraceCtx{Ctx: ctx, Span: span}
 }
 
 // parseTraceContext parses trace context string from session variables
 // Format: "traceparent=00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01;tracestate=rojo=00f067aa0ba902b7"
 func (h *hubBase) parseTraceContext(traceContextString string) context.Context {
+	log.Printf("[DEBUG] parseTraceContext called with: %s", traceContextString)
+
 	if traceContextString == "" {
+		log.Printf("[DEBUG] Empty trace context string")
 		return nil
 	}
 
 	carrier := propagation.MapCarrier{}
 
 	// Parse the trace context string format: "traceparent=..;tracestate=.."
 	parts := strings.Split(traceContextString, ";")
+	log.Printf("[DEBUG] Split trace context into %d parts: %v", len(parts), parts)
+
 	for _, part := range parts {
 		if kv := strings.SplitN(part, "=", 2); len(kv) == 2 {
 			key := strings.TrimSpace(kv[0])
 			value := strings.TrimSpace(kv[1])
 			carrier[key] = value
+			log.Printf("[DEBUG] Added to carrier: %s = %s", key, value)
+		} else {
+			log.Printf("[DEBUG] Skipping invalid part: %s", part)
 		}
 	}
 
+	log.Printf("[DEBUG] Final carrier contents: %v", carrier)
+
 	if len(carrier) == 0 {
 		log.Printf("[WARN] No valid trace context found in: %s", traceContextString)
 		return nil
@@ -438,7 +460,7 @@ func (h *hubBase) parseTraceContext(traceContextString string) context.Context {
 		return extractedCtx
 	}
 
-	log.Printf("[WARN] Extracted trace context is not valid")
+	log.Printf("[WARN] Extracted trace context is not valid - carrier was: %v", carrier)
 	return nil
 }
 

hub/scan_iterator_base.go

@@ -16,6 +16,7 @@ import (
 	"github.com/turbot/steampipe-plugin-sdk/v5/telemetry"
 	"github.com/turbot/steampipe-postgres-fdw/v2/types"
 	"github.com/turbot/steampipe/v2/pkg/query/queryresult"
+	"go.opentelemetry.io/otel/trace"
 	"google.golang.org/protobuf/reflect/protoreflect"
 )
 
@@ -199,13 +200,25 @@ func (i *scanIteratorBase) GetScanMetadata() []queryresult.ScanMetadataRow {
 }
 
 func (i *scanIteratorBase) newExecuteRequest() *proto.ExecuteRequest {
+	traceCarrier := grpc.CreateCarrierFromContext(i.traceCtx.Ctx)
+	log.Printf("[DEBUG] newExecuteRequest creating trace carrier for table %s: %v", i.table, traceCarrier)
+
+	// Validate span context from the trace context
+	spanCtx := trace.SpanContextFromContext(i.traceCtx.Ctx)
+	if spanCtx.IsValid() {
+		log.Printf("[DEBUG] newExecuteRequest has valid span context - TraceID: %s, SpanID: %s",
+			spanCtx.TraceID().String(), spanCtx.SpanID().String())
+	} else {
+		log.Printf("[WARN] newExecuteRequest has invalid span context for table %s", i.table)
+	}
+
 	req := &proto.ExecuteRequest{
 		Table:        i.table,
 		QueryContext: i.queryContext,
 		CallId:       i.callId,
 		// pass connection name - used for aggregators
 		Connection:            i.connectionName,
-		TraceContext:          grpc.CreateCarrierFromContext(i.traceCtx.Ctx),
+		TraceContext:          traceCarrier,
 		ExecuteConnectionData: make(map[string]*proto.ExecuteConnectionData),
 	}