log4j2: AWSRequestId set in ThreadContext map, incorrect for multithreaded applications

[jhovell]

If I include a %X in my pattern layout, I see that the following appears in my log output

... { AWSRequestId=4e145840-092b-11e8-a601-a9957c1b507d}...

I don't see anything in this library that sets ThreadContext, so I am unsure if this is somehow being set by the Lambda runtime or by some other log4j2 mechanism I am not aware of.

While this value appears to be correct in the main thread, I have noticed that other threads such as in a fork join pool will have this value populated, but often incorrectly (in the case of container re-use, it will retain the value of a previous invocation/request Id). Usually some of the threads have correct IDs while others have stale/old/incorrect IDs: I think the behavior is the request ID is set once the first time the thread is used in a container, but after the thread has been spawned the request ID in the child threads never get updated again, so they retain the request ID of whatever invocation was the first to use/spawn that particular thread.

What library/entity owns setting this request ID and how can I get this to be correct for multi-threaded applications?

[jhovell]

This can be fairly easily reproduced by including the following in your event handler class and then performing some asynchronous work via CompleteableFuture.supplyAsync or similar.

    static {
        // Set parallelism to 4 to get extra threads in the common pool
        System.setProperty("java.util.concurrent.ForkJoinPool.common.parallelism", "4");
    }

[jhovell]

Turns out this is because I had set

System.setProperty("isThreadContextMapInheritable", "true");

as well. Removing this means any child threads have no context information and AWSRequestId is blank.

Given Lambda by design will only ever be serving a single request at a time, wouldn't it be better to configure log4j2 to clone/propagate context to all threads during a given lambda execution? I was hoping log4j2 would have some way to globally set context having nothing to do with threads but not sure this is possible.

[jhovell]

I ended up writing a custom log4j2 ContextDataInjector and corresponding context that propagates context data for all threads. Not sure if this is something that should be included with this log4j lambda library, since for serverless applications context likely applies to all threads since at least if the context corresponds to the lambda request the context is essentially global (a lambda and the underlying JVM only services a single request at a time).

[codefromthecrypt]

I suppose the request id part would be global, but you can start a subsegment, so whatever reflects the current segment ID would be potentially scoped finer than the process

[jhovell]

@adriancole are you talking about X-Ray and do you mean Trace ID?

[codefromthecrypt]

Sorry yes that is what I mean. The Root part will be the same, but for example Parent if in a log context will be about the incoming trace context even if the current span ID has changed. Different topic, but figured I would mention

…

On 7 Feb 2018 5:51 pm, "jhovell" ***@***.***> wrote: @adriancole <https://github.com/adriancole> are you talking about X-Ray and do you mean Trace ID? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#40 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAD6190HHmhHrbi9iAkeWtR4A4k2lKdoks5tSdSngaJpZM4R4WKb> .

[asuresh8]

There's a reason the class is called ThreadContext, i.e. Log4j intends one context per thread.

Out of curiosity, why are you running a thread pool in your Lambda function? Why not run multiple Lambda functions concurrently?

[jhovell]

@asuresh8 For IO-blocked operations like making synchronous REST API calls to other services. Why pay for other lambdas that are just sitting idle waiting to get a payload back? Seems this a pretty common pattern in Lambda, especially in Node with callbacks & the event loop, no? I was basically trying to do the same thing I would do in a Node Lambda where several non-dependent API calls need to be made, and their results combined/transformed in some way.

[jhovell]

By the way, I ended up solving this problem by creating a CloseableGlobalContext (similar to CloseableThreadContext) class and a custom implementation of ContextDataInjector, call it GlobalLambdaContextDataInjector. I think this extensibility is fairly well documented in log4j2 and fits my use case. Would be happy to create a PR if this functionality would seem useful for other folks using log4j2 and Lambda.

This is then all activated by adding this in a class that gets loaded when your lambda is executed such as the handler class:

    static {
        System.setProperty("log4j2.ContextDataInjector", "com.mycompany.GlobalLambdaContextDataInjector");
    }

The result is that all threads get the logging context I want (AWS X-Ray trace info, Lambda Request ID) plus any other custom context elements I added

[rkuhlercadent]

I'm having the same problem. It's really helpful to use the lambda request ID to filter in Cloudwatch Logs to view all the logs from a single request. However, we use multi-threading in our lambda functions as well. Because %X{AWSRequestId} does not get substituted properly in child thread log entries, we can't find all the relevant log information.

It would be great if @jhovell could put up a pull request for his solution or someone from AWS could address this.

[jhovell]

Just curious if there was a reason why this issue was closed?

[msailes]

Sorry @jhovell my mistake, I thought you'd happily resolved this yourself. Yes if you would like to submit a PR we'd be more than happy to look at it.

[jhovell]

That probably wouldn't be too hard, sure.