Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Class cast exception obtaining Observation context on abortTransaction completion #4481

Closed
worldtiki opened this issue Aug 22, 2023 · 4 comments
Closed

Class cast exception obtaining Observation context on abortTransaction completion #4481

worldtiki opened this issue Aug 22, 2023 · 4 comments
Assignees
@mp911de
Labels
type: bug A general bug
Milestone
4.0.10 (2022.0.10)

Comments

@worldtiki
Copy link

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?
@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Aug 22, 2023
@mp911de
Copy link
Member

mp911de commented Aug 23, 2023

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.

@mp911de mp911de added the status: waiting-for-feedback We need additional information before we can continue label Aug 23, 2023
@worldtiki
Copy link
Author

worldtiki commented Aug 24, 2023 •
edited

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.

@spring-projects-issues spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Aug 24, 2023
@mp911de mp911de self-assigned this Aug 24, 2023
@mp911de
Copy link
Member

mp911de commented Aug 24, 2023

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.

@mp911de mp911de added type: bug A general bug and removed status: waiting-for-triage An issue we've not yet triaged status: feedback-provided Feedback has been provided labels Aug 24, 2023
@mp911de mp911de changed the title Class cast exception for Context when using transactions Class cast exception obtaining Observation context on abortTransaction completion Aug 24, 2023
@mp911de mp911de added this to the 4.0.10 (2022.0.10) milestone Aug 24, 2023
mp911de added a commit that referenced this issue Aug 24, 2023
@mp911de
Polishing.
e5aff26 
Refactor duplicate code into callback.

See #4481
mp911de added a commit that referenced this issue Aug 24, 2023
@mp911de
Guard command completion listener against unsupported observation con…
7404e84 
…text.

We now no longer attempt to complete the Observation if the context is not a MongoDB one. For commands that target the admin database and run within a parent observation, we still might have an Observation but that one points to the parent invocation and not the MongoDB one as we do not record commands for the admin database.

Closes #4481
mp911de added a commit that referenced this issue Aug 24, 2023
@mp911de
Polishing.
84b734c 
Refactor duplicate code into callback.

See #4481
mp911de added a commit that referenced this issue Aug 24, 2023
@mp911de
Guard command completion listener against unsupported observation con…
0be1e52 
…text.

We now no longer attempt to complete the Observation if the context is not a MongoDB one. For commands that target the admin database and run within a parent observation, we still might have an Observation but that one points to the parent invocation and not the MongoDB one as we do not record commands for the admin database.

Closes #4481
mp911de added a commit that referenced this issue Aug 24, 2023
@mp911de
Polishing.
0b3d1b8 
Refactor duplicate code into callback.

See #4481
@worldtiki
Copy link
Author

Thank you @mp911de

@christophstrobl christophstrobl mentioned this issue Aug 31, 2023
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@mp911de mp911de

Labels
type: bug A general bug
Projects
None yet
Milestone
4.0.10 (2022.0.10)
Development

No branches or pull requests
3 participants
@mp911de @worldtiki @spring-projects-issues