Support for ELASTIC_APM_ENABLE_LOG_CORRELATION - log4j2

[adrianj]

Hi - this is pretty much a duplicate of a similar issue in the mule3-agent. https://github.com/michaelhyatt/elastic-apm-mule3-agent/issues/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]

@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]

@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]

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]

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]

Could it be the AsyncLogger? If not, it may require extending the log4j:

Log4j 2.7 adds a flexible mechanism to tag logging statements with context
data coming from other sources than the ThreadContext. See the manual page
on extending Log4j
<https://logging.apache.org/log4j/2.x/manual/extending.html#Custom_ContextDataInjector>
for
details.

If there was only a way to log the trace.id value in the payload of the message, the Logs UI in Kibana would pick it up, since the search string it is using is trace.id : "XXX" OR "XXX" which caters for trace.id logged in the message field of the logged event.

On Mon, 31 Aug 2020 at 12:03, Adrian Jongenelen [email protected] wrote:

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.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/michaelhyatt/elastic-apm-mule4-agent/issues/6#issuecomment-683512736, or unsubscribe https://github.com/notifications/unsubscribe-auth/ADXR5DOCR2CO32ZOIEU43MDSDMAGDANCNFSM4OSMCKRQ .