JMS message beans doesn't contain elastic apm logging

[marinkton]

We upgraded our Spring Boot and Openliberty services to Java 17 and Spring Boot 3. What we've noticed is that the message beans for openliberty and spring boot (JMS) are not instrumenting the elasticsearch properties into the the logging. The rest-api's are logging correctly the elastic properties. We've also tried to print the trace id in our application by ourself with "ElasticApm.currentTransaction().getTraceId()". This is giving us an empty value.

So are we missing something in the configuration, because of the upgrade? We need the transaction and trace id in the logging.

The version we use is 1.39.0.

Our properties: elastic.apm: environment: dev service-name: apm-test-logging server-url: https://test:8200 verify-server-cert: false enable-log-correlation: true log-format-sout: json application-packages: nl.test central_config: false

[jackshirazi]

Can you try with version 1.35.0 to rule out or in some optimization that were added to the agent around messaging

[marinkton]

@jackshirazi I tried it and unfortunately it doesn't work. We're using as I said Spring Boot 3 and Open Liberty Services with Java 17. I see Spring Boot 3 support is added from version 1.38.0.

[jackshirazi]

I can't immediately see what's missing, it would be helpful if you have a minimal example I could run that shows the issue. Meanwhile I'll try to reproduce

[jackshirazi]

For reference, I used the spring boot tutorial app, from their reference repo. The only change I made to the complete example was to add a log line to the controller so that the log line could get the context, ie I added this just before the return

java.util.logging.Logger.getLogger(HelloController.class.getName()).info("logging greetings");

Command line options added

-javaagent:/agent/elastic-apm-agent-1.39.0.jar -Delastic.apm.enable_experimental_instrumentations=true -Delastic.apm.service_name=... -Delastic.apm.server_urls=... -Delastic.apm.secret_token=... -Delastic.apm.environment=test -Delastic.apm.enable_log_correlation=true -Delastic.apm.log_format_sout=json -Delastic.apm.log_sending=true

which gave me a log line correctly correlated

Note:

 :: Spring Boot ::                (v3.0.0)
2023-06-19T16:49:17.202+01:00  INFO 3716 --- [           main] com.example.springboot.Application       : Starting Application using Java 17.0.7 ...

[jackshirazi]

(obviously I need to extend to using messaging, but that's where you could help with a simple example)

[marinkton]

@jackshirazi Thanks, I appreciate your effort. As I said in my question, the controllers (rest api's) are instrumenting correctly the elastic properties in our Spring Boot and Open Liberty apps. The problem only occurs in the messaging beans for both.

We're using Artemis as a message broker.

[JonasKunz]

Maybe this is not related to spring at all but rather to jakarta.* vs jmx.* JMS namespaces? Looking at this issue, it seems like we don't support JMS in the jakarta.* namespace yet.

[marinkton]

@JonasKunz it is supported from version 1.28.0 it says in https://www.elastic.co/guide/en/apm/agent/java/current/supported-technologies-details.html.

[jackshirazi]

I think the supported tech entry may be incorrect, we did a push on the jakarta namespaces but I think we've not finished the JMS part, and it seems yours is the first bug report identifying that. I'll look at whether we can get you a snapshot to test

[marinkton]

@jackshirazi perfect thanks, any idea when jakarta.jms namespace will be supported?

[jackshirazi]

The next version in a couple of weeks if this is what is causing your issue. Please try the snapshot build (the agent snapshot jar is in the elastic-apm-agent zip file, or the -java8 one if you are using that)

[marinkton]

@jackshirazi thanks for the snapshot. I tried to include it in my project, but it seems like that the attach package is missing. I can't import co.elastic.apm.attach.ElasticApmAttacher. I've looked inside the jar and i've noticed that the attach package is missing.

This is how I added the snapshot build to my project.

`

co.elastic.apm apm-agent-attach 1.39.1 system ${project.basedir}/src/main/resources/elastic-apm-agent-1.39.1-SNAPSHOT.jar

`

[jackshirazi]

For testing could you use the javaagent option on the command line? Only the elastic-apm-agent-1.39.0.jar jar needs replacing with elastic-apm-agent-1.39.1-SNAPSHOT.jar in that case

[SylvainJuge]

Hi @marinkton , for clarification you are using the apm-agent-attach artifact in your application, and the link @jackshirazi provided was for the elastic-apm-agent artifact, the latter must be used with the -javaagent option.

So here you should either:

• download the large "build" archive from our CI and extract the apm-agent-attach-1.39.1-SNAPSHOT.jar from it and replace the <systemPath> value with this file path.
• use the -javaagent setup option with the elastic-apm-agent-1.39.1-SNAPSHOT.jar downloaded previously

[marinkton]

@SylvainJuge @jackshirazi unfortunately the snapshot does not work. I've used the --javaagent setup.

The startup logs : The logs are showing that I'm using your snapshot version correctly:

{"@timestamp":"2023-06-26T10:25:01.209Z","log.level": "WARN","message":"This is a pre-release snapshot version, usage in production is not recommended unless instructed otherwise.", "ecs.version": "1.2.0","event.dataset":"apm-logging.apm-agent","process.thread.name":"main","log.logger":"co.elastic.apm.agent.configuration.StartupInfo"} {"@timestamp":"2023-06-26T10:25:01.209Z","log.level": "INFO","message":"Starting Elastic APM 1.39.1-SNAPSHOT.6d79d01 as apm-logging on Java 17.0.7 Runtime version: 17.0.7+7 VM version: openj9-0.38.0 (IBM Corporation) Linux 4.18.0-372.32.1.el8_6.x86_64", "ecs.version": "1.2.0","event.dataset":"apm-logging.apm-agent","process.thread.name":"main","log.logger":"co.elastic.apm.agent.configuration.StartupInfo"}

But the elastic props are still empty in the messaging beans (I've used a open liberty service to test this).

{"message":"Bericht is succesvol geplaatst op logging-acties","ibm_datetime":"2023-06-26T12:26:44.276+0200","log.logger":"nl.test.jms.DADActiveMQDestination","log.level":"INFO","log.origin.function":"enqueue","ibm_className":"nl.test.jms.DADActiveMQDestination","transaction.id":"","trace.id":"","@timestamp":"2023-06-26T10:26:44.277546591Z","ext_appName":"logging-service","span.id":"","process.thread.name":"Thread-1 (ActiveMQ-client-global-threads)"}

[SylvainJuge]

In this case if you could provide a very simple app that helps to reproduce the problem that would really be helpful.

From what I understand:

• the transactions are properly created on the HTTP endpoint.
• you have some "messaging beans" that should be triggered when they handle a message from JMS.

What we need to know:

• does your application sends messages to JMS from the HTTP request handling or does the application also handles incoming messages through JMS ?
• how are those JSON logs created? are you using ecs-logging-java or the agent built-in reformatting feature ? The weird thing here is that we have empty valies for transaction.id and trace.id and I'm pretty sure the java agent does not set such empty values.

[marinkton]

@SylvainJuge the application handles incoming messages through JMS. We have multiple services in Open liberty and Spring Boot. Everything was working fine before the Java 17 and Jakarta namespace upgrade.

For spring boot we're using the dependency:

`

co.elastic.logging log4j2-ecs-layout ${co.elastic.logging.log4j2-ecs-layout-version}

`

and for open liberty we have a custom method for setting up the logging:

`

protected void setupLogging() {

    LogRecordContext.unregisterExtension(TIMESTAMP);
    LogRecordContext.unregisterExtension(TRACE_ID);
    LogRecordContext.unregisterExtension(TRANSACTION_ID);
    LogRecordContext.unregisterExtension(SPAN_ID);

    LogRecordContext.registerExtension(TIMESTAMP, () ->    
    ZonedDateTime.now(ZoneOffset.UTC).format(DateTimeFormatter.ISO_INSTANT));
    LogRecordContext.registerExtension(TRACE_ID, () -> ElasticApm.currentTransaction().getTraceId());
    LogRecordContext.registerExtension(TRANSACTION_ID, () -> ElasticApm.currentTransaction().getId());
    LogRecordContext.registerExtension(SPAN_ID, () -> ElasticApm.currentSpan().getId());

    initialized = true;
}

`

The transactions are properly created on the HTTP endpoint indeed, but the messagings beans are not created properly. This problem occurs in both frameworks (Spring and Open Liberty).

I'll try to provide an example today or tomorrow.

[SylvainJuge]

Thanks ! That explains the empty transaction_id fields in the JSON logs. We don't provide a dedicated instrumentation for OpenLiberty, but the setupLogging does an equivalent job here when the logs as written in JSON.

[LeaTaka]

Hi there, same problem here. I would like to contribute with my experience on the issue 👇

Tested;

• ecs-console-appender in logback-spring.xml*
• ELASTIC_APM_LOG_ECS_REFORMATTING* enabled instead of logback
• apm-agent version 1.36, 1.38 and 1.39
• Receiving a message from ibm MQ server with the DefaultJmsListenerContainerFactory

Results:

• No correlation id’s are injected jms listener related logback logging
• Correlation id’s are injected for normal api requests

*Please find attached the example project I used for testing. Also have a look at the example folder for the used configurations in the attached jms-logcorrelation-example-project.zip

[SylvainJuge]

Hi @LeaTaka and @marinkton , we have fixed a few issues in the PR that adds support for Jakarta namespace.

Could you try with this snapshot of the Java agent and see if that now works as expected ?

Thanks to the sample application provided by @LeaTaka I've managed to reproduce the issues locally which really helped a lot. There are still few test failures to investigate in the PR, but that's only due to unit-testing.

[LeaTaka]

First results testing with your snapshot;

1. using @JmsListener ✅
2. requested a normal rest api ✅
3. checking log-correlation in Kibana ✅

App-3 logging >>

`{"@timestamp":"2023-06-29T09:43:02.004Z","log.level": "INFO","message":"Received message is: \n JMSMessage class: jms_text\n JMSType: null\n JMSDeliveryMode: 2\n JMSDeliveryDelay: 0\n JMSDeliveryTime: 0\n JMSExpiration: 0\n JMSPriority: 4\n JMSMessageID: ID:414d51204d514d534f30352020202020645e84ef21a79402\n JMSTimestamp: 1688031781981\n JMSCorrelationID: null\n JMSDestination: queue:///DEV.SDS.02.LQ02\n JMSReplyTo: null\n JMSRedelivered: false\n JMSXAppID: /app/apm-java.jar \n JMSXDeliveryCount: 1\n JMSXUserID: mqsrtp01 \n JMS_IBM_Character_Set: UTF-8\n JMS_IBM_Encoding: 273\n JMS_IBM_Format: MQSTR \n JMS_IBM_MsgType: 8\n JMS_IBM_PutApplType: 28\n JMS_IBM_PutDate: 20230629\n JMS_IBM_PutTime: 09430199\n elastic_apm_traceparent: 00-1b751e269027419c5d29d1f34a4bb110-94ad8ee90009fc92-01\n traceparent: 00-1b751e269027419c5d29d1f34a4bb110-94ad8ee90009fc92-01\n tracestate: es=s:1\nListener - Message from App2: f673bbe2-67dd-4d54-a516-c059c91ee8a6","ecs.version": "1.2.0","service.name":"app-3-java","service.version":"0.0.1-SNAPSHOT","service.environment":"npo","event.dataset":"app-3-java.CONSOLE","process.thread.name":"org.springframework.jms.JmsListenerEndpointContainer#0-1","log.logger":"nl.xxx.healthcheck.poc.api.MyController","transaction.id":"414e81172c54699e","trace.id":"1b751e269027419c5d29d1f34a4bb110"}

{"@timestamp":"2023-06-29T09:44:02.949Z","log.level": "INFO","message":"Getting info from app4","ecs.version": "1.2.0","service.name":"app-3-java","service.version":"0.0.1-SNAPSHOT","service.environment":"npo","event.dataset":"app-3-java.CONSOLE","process.thread.name":"http-nio-8080-exec-6","log.logger":"nl.xxx.healthcheck.poc.api.MyController","transaction.id":"ce69bdfbf3b9cdb2","trace.id":"52616fc9f61319d5d638ff0dde9cfe6c"}

{"@timestamp":"2023-06-29T09:44:03.007Z","log.level": "INFO","message":"Getting info from app5","ecs.version": "1.2.0","service.name":"app-3-java","service.version":"0.0.1-SNAPSHOT","service.environment":"npo","event.dataset":"app-3-java.CONSOLE","process.thread.name":"http-nio-8080-exec-6","log.logger":"nl.xxx.healthcheck.poc.api.MyController","transaction.id":"ce69bdfbf3b9cdb2","trace.id":"52616fc9f61319d5d638ff0dde9cfe6c"}`

Kibana >>

[LeaTaka]

Seems to be working, excellent work! Please let me know when you plan to release the final fix.

[SylvainJuge]

Hi @LeaTaka you can subscribe to the notifications to know when #3198 is merged and when a new release is available.

[LeaTaka]

@SylvainJuge Heads-up: I could be wrong but it seems that elastic-apm-agent-1.39.1-SNAPSHOT.jar impacts ELASTIC_APM_LOG_SENDING.

[SylvainJuge]

Hi @LeaTaka , could you elaborate a bit on how it impacts log sending ?

• The log sending feature is quite isolated from the JMS instrumentation (which this is issue is about).
• Did it used to work in a way previously and now behaves differently now that the JMS is properly instrumented ? If yes could you clarify the differences ?

[SylvainJuge]

@LeaTaka I've tested the log sending locally and its working as expected on my side, could you try it with the latest release 1.39.0 and see if you have something in the "Observability > Logs > Log Stream" view in Kibana ? (here you might miss the trace correlation, but it should still be part of the global log stream, or even the per-service stream). If you still experience any issue here I would suggest we discuss this further in the forum or by creating another bug report as it seems to be a separate issue from the JMS support this issue is about.

[LeaTaka]

Cool @SylvainJuge. When I come across smt related, I will file a separate bug report. For now I do not have much time left to do further testing, so I leave it there. I might have seen it wrong.

Anyways good that you have it covered! Cheers 👌

[marinkton]

@jackshirazi@SylvainJuge,

Could you please reopen this bug issue? I wasn't available for the past two weeks, but now I'm back. We've tested the new snapshot version and it works well with Spring Boot, but unfortunately, we're encountering issues with open liberty. You can download the project from this link .

By the way, you can ignore the dockerfile in the project.

To build the project, simply run mvn clean install, and to run it, use mvn liberty:dev. If needed, you can modify the property values in liberty/config/server.env.

Thanks in advance!

[jackshirazi]

Please try with the just released 1.40.0. If it works with Spring but not open liberty it's a different bug - so in that case please open a separate issue