Opentelemetry autoinstrumentation with Log4j sending logs #7049

ggallotti · 2022-11-04T19:45:09Z

ggallotti
Nov 4, 2022

Hi guys.
I would really appreciate any help.

I have a Tomcat WebApplication running on Docker. A OTEL Collector is running also, in the same Docker Compose.

Metrics and Traces are working ok, but cannot make work the logs sdk part (seems that the agent is not sending them). Trying to use log4j2 autoinstrumentation.

Using OpenTelementry SDK: 1.19.2

[otel.javaagent 2022-11-04 19:48:06:583 +0000] [main] INFO io.opentelemetry.javaagent.tooling.VersionLogger - opentelemetry-javaagent - version: 1.19.2
04-Nov-2022 19:48:08.698 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version name:   Apache Tomcat/9.0.65
04-Nov-2022 19:48:08.701 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Jul 14 2022 12:28:53 UTC
04-Nov-2022 19:48:08.701 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version number: 9.0.65.0
04-Nov-2022 19:48:08.701 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Linux
04-Nov-2022 19:48:08.701 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            5.10.102.1-microsoft-standard-WSL2

Also added to webapp lib:

opentelemetry-sdk-logs-1.19.0-alpha.jar

Log4J:

log4j-api-2.17.0.jar
log4j-core-2.17.0.jar

Log4j2.xml logs only to Console (SYSOUT).

The WebApp is configured with envvars:

app:
    image: testotelgenexus
    environment:      
      - OTEL_SERVICE_NAME=myapp
      - OTEL_LOG_LEVEL=debug
      - OTEL_EXPORTER_OTLP_ENDPOINT=http://otel-collector:4317

log4j2-appender seems to have been instrumented:

[otel.javaagent 2022-11-04 19:34:22:078 +0000] [main] DEBUG io.opentelemetry.javaagent.extension.instrumentation.InstrumentationModule - Applying instrumentation: log4j-appender [class io.opentelemetry.javaagent.instrumentation.log4j.appender.v2_17.Log4jAppenderInstrumentationModule] on ParallelWebappClassLoader
  context: ROOT
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@1faf386c

[otel.javaagent 2022-11-04 19:34:22:079 +0000] [main] DEBUG io.opentelemetry.javaagent.tooling.HelperInjector - Injecting classes onto class loader ParallelW
  context: ROOT
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@1faf386c
 -> [io.opentelemetry.javaagent.instrumentation.log4j.appender.v2_17.Log4jHelper, io.opentelemetry.javaagent.shaded.instrumentation.log4j.appender.v2_17.internal.ContextDataAccessor, io.opentelemetry.javaagent.shaded.instrumentation.log4j.appender.v2_17.internal.LogEventMapper, io.opentelemetry.javaagent.shaded.instrumentation.log4j.appender.v2_17.internal.LogEventMapper$1, io.opentelemetry.javaagent.instrumentation.log4j.appender.v2_17.Log4jHelper$ContextDataAccessorImpl]
[otel.javaagent 2022-11-04 19:34:22:093 +0000] [main] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed org.apache.logging.log4j.spi.AbstractLogger -- ParallelWebappClassLoader
  context: ROOT
  delegate: false

However, I cannot see in the WebApplication Logs that the LogEvent is sent to the OTEL Collector.
Traces and metrics work ok. Logs are printed in the SYSOut of the Container.

OTEL collector has enabled "logs" pipeline.:

service:
    logs:
      receivers: [otlp]
      processors: [batch]
      exporters: [logging]

Do I need to add the OpenTelemetry Appender to the log4j2.xml manually? Or the integration should be donde automatically?

I cannot figure out why the instrumentation is not working.

This is the full Agent log when the logging is printed in the SYS OUT:

2022-11-04T19:35:34,625 [http-nio-8080-exec-2] INFO  AppLog.ListCars - Start ListCars (INFO)
2022-11-04T19:35:34,625 [http-nio-8080-exec-2] INFO  AppLog.ListCars - Start ListCars (INFO)
2022-11-04T19:35:34,625 [http-nio-8080-exec-2] DEBUG AppLog.ListCars - Start ListCars (Debug)
2022-11-04T19:35:34,625 [http-nio-8080-exec-2] DEBUG AppLog.ListCars - Start ListCars (Debug)
[otel.javaagent 2022-11-04 19:35:34:640 +0000] [http-nio-8080-exec-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed com.microsoft.sqlserver.jdbc.SQLServerDriver -- ParallelWebappClassLoader
  context: ROOT
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@1faf386c

[otel.javaagent 2022-11-04 19:35:34:661 +0000] [http-nio-8080-exec-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed com.app.db.driver.GXConnection$1 -- ParallelWebappClassLoader
  context: ROOT
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@1faf386c

[otel.javaagent 2022-11-04 19:35:34:668 +0000] [http-nio-8080-exec-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed com.microsoft.sqlserver.jdbc.ISQLServerConnection -- ParallelWebappClassLoader
  context: ROOT
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@1faf386c

[otel.javaagent 2022-11-04 19:35:34:691 +0000] [http-nio-8080-exec-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed com.microsoft.sqlserver.jdbc.SQLServerConnection -- ParallelWebappClassLoader
  context: ROOT
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@1faf386c

[otel.javaagent 2022-11-04 19:35:34:704 +0000] [http-nio-8080-exec-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed com.microsoft.sqlserver.jdbc.ISQLServerStatement -- ParallelWebappClassLoader
  context: ROOT
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@1faf386c

[otel.javaagent 2022-11-04 19:35:34:718 +0000] [http-nio-8080-exec-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed com.microsoft.sqlserver.jdbc.ReconnectThread -- ParallelWebappClassLoader
  context: ROOT
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@1faf386c

[otel.javaagent 2022-11-04 19:35:34:756 +0000] [OkHttp otel-collector] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10003 scheduled after   0 µs: OkHttp otel-collector ping
[otel.javaagent 2022-11-04 19:35:34:756 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10003 starting              : OkHttp otel-collector ping
[otel.javaagent 2022-11-04 19:35:34:757 +0000] [OkHttp http://otel-collector:4317/...] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10002 scheduled after   0 µs: OkHttp ConnectionPool
[otel.javaagent 2022-11-04 19:35:34:757 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10002 starting              : OkHttp ConnectionPool
[otel.javaagent 2022-11-04 19:35:34:757 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10003 finished run in 421 µs: OkHttp otel-collector ping
[otel.javaagent 2022-11-04 19:35:34:757 +0000] [OkHttp ConnectionPool] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10002 run again after 300 s : OkHttp ConnectionPool
[otel.javaagent 2022-11-04 19:35:34:757 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10002 finished run in 241 µs: OkHttp ConnectionPool
[otel.javaagent 2022-11-04 19:35:34:929 +0000] [http-nio-8080-exec-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed com.app.db.driver.GXStatement -- ParallelWebappClassLoader
  context: ROOT
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@1faf386c

[otel.javaagent 2022-11-04 19:35:34:937 +0000] [http-nio-8080-exec-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed com.app.db.driver.GXPreparedStatement -- ParallelWebappClassLoader
  context: ROOT
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@1faf386c

[otel.javaagent 2022-11-04 19:35:34:955 +0000] [http-nio-8080-exec-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed com.microsoft.sqlserver.jdbc.SQLServerStatement -- ParallelWebappClassLoader
  context: ROOT
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@1faf386c

[otel.javaagent 2022-11-04 19:35:34:962 +0000] [http-nio-8080-exec-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed com.microsoft.sqlserver.jdbc.ISQLServerPreparedStatement -- ParallelWebappClassLoader
  context: ROOT
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@1faf386c

[otel.javaagent 2022-11-04 19:35:34:976 +0000] [http-nio-8080-exec-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement -- ParallelWebappClassLoader
  context: ROOT
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@1faf386c

[otel.javaagent 2022-11-04 19:35:35:002 +0000] [http-nio-8080-exec-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed mssql.googlecode.concurrentlinkedhashmap.ConcurrentLinkedHashMap$AddTask -- ParallelWebappClassLoader
  context: ROOT
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@1faf386c

[otel.javaagent 2022-11-04 19:35:35:081 +0000] [http-nio-8080-exec-2] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'SELECT test' : ab9830cb7b9ddbb4de35af13edab4675 2605c48996bab302 CLIENT [tracer: io.opentelemetry.jdbc:1.19.2-alpha] AttributesMap{data={net.peer.port=1433, thread.name=http-nio-8080-exec-2, db.name=test, db.operation=SELECT, db.statement=SELECT @@spid, db.system=mssql, thread.id=38, db.connection_string=sqlserver://172.16.3.125:1433, net.peer.name=172.16.3.125}, capacity=128, totalAddedValues=9}
[otel.javaagent 2022-11-04 19:35:35:101 +0000] [http-nio-8080-exec-2] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'SELECT test.CarMake' : ab9830cb7b9ddbb4de35af13edab4675 ecd9d138bf2100b7 CLIENT [tracer: io.opentelemetry.jdbc:1.19.2-alpha] AttributesMap{data={net.peer.port=1433, thread.name=http-nio-8080-exec-2, db.name=test, db.sql.table=CarMake, db.operation=SELECT, db.statement=SELECT [CarMakeId], [CarMakeName] FROM [CarMake] ORDER BY [CarMakeId] , db.system=mssql, thread.id=38, db.connection_string=sqlserver://172.16.3.125:1433, net.peer.name=172.16.3.125, db.user=ggallotti}, capacity=128, totalAddedValues=11}
**2022-11-04T19:35:35,103 [http-nio-8080-exec-2] INFO  App.ListCars - End ListCars
2022-11-04T19:35:35,103 [http-nio-8080-exec-2] INFO  App.ListCars - End ListCars**
[otel.javaagent 2022-11-04 19:35:35:116 +0000] [http-nio-8080-exec-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed HTTPClient.SocketTimeout -- ParallelWebappClassLoader
  context: ROOT
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@1faf386c

[otel.javaagent 2022-11-04 19:35:35:119 +0000] [http-nio-8080-exec-2] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'carsapi_services_rest.gxep_list' : ab9830cb7b9ddbb4de35af13edab4675 af70e28a6851fe00 INTERNAL [tracer: io.opentelemetry.jaxrs-2.0-annotations:1.19.2-alpha] AttributesMap{data={thread.name=http-nio-8080-exec-2, code.function=gxep_list, thread.id=38, code.namespace=com.testopentelemetry.carsapi_services_rest}, capacity=128, totalAddedValues=4}
[otel.javaagent 2022-11-04 19:35:35:158 +0000] [OkHttp otel-collector] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10003 scheduled after   0 µs: OkHttp otel-collector ping
[otel.javaagent 2022-11-04 19:35:35:159 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10003 starting              : OkHttp otel-collector ping
[otel.javaagent 2022-11-04 19:35:35:159 +0000] [OkHttp http://otel-collector:4317/...] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10002 scheduled after   0 µs: OkHttp ConnectionPool
[otel.javaagent 2022-11-04 19:35:35:159 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10002 starting              : OkHttp ConnectionPool
[otel.javaagent 2022-11-04 19:35:35:159 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10003 finished run in 383 µs: OkHttp otel-collector ping
[otel.javaagent 2022-11-04 19:35:35:159 +0000] [OkHttp ConnectionPool] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10002 run again after 300 s : OkHttp ConnectionPool
[otel.javaagent 2022-11-04 19:35:35:159 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10002 finished run in 229 µs: OkHttp ConnectionPool
[otel.javaagent 2022-11-04 19:35:35:189 +0000] [http-nio-8080-exec-2] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - '/rest/{carsapi :(?i)carsapi}/{list :(?i)list}' : ab9830cb7b9ddbb4de35af13edab4675 aaf0a31a51d20ae7 SERVER [tracer: io.opentelemetry.tomcat-7.0:1.19.2-alpha] AttributesMap{data={http.method=GET, http.scheme=http, net.sock.host.addr=192.168.192.7, http.user_agent=Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36, http.route=/rest/{carsapi :(?i)carsapi}/{list :(?i)list}, thread.name=http-nio-8080-exec-2, http.response_content_length=135, net.host.port=1111, http.status_code=200, net.sock.peer.port=45612, http.target=/CarsAPI/List, net.sock.peer.addr=192.168.192.1, http.flavor=1.1, thread.id=38, net.sock.host.port=8080, net.host.name=localhost, net.transport=ip_tcp}, capacity=128, totalAddedValues=17}
[otel.javaagent 2022-11-04 19:35:37:677 +0000] [OkHttp http://otel-collector:4317/...] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10014 scheduled after   0 µs: OkHttp otel-collector
[otel.javaagent 2022-11-04 19:35:37:677 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10014 starting              : OkHttp otel-collector
[otel.javaagent 2022-11-04 19:35:37:677 +0000] [OkHttp http://otel-collector:4317/...] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10001 scheduled after   0 µs: OkHttp ConnectionPool
[otel.javaagent 2022-11-04 19:35:37:677 +0000] [OkHttp otel-collector] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10011 scheduled after   0 µs: OkHttp otel-collector applyAndAckSettings
[otel.javaagent 2022-11-04 19:35:37:678 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10001 starting              : OkHttp ConnectionPool
[otel.javaagent 2022-11-04 19:35:37:679 +0000] [OkHttp ConnectionPool] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10001 run again after 300 s : OkHttp ConnectionPool
[otel.javaagent 2022-11-04 19:35:37:679 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10011 starting              : OkHttp otel-collector applyAndAckSettings
[otel.javaagent 2022-11-04 19:35:37:679 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10001 finished run in   1 ms: OkHttp ConnectionPool
[otel.javaagent 2022-11-04 19:35:37:679 +0000] [OkHttp otel-collector] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10011 scheduled after   0 µs: OkHttp otel-collector ping
[otel.javaagent 2022-11-04 19:35:37:680 +0000] [OkHttp otel-collector applyAndAckSettings] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10013 scheduled after   0 µs: OkHttp otel-collector onSettings
[otel.javaagent 2022-11-04 19:35:37:680 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10013 starting              : OkHttp otel-collector onSettings
[otel.javaagent 2022-11-04 19:35:37:680 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10011 finished run in   1 ms: OkHttp otel-collector applyAndAckSettings
[otel.javaagent 2022-11-04 19:35:37:680 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10013 finished run in 383 µs: OkHttp otel-collector onSettings
[otel.javaagent 2022-11-04 19:35:37:680 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10011 starting              : OkHttp otel-collector ping
[otel.javaagent 2022-11-04 19:35:37:680 +0000] [OkHttp http://otel-collector:4317/...] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10001 scheduled after   0 µs: OkHttp ConnectionPool
[otel.javaagent 2022-11-04 19:35:37:681 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10001 starting              : OkHttp ConnectionPool
[otel.javaagent 2022-11-04 19:35:37:681 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10011 finished run in 595 µs: OkHttp otel-collector ping
[otel.javaagent 2022-11-04 19:35:37:681 +0000] [OkHttp ConnectionPool] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10001 run again after 300 s : OkHttp ConnectionPool
[otel.javaagent 2022-11-04 19:35:37:681 +0000] [OkHttp TaskRunner] DEBUG okhttp3.internal.concurrent.TaskRunner - Q10001 finished run in 263 µs: OkHttp ConnectionPool
[otel.javaagent 2022-11-04 19:35:38:505 +0000] [supportability_metrics_reporter] DEBUG io.opentelemetry.javaagent.shaded.instrumentation.api.internal.SupportabilityMetrics - Counter 'SqlStatementSanitizer cache miss' : 2

Answered by trask

Nov 5, 2022

hi @ggallotti, did you configure the log exporter?

https://github.com/open-telemetry/opentelemetry-java/blob/main/sdk-extensions/autoconfigure/README.md#exporters

the default log exporter is still none since logs are still -alpha

View full answer

trask · 2022-11-05T01:16:43Z

trask
Nov 5, 2022
Maintainer

hi @ggallotti, did you configure the log exporter?

https://github.com/open-telemetry/opentelemetry-java/blob/main/sdk-extensions/autoconfigure/README.md#exporters

the default log exporter is still none since logs are still -alpha

2 replies

ggallotti Nov 5, 2022
Author

Thank you @trask ! Adding OTEL_LOGS_EXPORTER=otlp got it working!
You saved my day! Thank you very much for your time!

trajano Nov 8, 2023

It's beta now :) but still not enabled. I was just trying to see where it is in the code just now but it only appears on some test case so I guess it is outside the scope of this github project.

greatvovan · 2024-10-18T09:58:37Z

greatvovan
Oct 18, 2024

How do you enable this verbose instrumentation logging? I tried -Dotel.javaagent.debug=true but I still don't see that my log4j is instrumented by the agent.

1 reply

trask Oct 18, 2024
Maintainer

hi @greatvovan, log4j should be instrumented by default. -Dotel.javaagent.debug is for a different purpose, to enable the agent's internal self-diagnostic debug logging. can you open a new issue and include more details about the problem you're facing?

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Opentelemetry autoinstrumentation with Log4j sending logs #7049

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 2 comments 3 replies

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

Opentelemetry autoinstrumentation with Log4j sending logs #7049

ggallotti Nov 4, 2022

Replies: 2 comments · 3 replies

trask Nov 5, 2022 Maintainer

ggallotti Nov 5, 2022 Author

trajano Nov 8, 2023

greatvovan Oct 18, 2024

trask Oct 18, 2024 Maintainer

ggallotti
Nov 4, 2022

Replies: 2 comments 3 replies

trask
Nov 5, 2022
Maintainer

ggallotti Nov 5, 2022
Author

greatvovan
Oct 18, 2024

trask Oct 18, 2024
Maintainer