Class cast exception obtaining `Observation` context on `abortTransaction` completion

[worldtiki]

When using transactions, the MongoObservationCommandListener.commandSucceeded() is executed twice.

The 1st time, it tries to cast the observation context to a MongoHandlerContext (and succeeds), but the 2nd time, which is executed in the context of the commit of the transaction, this cast fails with an exception

java.lang.ClassCastException: class org.springframework.http.server.observation.ServerRequestObservationContext cannot be cast to class org.springframework.data.mongodb.observability.MongoHandlerContext

This seems to be on purpose, at least according to this comment, which is what causes the MongoHandlerContext to never be created.

Should there be a bit of defensive code to avoid force casting the context into a MongoHandlerContext?

[mp911de]

If you would like us to spend some time helping you to diagnose the problem, please spend some time describing it and, ideally, providing a minimal yet complete sample that reproduces the problem.
You can share it with us by pushing it to a separate repository on GitHub or by zipping it up and attaching it to this issue. We need to have the stack trace as well.

[worldtiki]

Of course.

The stack trace:

2023-08-23T15:37:15.613+01:00  WARN 30853 --- [o-auto-1-exec-1] org.mongodb.driver.protocol.event        : Exception thrown raising command succeeded event to listener org.springframework.data.mongodb.observability.MongoObservationCommandListener@4a5fab78

java.lang.ClassCastException: class org.springframework.http.server.observation.ServerRequestObservationContext cannot be cast to class org.springframework.data.mongodb.observability.MongoHandlerContext (org.springframework.http.server.observation.ServerRequestObservationContext and org.springframework.data.mongodb.observability.MongoHandlerContext are in unnamed module of loader 'app')
        at org.springframework.data.mongodb.observability.MongoObservationCommandListener.commandSucceeded(MongoObservationCommandListener.java:140) ~[spring-data-mongodb-4.1.2.jar:4.1.2]
        at com.mongodb.internal.event.CommandListenerMulticaster.commandSucceeded(CommandListenerMulticaster.java:60) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.connection.ProtocolHelper.sendCommandSucceededEvent(ProtocolHelper.java:296) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.connection.LoggingCommandEventSender.sendSucceededEvent(LoggingCommandEventSender.java:170) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.connection.LoggingCommandEventSender.sendSucceededEvent(LoggingCommandEventSender.java:140) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:448) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:365) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:114) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:643) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:73) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:204) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:122) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:87) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:76) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.connection.DefaultServer$OperationCountTrackingConnection.command(DefaultServer.java:288) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.operation.CommandOperationHelper.lambda$executeRetryableWrite$15(CommandOperationHelper.java:423) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.operation.OperationHelper.lambda$withSourceAndConnection$0(OperationHelper.java:358) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.operation.OperationHelper.withSuppliedResource(OperationHelper.java:383) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.operation.OperationHelper.lambda$withSourceAndConnection$1(OperationHelper.java:357) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.operation.OperationHelper.withSuppliedResource(OperationHelper.java:383) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.operation.OperationHelper.withSourceAndConnection(OperationHelper.java:356) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.operation.CommandOperationHelper.lambda$executeRetryableWrite$16(CommandOperationHelper.java:407) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.async.function.RetryingSyncSupplier.get(RetryingSyncSupplier.java:67) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.operation.CommandOperationHelper.executeRetryableWrite(CommandOperationHelper.java:435) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.operation.TransactionOperation.execute(TransactionOperation.java:58) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.operation.CommitTransactionOperation.execute(CommitTransactionOperation.java:94) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.internal.operation.CommitTransactionOperation.execute(CommitTransactionOperation.java:52) ~[mongodb-driver-core-4.9.1.jar:na]
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:206) ~[mongodb-driver-sync-4.9.1.jar:na]
        at com.mongodb.client.internal.ClientSessionImpl.commitTransaction(ClientSessionImpl.java:148) ~[mongodb-driver-sync-4.9.1.jar:na]
        at org.springframework.data.mongodb.MongoTransactionManager$MongoTransactionObject.commitTransaction(MongoTransactionManager.java:425) ~[spring-data-mongodb-4.1.2.jar:4.1.2]
        at org.springframework.data.mongodb.MongoTransactionManager.doCommit(MongoTransactionManager.java:212) ~[spring-data-mongodb-4.1.2.jar:4.1.2]
        at org.springframework.data.mongodb.MongoTransactionManager.doCommit(MongoTransactionManager.java:176) ~[spring-data-mongodb-4.1.2.jar:4.1.2]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:743) ~[spring-tx-6.0.11.jar:6.0.11]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711) ~[spring-tx-6.0.11.jar:6.0.11]
        at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:660) ~[spring-tx-6.0.11.jar:6.0.11]
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:410) ~[spring-tx-6.0.11.jar:6.0.11]
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) ~[spring-tx-6.0.11.jar:6.0.11]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184) ~[spring-aop-6.0.11.jar:6.0.11]
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:756) ~[spring-aop-6.0.11.jar:6.0.11]
        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:708) ~[spring-aop-6.0.11.jar:6.0.11]
        at mongo.test.controllers.Processor$$SpringCGLIB$$0.process(<generated>) ~[mongo-test-1.0-SNAPSHOT.jar:na]
        at mongo.test.controllers.TestController.process(TestController.java:16) ~[mongo-test-1.0-SNAPSHOT.jar:na]
        at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104) ~[na:na]
        at java.base/java.lang.reflect.Method.invoke(Method.java:578) ~[na:na]
        at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205) ~[spring-web-6.0.11.jar:6.0.11]
        at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150) ~[spring-web-6.0.11.jar:6.0.11]
        at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:118) ~[spring-webmvc-6.0.11.jar:6.0.11]
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:884) ~[spring-webmvc-6.0.11.jar:6.0.11]
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:797) ~[spring-webmvc-6.0.11.jar:6.0.11]
        at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-6.0.11.jar:6.0.11]
        at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1081) ~[spring-webmvc-6.0.11.jar:6.0.11]
        at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:974) ~[spring-webmvc-6.0.11.jar:6.0.11]
        at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1011) ~[spring-webmvc-6.0.11.jar:6.0.11]
        at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:914) ~[spring-webmvc-6.0.11.jar:6.0.11]
        at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:590) ~[tomcat-embed-core-10.1.11.jar:6.0]
        at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:885) ~[spring-webmvc-6.0.11.jar:6.0.11]
        at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:658) ~[tomcat-embed-core-10.1.11.jar:6.0]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:205) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51) ~[tomcat-embed-websocket-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-6.0.11.jar:6.0.11]
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) ~[spring-web-6.0.11.jar:6.0.11]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-6.0.11.jar:6.0.11]
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) ~[spring-web-6.0.11.jar:6.0.11]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.springframework.web.filter.ServerHttpObservationFilter.doFilterInternal(ServerHttpObservationFilter.java:109) ~[spring-web-6.0.11.jar:6.0.11]
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) ~[spring-web-6.0.11.jar:6.0.11]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-6.0.11.jar:6.0.11]
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) ~[spring-web-6.0.11.jar:6.0.11]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:166) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:482) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:115) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:341) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:391) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:894) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1740) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-10.1.11.jar:10.1.11]
        at java.base/java.lang.Thread.run(Thread.java:1623) ~[na:na]

And the sample project: https://github.com/worldtiki/mongo-test/tree/main

You can either run ./mvnw clean verify or run the MongoTransactionsIT test in your ide. The error is visible in the logs when the test runs.

This file is also relevant as it contains the Observation and Transaction configurations.

[mp911de]

Thanks a lot for the reproducer. The problem comes from the failed abortTransaction command. We do not create an observation for that command as it is invoked against the admin database. However, the current observation points at the web request and that is where the failure comes from.

We can avoid such exceptions by checking whether the current context points at a MongoDB operation.