Servlet instrumentation ignored when Undertow instrumentation is enabled

[amoscatelli]

Describe the bug
I run wildfly with otel java instrumentation and I see traces (for example jdbc traces) on my otel backend. Yet I can't see user.principal in my traces. Shouldn't servlet be instrumented automatically and user.principal added to tags ?

https://github.com/open-telemetry/opentelemetry-java-instrumentation/pull/466/files#r433592830

Steps to reproduce
Start wildfly with JAVA_TOOL_OPTIONS=-javaagent:/tmp/opentelemetry-javaagent.jar

What did you expect to see?
I expect to see user.principal added to trace

What did you see instead?
No user.principal added to trace

What version are you using?
otel/opentelemetry-collector-contrib:0.53.0
Wildfly 26.0.1

Environment
Centos 7

[mateuszrzeszutek]

Hey @amoscatelli ,
The user principal name is set as the enduser.id attribute: https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/main/instrumentation/servlet/servlet-common/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/servlet/ServletAdditionalAttributesExtractor.java#L49
Do your traces contain this attribute?

[amoscatelli]

@mateuszrzeszutek thank you for your answer.

No, my traces don't contain that attribute.

I enabled agent debugging with : -Dotel.javaagent.debug=true
Here are my logs ...

logs.txt

A strange thing is that I see DEBUG logging sent to System.err ... is this done by the agent ?

Another strange thing are these lines :

07:59:17,173 ERROR [stderr] (supportability_metrics_reporter) [otel.javaagent 2022-06-23 07:59:17:172 +0000] [supportability_metrics_reporter] DEBUG io.opentelemetry.javaagent.shaded.instrumentation.api.internal.SupportabilityMetrics - Suppressed Spans by 'io.opentelemetry.servlet-3.0' (SERVER) : 32
07:59:27,172 ERROR [stderr] (supportability_metrics_reporter) [otel.javaagent 2022-06-23 07:59:27:172 +0000] [supportability_metrics_reporter] DEBUG io.opentelemetry.javaagent.shaded.instrumentation.api.internal.SupportabilityMetrics - Suppressed Spans by 'io.opentelemetry.servlet-3.0' (SERVER) : 55
07:59:32,173 ERROR [stderr] (supportability_metrics_reporter) [otel.javaagent 2022-06-23 07:59:32:173 +0000] [supportability_metrics_reporter] DEBUG io.opentelemetry.javaagent.shaded.instrumentation.api.internal.SupportabilityMetrics - Suppressed Spans by 'io.opentelemetry.servlet-3.0' (SERVER) : 22

What is happening ?

[mateuszrzeszutek]

A strange thing is that I see DEBUG logging sent to System.err ... is this done by the agent ?

Yes, when you run the agent in the debug mode (-Dotel.javaagent.debug=true) it prints out lots of stuff to stderr.

Another strange thing are these lines :

07:59:17,173 ERROR [stderr] (supportability_metrics_reporter) [otel.javaagent 2022-06-23 07:59:17:172 +0000] [supportability_metrics_reporter] DEBUG io.opentelemetry.javaagent.shaded.instrumentation.api.internal.SupportabilityMetrics - Suppressed Spans by 'io.opentelemetry.servlet-3.0' (SERVER) : 32
07:59:27,172 ERROR [stderr] (supportability_metrics_reporter) [otel.javaagent 2022-06-23 07:59:27:172 +0000] [supportability_metrics_reporter] DEBUG io.opentelemetry.javaagent.shaded.instrumentation.api.internal.SupportabilityMetrics - Suppressed Spans by 'io.opentelemetry.servlet-3.0' (SERVER) : 55
07:59:32,173 ERROR [stderr] (supportability_metrics_reporter) [otel.javaagent 2022-06-23 07:59:32:173 +0000] [supportability_metrics_reporter] DEBUG io.opentelemetry.javaagent.shaded.instrumentation.api.internal.SupportabilityMetrics - Suppressed Spans by 'io.opentelemetry.servlet-3.0' (SERVER) : 22

What is happening ?

There are several "layers" of instrumentations that essentially do very similar things -- for example, we instrument application servers (like tomcat, jetty, undertow), and the servlet API itself. All these instrumentations create SERVER spans; and, since we don't want to have duplicate SERVER spans, usually the first instrumentation that executes creates the span and all other ones that come later are suppressed. These logs indicate that the servlet instrumentation was suppressed - because the SERVER span was already created by the Undertow instrumentation:

 '/optoplus-services-web/*' : 51d24d301ad020bb1d546abd62b67b06 cebf5ebdf9957617 SERVER [tracer: io.opentelemetry.undertow-1.4:1.15.0-alpha] AttributesMap{data={thread.id=135, http.route=/optoplus-services-web/*, http.user_agent=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/102.0.5005.63 Safari/537.36 Edg/102.0.1245.39, http.method=OPTIONS, http.response_content_length=0, http.scheme=http, http.status_code=202, http.target=/optoplus-services-web/api/credential, http.flavor=1.1, net.transport=ip_tcp, net.peer.ip=172.17.0.1, thread.name=default I/O-3, http.client_ip=192.168.0.41, net.peer.port=33418, http.host=localhost:8080}, capacity=128, totalAddedValues=15}

(see the tracer: io.opentelemetry.undertow-1.4:1.15.0-alpha part)

So, what happens, is that the Undertow instrumentation does not set the enduser.id attribute. And because it suppresses the servlet instrumentation, it does not execute and does not set it. This looks like a bug, either the Undertow instrumentation should set that attribute (like the Tomcat one does), or the servlet instrumentation should be reworked to fill that info in even if it did not create the span.

[amoscatelli]

@mateuszrzeszutek thank you again

So I can try to disable the undertow instrumentation right ?
Then it should work.

For me, at the moment, enduser.id information is very important to build my charts.

[mateuszrzeszutek]

Yeah, that should help I think - the servlet instrumentation should kick in once you disable undertow.

[amoscatelli]

Yea that worked.
Now I see enduser.id in my traces thank you @mateuszrzeszutek .

I think we should leave this issue opened (I'll rename it) to track the bug anyway.

Probably the correct behaviour is to have the FIRST (undertow) instrumentation in the stack to open a certain type of span (SERVER in this example), start filling it, while other subsequent instrumentations (like servlet) shoud fill tags in the same span, then at last when we go back to the top of the stack the span is sent by the first instrumentation.

[laurit]

@amoscatelli could you confirm that it works as expected with latest snapshot from https://oss.sonatype.org/content/repositories/snapshots/io/opentelemetry/javaagent/opentelemetry-javaagent/1.16.0-SNAPSHOT/

[amoscatelli]

@laurit yes it works properly using 1.16

thank you