Auto-instrumentation: Incoming and outgoing HTTP requests create separate, uncorrelated traces

[shravanv1]

Describe the bug

I am using OpenTelemetry auto-instrumentation in a Go application to trace both incoming and outgoing HTTP requests. However, while I can see traces for incoming requests, the outgoing requests are creating entirely new, uncorrelated traces instead of being part of the same trace as the incoming request.

Environment
Language: Go
Go Version: 1.23.1
OpenTelemetry Go Auto-Instrumentation Version: v0.15.0-alpha
OS: Linux (Amazon Linux 2023)
Kernel Version: 6.1.0
Tracing Backend: Jaeger

Code -

// this is handler for API -- /v1/thor/rest/flight/home/deals
func DailyStealDealHandlerChain() gin.HandlersChain {
	return gin.HandlersChain{
		baseRequestParserMiddleware(client.NewDealsBaseHelper),
		monitorHelper(handlers.NewMetricNameHelper(internal.MetricPrefixStealDeal)),
		authMiddleware(),
		requestParser(client.DailyStealDealRequestParser),
		pokusMiddleware(),
		getController(handlers.DailyStealDealHandler),
	}
}


// helper to create gin handlers from common handlers
func getController(handler func(icontext.IContext, http.ResponseWriter, *http.Request)) gin.HandlerFunc {
	return func(c *gin.Context) {
		iCtx := copyGinContext(c)
		generic_logger.NewLoggerWithUpdatedCtx(iCtx)
		handler(iCtx, c.Writer, c.Request)
		c.Writer.Flush()
	}
}

func copyGinContext(c *gin.Context) icontext.IContext {
	ctx := icontext.NewContext()
	for k, v := range c.Keys {
		ctx.SetValue(icontext.ContextKey(k), v)
	}
	for _, p := range c.Params {
		ctx.SetValue(icontext.ContextKey(p.Key), p.Value)
	}
	return ctx
}


func DailyStealDealHandler(ctx icontext.IContext, w http.ResponseWriter, req *http.Request) {
	dealReq := client.GetDailyStealDealRequest(ctx.GetBaseContext())
	var clientResp *client.DealsResponse
	var err error

	clientResp, err = dealHandlerV2(ctx, dealReq)

	if err != nil {
		client.SendError(w, err)
	}
	client.SendJsonRespnse(w, clientResp)
}

inside dealHandlerV2 I am making http call to another API flights-b2c-misc/v2/daily-steal-deals.* by craeting this

ctx, _ = context.WithTimeout(ctx, time.Duration(b.Timeout)*time.Millisecond)
	req, err := http.NewRequestWithContext(ctx, b.Method, b.Url, b.Body)

but for /v1/thor/rest/flight/home/deals I am getting another trace and for flights-b2c-misc/v2/daily-steal-deals.* I am getting different tarce ideally this sholud be same

[shravanv1]

Hello can pls anyone provide update on this I tried multiple ways but still facing same issue @RonFed

[damemi]

Hi, can you please share the logs from the auto-instrumentation agent?

[shravanv1]

@damemi pls find attaced logs

{
  "time": "2024-10-16T21:42:16.987830371+05:30",
  "level": "DEBUG",
  "source": {
    "function": "go.opentelemetry.io/auto/internal/pkg/opentelemetry.(*Controller).Trace",
    "file": "/go/src/Flights-GI-Backend/opentelemetry-go-instrumentation/internal/pkg/opentelemetry/controller.go",
    "line": 75
  },
  "msg": "getting tracer",
  "name": "Flights-GI-Backend-ts",
  "version": "",
  "schema": ""
}

{
  "time": "2024-10-16T21:42:16.994011898+05:30",
  "level": "DEBUG",
  "source": {
    "function": "go.opentelemetry.io/auto/internal/pkg/opentelemetry.(*Controller).Trace",
    "file": "/go/src/Flights-GI-Backend/opentelemetry-go-instrumentation/internal/pkg/opentelemetry/controller.go",
    "line": 56
  },
  "msg": "got event",
  "kind": "client",
  "pkg": "net/http",
  "attrs": [
    {
      "Key": "http.request.method",
      "Value": {
        "Type": "STRING",
        "Value": "POST"
      }
    },
    {
      "Key": "http.response.status_code",
      "Value": {
        "Type": "INT64",
        "Value": 200
      }
    },
    {
      "Key": "url.path",
      "Value": {
        "Type": "STRING",
        "Value": "/experiment/assignVariantBackend"
      }
    },
    {
      "Key": "url.full",
      "Value": {
        "Type": "STRING",
        "Value": "http://pokus-gi.mmt.mmt/experiment/assignVariantBackend"
      }
    },
    {
      "Key": "server.address",
      "Value": {
        "Type": "STRING",
        "Value": "pokus-gi.mmt.mmt"
      }
    },
    {
      "Key": "network.protocol.version",
      "Value": {
        "Type": "STRING",
        "Value": "1.1"
      }
    }
  ],
  "traceID": "999dee807db1ec854a11c5460d677d46",
  "spanID": "566a6db5dbc42071"
}

{
  "time": "2024-10-16T21:42:16.994057519+05:30",
  "level": "DEBUG",
  "source": {
    "function": "go.opentelemetry.io/auto/internal/pkg/opentelemetry.(*Controller).Trace",
    "file": "/go/src/Flights-GI-Backend/opentelemetry-go-instrumentation/internal/pkg/opentelemetry/controller.go",
    "line": 75
  },
  "msg": "getting tracer",
  "name": "",
  "version": "",
  "schema": "https://opentelemetry.io/schemas/1.26.0"
}
{
  "time": "2024-10-16T21:42:16.994412896+05:30",
  "level": "DEBUG",
  "source": {
    "function": "go.opentelemetry.io/auto/internal/pkg/opentelemetry.(*Controller).Trace",
    "file": "/go/src/Flights-GI-Backend/opentelemetry-go-instrumentation/internal/pkg/opentelemetry/controller.go",
    "line": 75
  },
  "msg": "getting tracer",
  "name": "Flights-GI-Backend-ts",
  "version": "",
  "schema": ""
}{
  "time": "2024-10-16T21:42:17.012567507+05:30",
  "level": "DEBUG",
  "source": {
    "function": "go.opentelemetry.io/auto/internal/pkg/opentelemetry.(*Controller).Trace",
    "file": "/go/src/Flights-GI-Backend/opentelemetry-go-instrumentation/internal/pkg/opentelemetry/controller.go",
    "line": 56
  },
  "msg": "got event",
  "kind": "client",
  "pkg": "net/http",
  "attrs": [
    {
      "Key": "http.request.method",
      "Value": {
        "Type": "STRING",
        "Value": "GET"
      }
    },
    {
      "Key": "http.response.status_code",
      "Value": {
        "Type": "INT64",
        "Value": 200
      }
    },
    {
      "Key": "url.path",
      "Value": {
        "Type": "STRING",
        "Value": "/flights-b2c-misc/v2/daily-steal-deals"
      }
    },
    {
      "Key": "url.full",
      "Value": {
        "Type": "STRING",
        "Value": "http://flights-proxy-service.ecs.mmt/flights-b2c-misc/v2/daily-steal-deals?city=DEL%2CBOM%2CGOI%2CHYD%2CMAA%2CBLR%2CCCU%2CSXR%2CTRV%2CAMD\u0026currency=inr\u0026language=eng\u0026region=in"
      }
    },
    {
      "Key": "server.address",
      "Value": {
        "Type": "STRING",
        "Value": "flights-proxy-service.ecs.mmt"
      }
    },
    {
      "Key": "network.protocol.version",
      "Value": {
        "Type": "STRING",
        "Value": "1.1"
      }
    }
  ],
  "traceID": "fc5c0c088229b958b83394fdc68abd5c",
  "spanID": "2e064b5142cce655"
}{
  "time": "2024-10-16T21:42:17.01267172+05:30",
  "level": "DEBUG",
  "source": {
    "function": "go.opentelemetry.io/auto/internal/pkg/opentelemetry.(*Controller).Trace",
    "file": "/go/src/Flights-GI-Backend/opentelemetry-go-instrumentation/internal/pkg/opentelemetry/controller.go",
    "line": 75
  },
  "msg": "getting tracer",
  "name": "",
  "version": "",
  "schema": "https://opentelemetry.io/schemas/1.26.0"
}{
  "time": "2024-10-16T21:42:17.014058278+05:30",
  "level": "DEBUG",
  "source": {
    "function": "go.opentelemetry.io/auto/internal/pkg/opentelemetry.(*Controller).Trace",
    "file": "/go/src/Flights-GI-Backend/opentelemetry-go-instrumentation/internal/pkg/opentelemetry/controller.go",
    "line": 56
  },
  "msg": "got event",
  "kind": "server",
  "pkg": "net/http",
  "attrs": [
    {
      "Key": "http.request.method",
      "Value": {
        "Type": "STRING",
        "Value": "POST"
      }
    },
    {
      "Key": "url.path",
      "Value": {
        "Type": "STRING",
        "Value": "/v1/thor/rest/flight/home/deals"
      }
    },
    {
      "Key": "http.response.status_code",
      "Value": {
        "Type": "INT64",
        "Value": 200
      }
    },
    {
      "Key": "network.peer.address",
      "Value": {
        "Type": "STRING",
        "Value": "127.0.0.1"
      }
    },
    {
      "Key": "network.peer.port",
      "Value": {
        "Type": "INT64",
        "Value": 49778
      }
    },
    {
      "Key": "server.address",
      "Value": {
        "Type": "STRING",
        "Value": "gicb"
      }
    },
    {
      "Key": "network.protocol.version",
      "Value": {
        "Type": "STRING",
        "Value": "1.1"
      }
    }
  ],
  "traceID": "fc57d028e13d5cf01fcc68224be25f75",
  "spanID": "298504b20bd9459a"
}{
  "time": "2024-10-16T21:42:17.014099379+05:30",
  "level": "DEBUG",
  "source": {
    "function": "go.opentelemetry.io/auto/internal/pkg/opentelemetry.(*Controller).Trace",
    "file": "/go/src/Flights-GI-Backend/opentelemetry-go-instrumentation/internal/pkg/opentelemetry/controller.go",
    "line": 75
  },
  "msg": "getting tracer",
  "name": "",
  "version": "",
  "schema": "https://opentelemetry.io/schemas/1.26.0"
}

[damemi]

@shravanv1 do you have the full logs from the agent from when it starts up? Not just the logs around the spans. I'm looking for a message that would indicate if your host supports context propagation

[shravanv1]

@damemi the thing is when I am using this ctx := icontext.NewContext() in this method func copyGinContext(c *gin.Context) icontext.IContext to create the icontext I thing there it is breaking , but when I am using ctx := icontext.NewContextFromParent(c.Request.Context()) context propgation is working fine. But I can't use this NewContextFromParent bcz I am using icontext later for async logging and once the request complete this got cancelled.

adding @MrAlias also. As this is a bit urgent I am planing to go live with auto instrumentation on prod.

PFA start up logs
otel.json

[RonFed]

@shravanv1 you pointed out the problem correctly. Currently, for in-process context propagation to work the context of the outgoing request must be a descendant of the one from the incoming request.
ctx := icontext.NewContext() breaks that.