Spring Cloud Gateway (with Netty): Otel auto-instrumentation generates mutiple invalid traces

[ziomill]

Hi guys,

I'm using Open Telemetry auto instrumentation (1.21.0) on a Spring Cloud Gateway instance for trace handling. The Spring Cloud Gateway simply proxies incoming calls to some internal microservices.

It happens that, for a single incoming request, two different traces are created at the gateway level.

See this log:

1. The incoming request arrives at the Spring Cloud Gateway instance.
2. The OpenTelemetry agent generates a first trace having trace-id: 166fe40addb0d7333de1e7289ac01483 and span-id: cf9cde89ad120b9f (lines 1 and 2). This trace remains orphaned, and it will not be passed to the proxied microservice.
3. The OpenTelemetry agent generates a second trace having trace-id: 68f2fd4d11efa82eb1e15fd4ce438705 and span-id: b744f6251966d095 (line 4).
4. The gateway performs the request to the target microservice passing the second trace (trace-id: 68f2fd4d11efa82eb1e15fd4ce438705 and span-id: b744f6251966d095) in the context.

{"Timestamp":"2022-12-31T11:17:16.438Z","TraceId":"166fe40addb0d7333de1e7289ac01483","SpanId":"cf9cde89ad120b9f","SeverityText":"DEBUG","Body":"[80d50eb5] REGISTERED","Resource":{},"Attributes":{"tag":"applicative_log","thread":"reactor-http-nio-2","class":"reactor.netty.http.client.HttpClient"}}
{"Timestamp":"2022-12-31T11:17:16.439Z","TraceId":"166fe40addb0d7333de1e7289ac01483","SpanId":"cf9cde89ad120b9f","SeverityText":"DEBUG","Body":"[80d50eb5] CONNECT: localhost/127.0.0.1:10000","Resource":{},"Attributes":{"tag":"applicative_log","thread":"reactor-http-nio-2","class":"reactor.netty.http.client.HttpClient"}}
{"Timestamp":"2022-12-31T11:17:16.44Z","SeverityText":"DEBUG","Body":"[80d50eb5, L:/127.0.0.1:50836 - R:localhost/127.0.0.1:10000] ACTIVE","Resource":{},"Attributes":{"tag":"applicative_log","thread":"reactor-http-nio-2","class":"reactor.netty.http.client.HttpClient"}}
{"Timestamp":"2022-12-31T11:17:16.44Z","SeverityText":"DEBUG","Body":"[80d50eb5-1, L:/127.0.0.1:50836 - R:localhost/127.0.0.1:10000] Handler is being applied: {uri=http://localhost:10000/users-api/users, method=GET}","Resource":{},"Attributes":{"tag":"applicative_log","thread":"reactor-http-nio-2","class":"reactor.netty.http.client.HttpClientConnect"}}
{"Timestamp":"2022-12-31T11:17:16.441Z","TraceId":"68f2fd4d11efa82eb1e15fd4ce438705","SpanId":"b744f6251966d095","SeverityText":"DEBUG","Body":"[80d50eb5-1, L:/127.0.0.1:50836 - R:localhost/127.0.0.1:10000] WRITE: 497B\r\n         +-------------------------------------------------+\r\n         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |\r\n+--------+-------------------------------------------------+----------------+\r\n|00000000| 47 45 54 20 2f 75 73 65 72 73 2d 61 70 69 2f 75 |GET /users-api/u|\r\n|00000010| 73 65 72 73 20 48 54 54 50 2f 31 2e 31 0d 0a 55 |sers HTTP/1.1..U|\r\n|00000020| 73 65 72 2d 41 67 65 6e 74 3a 20 69 6e 73 6f 6d |ser-Agent: insom|\r\n|00000030| 6e 69 61 2f 32 30 32 32 2e 37 2e 30 0d 0a 43 6f |nia/2022.7.0..Co|\r\n|00000040| 6f 6b 69 65 3a 20 72 65 71 75 65 73 74 65 64 55 |okie: requestedU|\r\n|00000050| 52 49 3d 2e 2e 2f 2e 2e 2f 61 67 77 2d 75 73 65 |RI=../../agw-use|\r\n|00000060| 72 73 2d 61 70 69 2f 76 31 2f 6c 69 73 74 3b 20 |rs-api/v1/list; |\r\n|00000070| 4a 53 45 53 53 49 4f 4e 49 44 3d 36 32 39 37 41 |JSESSIONID=6297A|\r\n|00000080| 37 44 31 35 31 30 33 43 41 45 41 31 36 32 42 46 |7D15103CAEA162BF|\r\n|00000090| 36 33 32 39 32 34 30 35 38 43 39 0d 0a 41 63 63 |632924058C9..Acc|\r\n|000000a0| 65 70 74 3a 20 2a 2f 2a 0d 0a 46 6f 72 77 61 72 |ept: */*..Forwar|\r\n|000000b0| 64 65 64 3a 20 70 72 6f 74 6f 3d 68 74 74 70 3b |ded: proto=http;|\r\n|000000c0| 68 6f 73 74 3d 22 6c 6f 63 61 6c 68 6f 73 74 3a |host=\"localhost:|\r\n|000000d0| 39 30 30 30 22 3b 66 6f 72 3d 22 31 32 37 2e 30 |9000\";for=\"127.0|\r\n|000000e0| 2e 30 2e 31 3a 35 30 37 39 38 22 0d 0a 58 2d 46 |.0.1:50798\"..X-F|\r\n|000000f0| 6f 72 77 61 72 64 65 64 2d 46 6f 72 3a 20 31 32 |orwarded-For: 12|\r\n|00000100| 37 2e 30 2e 30 2e 31 0d 0a 58 2d 46 6f 72 77 61 |7.0.0.1..X-Forwa|\r\n|00000110| 72 64 65 64 2d 50 72 6f 74 6f 3a 20 68 74 74 70 |rded-Proto: http|\r\n|00000120| 0d 0a 58 2d 46 6f 72 77 61 72 64 65 64 2d 50 72 |..X-Forwarded-Pr|\r\n|00000130| 65 66 69 78 3a 20 2f 73 68 6f 70 73 2d 61 70 69 |efix: /shops-api|\r\n|00000140| 2d 67 77 0d 0a 58 2d 46 6f 72 77 61 72 64 65 64 |-gw..X-Forwarded|\r\n|00000150| 2d 50 6f 72 74 3a 20 39 30 30 30 0d 0a 58 2d 46 |-Port: 9000..X-F|\r\n|00000160| 6f 72 77 61 72 64 65 64 2d 48 6f 73 74 3a 20 6c |orwarded-Host: l|\r\n|00000170| 6f 63 61 6c 68 6f 73 74 3a 39 30 30 30 0d 0a 68 |ocalhost:9000..h|\r\n|00000180| 6f 73 74 3a 20 6c 6f 63 61 6c 68 6f 73 74 3a 31 |ost: localhost:1|\r\n|00000190| 30 30 30 30 0d 0a 63 6f 6e 74 65 6e 74 2d 6c 65 |0000..content-le|\r\n|000001a0| 6e 67 74 68 3a 20 30 0d 0a 74 72 61 63 65 70 61 |ngth: 0..tracepa|\r\n|000001b0| 72 65 6e 74 3a 20 30 30 2d 37 63 31 34 63 66 34 |rent: 00-7c14cf4|\r\n|000001c0| 39 31 65 65 32 39 38 38 37 62 63 36 61 61 62 33 |91ee29887bc6aab3|\r\n|000001d0| 31 61 65 64 31 34 30 63 37 2d 35 66 34 62 34 39 |1aed140c7-5f4b49|\r\n|000001e0| 34 39 65 65 62 37 64 33 36 35 2d 30 31 0d 0a 0d |49eeb7d365-01...|\r\n|000001f0| 0a                                              |.               |\r\n+--------+-------------------------------------------------+----------------+","Resource":{},"Attributes":{"tag":"applicative_log","thread":"reactor-http-nio-2","class":"reactor.netty.http.client.HttpClient"}}
{"Timestamp":"2022-12-31T11:17:16.441Z","SeverityText":"DEBUG","Body":"[80d50eb5-1, L:/127.0.0.1:50836 - R:localhost/127.0.0.1:10000] FLUSH","Resource":{},"Attributes":{"tag":"applicative_log","thread":"reactor-http-nio-2","class":"reactor.netty.http.client.HttpClient"}}
{"Timestamp":"2022-12-31T11:17:16.452Z","SeverityText":"DEBUG","Body":"[80d50eb5-1, L:/127.0.0.1:50836 - R:localhost/127.0.0.1:10000] READ: 314B\r\n         +-------------------------------------------------+\r\n         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |\r\n+--------+-------------------------------------------------+----------------+\r\n|00000000| 48 54 54 50 2f 31 2e 31 20 32 30 30 20 0d 0a 43 |HTTP/1.1 200 ..C|\r\n|00000010| 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70 70 |ontent-Type: app|\r\n|00000020| 6c 69 63 61 74 69 6f 6e 2f 6a 73 6f 6e 0d 0a 54 |lication/json..T|\r\n|00000030| 72 61 6e 73 66 65 72 2d 45 6e 63 6f 64 69 6e 67 |ransfer-Encoding|\r\n|00000040| 3a 20 63 68 75 6e 6b 65 64 0d 0a 44 61 74 65 3a |: chunked..Date:|\r\n|00000050| 20 53 61 74 2c 20 33 31 20 44 65 63 20 32 30 32 | Sat, 31 Dec 202|\r\n|00000060| 32 20 31 31 3a 31 37 3a 31 36 20 47 4d 54 0d 0a |2 11:17:16 GMT..|\r\n|00000070| 0d 0a 63 32 0d 0a 5b 7b 22 6e 61 6d 65 22 3a 22 |..c2..[{\"name\":\"|\r\n|00000080| 4a 68 6f 6e 22 2c 22 73 75 72 6e 61 6d 65 22 3a |Jhon\",\"surname\":|\r\n|00000090| 22 44 6f 65 22 2c 22 65 6d 61 69 6c 22 3a 22 6a |\"Doe\",\"email\":\"j|\r\n|000000a0| 68 6f 6e 2e 64 6f 65 40 67 6d 61 69 6c 2e 63 6f |hon.doe@gmail.co|\r\n|000000b0| 6d 22 7d 2c 7b 22 6e 61 6d 65 22 3a 22 4c 75 6b |m\"},{\"name\":\"Luk|\r\n|000000c0| 65 22 2c 22 73 75 72 6e 61 6d 65 22 3a 22 42 6c |e\",\"surname\":\"Bl|\r\n|000000d0| 75 65 22 2c 22 65 6d 61 69 6c 22 3a 22 6c 75 6b |ue\",\"email\":\"luk|\r\n|000000e0| 65 2e 62 6c 75 65 40 67 6d 61 69 6c 2e 63 6f 6d |e.blue@gmail.com|\r\n|000000f0| 22 7d 2c 7b 22 6e 61 6d 65 22 3a 22 41 72 6d 61 |\"},{\"name\":\"Arma|\r\n|00000100| 6e 64 22 2c 22 73 75 72 6e 61 6d 65 22 3a 22 53 |nd\",\"surname\":\"S|\r\n|00000110| 74 6f 6e 65 22 2c 22 65 6d 61 69 6c 22 3a 22 61 |tone\",\"email\":\"a|\r\n|00000120| 72 6d 61 6e 64 2e 73 74 6f 6e 65 40 67 6d 61 69 |rmand.stone@gmai|\r\n|00000130| 6c 2e 63 6f 6d 22 7d 5d 0d 0a                   |l.com\"}]..      |\r\n+--------+-------------------------------------------------+----------------+","Resource":{},"Attributes":{"tag":"applicative_log","thread":"reactor-http-nio-2","class":"reactor.netty.http.client.HttpClient"}}
{"Timestamp":"2022-12-31T11:17:16.452Z","SeverityText":"DEBUG","Body":"[80d50eb5-1, L:/127.0.0.1:50836 - R:localhost/127.0.0.1:10000] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)\r\nHTTP/1.1 200 \r\nContent-Type: <filtered>\r\nTransfer-Encoding: <filtered>\r\nDate: <filtered>","Resource":{},"Attributes":{"tag":"applicative_log","thread":"reactor-http-nio-2","class":"reactor.netty.http.client.HttpClientOperations"}}
{"Timestamp":"2022-12-31T11:17:16.454Z","SeverityText":"DEBUG","Body":"[80d50eb5-1, L:/127.0.0.1:50836 - R:localhost/127.0.0.1:10000] READ COMPLETE","Resource":{},"Attributes":{"tag":"applicative_log","thread":"reactor-http-nio-2","class":"reactor.netty.http.client.HttpClient"}}
{"Timestamp":"2022-12-31T11:17:16.455Z","SeverityText":"DEBUG","Body":"[80d50eb5-1, L:/127.0.0.1:50836 - R:localhost/127.0.0.1:10000] READ: 5B\r\n         +-------------------------------------------------+\r\n         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |\r\n+--------+-------------------------------------------------+----------------+\r\n|00000000| 30 0d 0a 0d 0a                                  |0....           |\r\n+--------+-------------------------------------------------+----------------+","Resource":{},"Attributes":{"tag":"applicative_log","thread":"reactor-http-nio-2","class":"reactor.netty.http.client.HttpClient"}}
{"Timestamp":"2022-12-31T11:17:16.455Z","SeverityText":"DEBUG","Body":"[80d50eb5-1, L:/127.0.0.1:50836 - R:localhost/127.0.0.1:10000] Received last HTTP packet","Resource":{},"Attributes":{"tag":"applicative_log","thread":"reactor-http-nio-2","class":"reactor.netty.http.client.HttpClientOperations"}}
{"Timestamp":"2022-12-31T11:17:16.457Z","SeverityText":"DEBUG","Body":"[80d50eb5, L:/127.0.0.1:50836 - R:localhost/127.0.0.1:10000] READ COMPLETE","Resource":{},"Attributes":{"tag":"applicative_log","thread":"reactor-http-nio-2","class":"reactor.netty.http.client.HttpClient"}}

So, in the jaeger console, I see two traces for this single incoming request.

The orphaned one:

And the correct one:

It sounds like a bug in the netty auto instrumentation to me.
Do you agree with me?

Thank you for help!

[mateuszrzeszutek]

Hey @ziomill ,

Can you open a bug for this issue? Please include more information about the two traces/spans (in particular, the name of the instrumentation that produced them). If possible, could you create a repro scenario that'd allow to debug this?
Thanks!

[ziomill]

@mateuszrzeszutek I opened the bug
As you have suggested, I have also provided a working scenario in order to reproduce the issue.
All the details in the issue.

Thank you for your support