Spring Exceptions can be lost in RemoteInvocationTraceInterceptor

Affects: 5.3.33

We recently had an instance of a remote method call failing but the exception that was caught was a NullPointerException thrown from ClassUtils.getQualifiedMethodName via the logging call in RemoteInvocationTraceInterceptor rather than the original cause.

catch (Throwable ex) {
    // ...
    else {
        if (logger.isInfoEnabled()) {
            logger.info("Processing of " + this.exporterNameClause + "remote call resulted in exception: " +
                    ClassUtils.getQualifiedMethodName(method), ex); // <-- here
        }
    }
}

I'm not sure what is happening yet to cause method to be null, but having the original exception would help debug the issue - especially to rule out the possibility that method being null is a valid state. Presumably given the raised exception wasn't a RuntimeException it wasn't a different NPE thrown from further into the invocation. It also meant that disabling the info level logging would have increased the detail of the exception as the original exception would have been thrown.

Assuming method being null here is unexpected, could the logging guard against the subsequent NPE?

Comment From: sbrannen

Indeed, org.aopalliance.intercept.MethodInvocation.getMethod() should never return null.

Did you encounter the NPE in a testing scenario, potentially with some form of mocks?

Or did you encounter this in a production deployment?

Comment From: tpoliaw

We've seen it a handful of times in production but haven't been able to reproduce it or narrow down what's causing it yet. I'm happy to accept that the bug is probably on our side for that - we have another layer of proxying going on that may be interfering - this was more about the exception being unavailable.

If if helps, the full stack (up to the 'filling in client stack trace' section):

java.lang.IllegalArgumentException: Method must not be null
    at org.springframework.util.Assert.notNull(Assert.java:201)
    at org.springframework.util.ClassUtils.getQualifiedMethodName(ClassUtils.java:1066)
    at org.springframework.util.ClassUtils.getQualifiedMethodName(ClassUtils.java:1053)
    at org.springframework.remoting.support.RemoteInvocationTraceInterceptor.invoke(RemoteInvocationTraceInterceptor.java:97)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
    at jdk.proxy8/jdk.proxy8.$Proxy63.moveTo(Unknown Source)
    at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Unknown Source)
    at java.base/java.lang.reflect.Method.invoke(Unknown Source)
    at org.springframework.remoting.support.RemoteInvocation.invoke(RemoteInvocation.java:215)
    at org.springframework.remoting.support.DefaultRemoteInvocationExecutor.invoke(DefaultRemoteInvocationExecutor.java:39)
    at org.springframework.remoting.support.RemoteInvocationBasedExporter.invoke(RemoteInvocationBasedExporter.java:78)
    at org.springframework.remoting.rmi.RmiBasedExporter.invoke(RmiBasedExporter.java:75)
    at org.springframework.remoting.rmi.RmiInvocationWrapper.invoke(RmiInvocationWrapper.java:78)
    at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Unknown Source)
    at java.base/java.lang.reflect.Method.invoke(Unknown Source)
    at java.rmi/sun.rmi.server.UnicastServerRef.dispatch(Unknown Source)
    at java.rmi/sun.rmi.transport.Transport$1.run(Unknown Source)
    at java.rmi/sun.rmi.transport.Transport$1.run(Unknown Source)
    at java.base/java.security.AccessController.doPrivileged(Unknown Source)
    at java.rmi/sun.rmi.transport.Transport.serviceCall(Unknown Source)
    at java.rmi/sun.rmi.transport.tcp.TCPTransport.handleMessages(Unknown Source)
    at java.rmi/sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(Unknown Source)
    at java.rmi/sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(Unknown Source)
    at java.base/java.security.AccessController.doPrivileged(Unknown Source)
    at java.rmi/sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(Unknown Source)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

Comment From: snicoll

@tpoliaw unfortunately RemoteInvocationTraceInterceptor is deprecated so we have no intention to make further changes to it. Without a reproducer, we can't really help you. Please note that Spring 5.3.x will be EOL shortly and RemoteInvocationTraceInterceptor has been removed in Spring Framework 6.