Thread locals not set when handling exceptions in DataFetcherExceptionHandler

[shivani15]

hi,

We are using Hooks.enableAutomaticContextPropagation() for automatic propagation of the context and setting the MDC values in thread locals on context switch.

But unfortunately when any exception is thrown from our application code and we try to handle (prepare response + logging) these exceptions in our custom class implementing from DataFetcherExceptionHandler we find that the MDC values are not populated.

Although the reactor context is available in the DataFetcherExceptionHandler but the thread locals are not set. Could someone please help me resolve the issue. Sharing some code segments from our project:

public class RequestContextWebFilter implements WebFilter, Ordered {

  private final int order;

  public RequestContextWebFilter(final int order) {
    this.order = order;
  }

  @PostConstruct
  public void init() {
    Hooks.enableAutomaticContextPropagation();
    ContextRegistry.getInstance().registerThreadLocalAccessor(
        new Slf4jThreadLocalAccessor()
    );
  }

  @Override
  public Mono<Void> filter(@NonNull final ServerWebExchange exchange, @NonNull final WebFilterChain chain) {
    final Map<String, String> mdcMap = new HashMap<>();
    mdcMap.put("REQUEST_ID", asrContext.getRequestId());

    // The custom map(mdcMap) is added to the reactive context with a key(MDC_KEY) so that it can be accessed by
    // context-propagation library, resulting in MDC population in the downstream reactive chains
    return chain.filter(exchange).contextWrite(Context.of(Slf4jThreadLocalAccessor.KEY, mdcMap));
  }

  @Override
  public int getOrder() {
    return order;
  }
}

@DgsData(parentType = RECENTSLIST.TYPE_NAME, field = RECENTSLIST.AssetListConnection)
  public Mono<DataFetcherResult<AssetListConnection>> getAssetChildConnection(
      @InputArgument(name = RECENTSLIST.ASSETLISTCONNECTION_INPUT_ARGUMENT.Filter) AssetListFilter filter,
      ...) {
     <some application logic which throws some exceptions >
}

@Component
@Slf4j
public class ExceptionHandler implements DataFetcherExceptionHandler {
  //private static final Logger LOGGER = LoggerFactory.getLogger(ExceptionHandler.class);

  @Override
  public CompletableFuture<DataFetcherExceptionHandlerResult> handleException(
      DataFetcherExceptionHandlerParameters handlerParameters) {
         // trying to log exceptions but MDC.getCopyOfContextMap() is null
   }
}

[jonatan-ivanov]

Which version of Boot this is? If not the latest, could you please upgrade in the first place please, there were a lot of fixes between 3.0.0 and the latest version.

Hooks.enableAutomaticContextPropagation() should be in the first line of your main method to make sure things work properly (btw there is now a property for this in Boot).

Also, why do you need to register Slf4jThreadLocalAccessor? I thought it is already registered by Boot, aren't you using Microimeter Tracing? If so, your contextWrite might conflict with other logic since they use the same key.

Not sure about your ExceptionHandler (this might be webflux-related too), what happens if you remove your custom context writing logic and also remove registering Slf4jThreadLocalAccessor and you use Micrometer Tracing, will you see the traceId in the MDC?

/cc @chemicL

[shivani15]

We are using springboot 3.2.4 and we are using

<micrometer-context-propagation.version>1.1.3</micrometer-context-propagation.version>
<projectreactor-reactor-core.version>3.7.5</projectreactor-reactor-core.version>
<micrometer-core>1.14.6</micrometer-core>

I tried to add Hooks.enableAutomaticContextPropagation() in @PostConstruct method of both Application.java and RequestContextWebFilter.

We are not using Micrometer Tracing as we need to have some custom context for each request like requestId generated within our system. And hence we are using Slf4jThreadLocalAccessor.

you use Micrometer Tracing, will you see the traceId in the MDC

This might be a big change and is not currently needed by us.

Not sure about your ExceptionHandler (this might be webflux-related too)

What do you mean by this ?

[jonatan-ivanov]

Could you please only define the Boot BOM version and let it set the version numbers? Right now you are defining all version on your own, please let Spring Boot use the versions it wants to.
Also, Spring Boot 3.2.x is out of OSS support, you should upgrade: https://spring.io/projects/spring-boot#support

Not sure about your ExceptionHandler (this might be webflux-related too)

What do you mean by this ?

I was wondering if this is an issue in webflux or not.

[shivani15]

hi, I tried to updating to Spring Boot 3.4.4 as well.
I have also removed the version number for above mentioned dependencies <projectreactor-reactor-core.version>3.7.5</projectreactor-reactor-core.version> as there were some conflicts in version due to multiple exported packages.

Even after the above changes it doesn't seem to work.

ExceptionHandler extends DataFetcherExceptionHandler which is part of graphql-java 20.3 package.

[chemicL]

Although the reactor context is available in the DataFetcherExceptionHandler

What do you mean by this? Looking at the DataFetcherExceptionHandler, it's just an interface that has nothing to do with reactive chains. So where do you see the Reactor Context? It might (might as well not, depending on how it's exercised) be a limitation of the exception handler's design in the graphql-java project that it's not part of a reactive pipeline and the code in the ExceptionHandler#handleException is executed on a non-context-propagated Thread. Can you try to print the Thread that's executing your code? Also, the stack trace so we know what's calling into it an why it's not propagating the MDC content.

[shivani15]

It is also a part of reactive chains. DataFetcherExceptionHandler#handleException give DataFetcherExceptionHandlerParameters which has DataFetchingEnvironment->GraphQLContext which contains/stores the reactor context.

I also tried to debug it a little the below line from the stacktrace resets the thread locals and sets it as null:

onError:127, MonoContextWriteRestoringThreadLocals$ContextWriteRestoringThreadLocalsSubscriber (reactor.core.publisher)

Following is the stack trace for the same:

getDataFetcherExceptionHandlerResult:160, ExceptionHandler (xxx)
handleCLSException:109, ExceptionHandler (xxx)
handleException:82, ExceptionHandler (xxxx)
asyncHandleException:375, ExecutionStrategy (graphql.execution)
handleFetchingException:363, ExecutionStrategy (graphql.execution)
lambda$fetchField$5:293, ExecutionStrategy (graphql.execution)
apply:-1, ExecutionStrategy$$Lambda$2401/0x000000b001bb5af0 (graphql.execution)
uniHandle:934, CompletableFuture (java.util.concurrent)
tryFire:911, CompletableFuture$UniHandle (java.util.concurrent)
postComplete:510, CompletableFuture (java.util.concurrent)
completeExceptionally:2162, CompletableFuture (java.util.concurrent)
onError:77, MonoToCompletableFuture (reactor.core.publisher)
onError:127, MonoContextWriteRestoringThreadLocals$ContextWriteRestoringThreadLocalsSubscriber (reactor.core.publisher)
onError:127, MonoContextWriteRestoringThreadLocals$ContextWriteRestoringThreadLocalsSubscriber (reactor.core.publisher)
onError:134, FluxMap$MapSubscriber (reactor.core.publisher)
onError:2236, Operators$MultiSubscriptionSubscriber (reactor.core.publisher)
onError:180, MonoFlatMap$FlatMapMain (reactor.core.publisher)
onError:2236, Operators$MultiSubscriptionSubscriber (reactor.core.publisher)
onError:142, FluxMapFuseable$MapFuseableSubscriber (reactor.core.publisher)
onError:180, MonoFlatMap$FlatMapMain (reactor.core.publisher)
onError:108, MonoCollectList$MonoCollectListSubscriber (reactor.core.publisher)
onError:140, FluxExpand$ExpandBreathSubscriber (reactor.core.publisher)
onError:106, FluxOnErrorResume$ResumeSubscriber (reactor.core.publisher)
error:198, Operators (reactor.core.publisher)
subscribe:53, MonoError (reactor.core.publisher)
subscribe:4568, Mono (reactor.core.publisher)
onError:103, FluxOnErrorResume$ResumeSubscriber (reactor.core.publisher)
secondError:241, MonoFlatMap$FlatMapMain (reactor.core.publisher)
onError:315, MonoFlatMap$FlatMapInner (reactor.core.publisher)
onError:142, FluxMapFuseable$MapFuseableSubscriber (reactor.core.publisher)
onError:108, MonoCollectList$MonoCollectListSubscriber (reactor.core.publisher)
drain:403, FluxMergeSequential$MergeSequentialMain (reactor.core.publisher)
innerError:321, FluxMergeSequential$MergeSequentialMain (reactor.core.publisher)
onError:586, FluxMergeSequential$MergeSequentialInner (reactor.core.publisher)
onError:134, FluxMap$MapSubscriber (reactor.core.publisher)
onError:106, FluxOnErrorResume$ResumeSubscriber (reactor.core.publisher)
error:198, Operators (reactor.core.publisher)
subscribe:53, MonoError (reactor.core.publisher)
subscribe:4568, Mono (reactor.core.publisher)
onError:103, FluxOnErrorResume$ResumeSubscriber (reactor.core.publisher)
onError:234, FluxPeekFuseable$PeekFuseableSubscriber (reactor.core.publisher)
onError:258, MonoPeekTerminal$MonoTerminalPeekSubscriber (reactor.core.publisher)
onError:265, FluxMap$MapConditionalSubscriber (reactor.core.publisher)
onError:553, FluxPeekFuseable$PeekFuseableConditionalSubscriber (reactor.core.publisher)
onError:258, MonoPeekTerminal$MonoTerminalPeekSubscriber (reactor.core.publisher)
onError:180, MonoFlatMap$FlatMapMain (reactor.core.publisher)
secondError:241, MonoFlatMap$FlatMapMain (reactor.core.publisher)
onError:315, MonoFlatMap$FlatMapInner (reactor.core.publisher)
onError:134, FluxMap$MapSubscriber (reactor.core.publisher)
onError:156, FluxDefaultIfEmpty$DefaultIfEmptySubscriber (reactor.core.publisher)
onError:2236, Operators$MultiSubscriptionSubscriber (reactor.core.publisher)
onError:544, FluxOnAssembly$OnAssemblySubscriber (reactor.core.publisher)
onError:180, MonoFlatMap$FlatMapMain (reactor.core.publisher)
onError:106, FluxOnErrorResume$ResumeSubscriber (reactor.core.publisher)
onError:280, MonoIgnoreThen$ThenIgnoreMain (reactor.core.publisher)
subscribeNext:232, MonoIgnoreThen$ThenIgnoreMain (reactor.core.publisher)
onComplete:204, MonoIgnoreThen$ThenIgnoreMain (reactor.core.publisher)
onComplete:169, FluxOnErrorReturn$ReturnSubscriber (reactor.core.publisher)
onComplete:89, MonoIgnoreElements$IgnoreElementsSubscriber (reactor.core.publisher)
onComplete:152, FluxMapFuseable$MapFuseableSubscriber (reactor.core.publisher)
onComplete:549, FluxOnAssembly$OnAssemblySubscriber (reactor.core.publisher)
onComplete:144, FluxMap$MapSubscriber (reactor.core.publisher)
onComplete:260, FluxPeek$PeekSubscriber (reactor.core.publisher)
onComplete:149, FluxContextWriteRestoringThreadLocals$ContextWriteRestoringThreadLocalsSubscriber (reactor.core.publisher)
onComplete:275, FluxMap$MapConditionalSubscriber (reactor.core.publisher)
onComplete:149, FluxContextWriteRestoringThreadLocals$ContextWriteRestoringThreadLocalsSubscriber (reactor.core.publisher)
complete:137, Operators (reactor.core.publisher)
startReceiver:181, FluxReceive (reactor.netty.channel)
subscribe:147, FluxReceive (reactor.netty.channel)
subscribe:46, FluxContextWriteRestoringThreadLocals (reactor.core.publisher)
subscribe:68, InternalFluxOperator (reactor.core.publisher)
subscribe:340, ByteBufFlux (reactor.netty)
subscribe:4568, Mono (reactor.core.publisher)
subscribeNext:265, MonoIgnoreThen$ThenIgnoreMain (reactor.core.publisher)
subscribe:51, MonoIgnoreThen (reactor.core.publisher)
subscribe:4568, Mono (reactor.core.publisher)
onError:103, FluxOnErrorResume$ResumeSubscriber (reactor.core.publisher)
onError:180, MonoFlatMap$FlatMapMain (reactor.core.publisher)
onNext:149, MonoFlatMap$FlatMapMain (reactor.core.publisher)
onNext:74, FluxSwitchIfEmpty$SwitchIfEmptySubscriber (reactor.core.publisher)
onNext:539, FluxOnAssembly$OnAssemblySubscriber (reactor.core.publisher)
onNext:122, FluxMap$MapSubscriber (reactor.core.publisher)
onNext:110, MonoContextWriteRestoringThreadLocals$ContextWriteRestoringThreadLocalsSubscriber (reactor.core.publisher)
onNext:129, FluxMapFuseable$MapFuseableSubscriber (reactor.core.publisher)
onNext:118, FluxFilterFuseable$FilterFuseableSubscriber (reactor.core.publisher)
completePossiblyEmpty:2097, Operators$BaseFluxToMonoOperator (reactor.core.publisher)
onComplete:145, MonoCollect$CollectSubscriber (reactor.core.publisher)
onComplete:144, FluxMap$MapSubscriber (reactor.core.publisher)
onComplete:260, FluxPeek$PeekSubscriber (reactor.core.publisher)
onComplete:149, FluxContextWriteRestoringThreadLocals$ContextWriteRestoringThreadLocalsSubscriber (reactor.core.publisher)
onComplete:275, FluxMap$MapConditionalSubscriber (reactor.core.publisher)
onComplete:149, FluxContextWriteRestoringThreadLocals$ContextWriteRestoringThreadLocalsSubscriber (reactor.core.publisher)
onInboundComplete:415, FluxReceive (reactor.netty.channel)
onInboundComplete:446, ChannelOperations (reactor.netty.channel)
terminate:500, ChannelOperations (reactor.netty.channel)
onInboundNext:793, HttpClientOperations (reactor.netty.http.client)
channelRead:114, ChannelOperationsHandler (reactor.netty.channel)
invokeChannelRead:444, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:420, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:412, AbstractChannelHandlerContext (io.netty.channel)
channelRead:289, IdleStateHandler (io.netty.handler.timeout)
invokeChannelRead:442, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:420, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:412, AbstractChannelHandlerContext (io.netty.channel)
channelRead:289, IdleStateHandler (io.netty.handler.timeout)
invokeChannelRead:442, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:420, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:412, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:436, CombinedChannelDuplexHandler$DelegatingChannelHandlerContext (io.netty.channel)
fireChannelRead:346, ByteToMessageDecoder (io.netty.handler.codec)
channelRead:318, ByteToMessageDecoder (io.netty.handler.codec)
channelRead:251, CombinedChannelDuplexHandler (io.netty.channel)
invokeChannelRead:442, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:420, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:412, AbstractChannelHandlerContext (io.netty.channel)
unwrap:1475, SslHandler (io.netty.handler.ssl)
decodeNonJdkCompatible:1349, SslHandler (io.netty.handler.ssl)
decode:1389, SslHandler (io.netty.handler.ssl)
decodeRemovalReentryProtection:529, ByteToMessageDecoder (io.netty.handler.codec)
callDecode:468, ByteToMessageDecoder (io.netty.handler.codec)
channelRead:290, ByteToMessageDecoder (io.netty.handler.codec)
invokeChannelRead:444, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:420, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:412, AbstractChannelHandlerContext (io.netty.channel)
channelRead:1410, DefaultChannelPipeline$HeadContext (io.netty.channel)
invokeChannelRead:440, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:420, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:919, DefaultChannelPipeline (io.netty.channel)
read:166, AbstractNioByteChannel$NioByteUnsafe (io.netty.channel.nio)
processSelectedKey:788, NioEventLoop (io.netty.channel.nio)
processSelectedKeysOptimized:724, NioEventLoop (io.netty.channel.nio)
processSelectedKeys:650, NioEventLoop (io.netty.channel.nio)
run:562, NioEventLoop (io.netty.channel.nio)
run:997, SingleThreadEventExecutor$4 (io.netty.util.concurrent)
run:74, ThreadExecutorMap$2 (io.netty.util.internal)
run:30, FastThreadLocalRunnable (io.netty.util.concurrent)
run:842, Thread (java.lang)