michaelhyatt/elastic-apm-mule4-agent

Support for ELASTIC_APM_ENABLE_LOG_CORRELATION - log4j2

adrianj opened this issue · 5 comments

adrianj commented

Hi - this is pretty much a duplicate of a similar issue in the mule3-agent.
michaelhyatt/elastic-apm-mule3-agent#24

Regardless of if I have ELASTIC_APM_ENABLE_LOG_CORRELATION=true, the %X{trace.id} and %X{transaction.id} are always empty. The %X{correlationId} does work.

Mule Kernel 4.2.0
AdoptOpenJDK 1.8
mule4-agent 0.0.2
mule-apikit-module 1.3.3

michaelhyatt commented

@adrianj I created a new release that populates MDC with trace.id and transaction.id, please give it a go:

https://github.com/michaelhyatt/elastic-apm-mule4-agent/releases/tag/v0.0.3

adrianj commented

@michaelhyatt sorry I just saw this comment, I'm not accustomed to checking my Github notifications.

I will test it out in the next few days and let you know how it goes 👍

adrianj commented

Hello,
Sorry it has taken me so long. I have come back around to testing version 0.0.3.
Alas, it is still not working for me.

mule kernel log:

**********************************************************************
* Started app                                                        *
* 'mule4.template.project.api-1.0.0-SNAPSHOT-mule-application'       *
* Application plugins:                                               *
*  - Sockets : 1.1.5                                                 *
*  - HTTP : 1.5.3                                                    *
*  - APIKit : 1.3.3                                                  *
* Application libraries:                                             *
*  - apm-agent-attach-1.17.0.jar                                     *
*  - jna-5.3.1.jar                                                   *
*  - jna-platform-5.3.1.jar                                          *
*  - apm-agent-api-1.17.0.jar                                        *
*  - mule4-agent-0.0.3.jar                                           *
**********************************************************************

log4j2.xml

<PatternLayout pattern="%d [%t] %-5p %c - %X{trace.id} %X{transaction.id} CorrelationID=%X{correlationId}, Message=%m%n" />

mule4.template.application.log - trace.id and transaction.id appear as empty strings.

2020-08-31 11:33:14,117 [[MuleRuntime].cpuLight.15: [mule4.template.project.api-1.0.0-SNAPSHOT-mule-application].post:\request:application\json:api-config.CPU_LITE @4dbe76a0] INFO  org.mule.runtime.core.internal.processor.LoggerMessageProcessor -   CorrelationID=e09e847b-b605-4f16-86b0-971698076fcd, Message={"Name":"name","Address":"address"}
adrianj commented

After digging a little deeper and attaching a debugger, I'm finding this behaviour:

  1. The MDC.put is being called for trace.id and transaction.id
  2. Looking at org.apache.logging.log4j.ThreadContext class, the correlationId is put many times within the flow, whereas trace.id is only put once.
  3. On the MDC.remove, the trace.id and transaction.id aren't there anymore, though the correlationId is.

Possibly the thread that put the ids is a different thread to the mule logger component, and different to the thread that ends the transaction.

system property log4j2.isThreadContextMapInheritable=true does not seem to make any difference.

michaelhyatt commented