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

Stacktraces of exceptions are trimmed too much #2238

Closed
hypfvieh opened this issue Mar 23, 2021 · 3 comments
Closed

Stacktraces of exceptions are trimmed too much #2238

hypfvieh opened this issue Mar 23, 2021 · 3 comments
Labels
please contribute

Comments

@hypfvieh
Copy link
Contributor

Hi,

I'm not sure if this is a bug or an intended behaviour.

When testing a method which throws an exception (checked or unchecked), the causing line is suppressed in the stack coming from Mockito.

Simple example:

package test;

import java.io.IOException;

import org.mockito.Mockito;

public class TestSpy {
    public static void main(String[] args) throws IOException {
        Foo spy = Mockito.spy(new Foo());
        spy.message();
    }

    public static class Foo {
        public void message() throws IOException {
            System.out.println("Hello 1!"); // line 15
            System.out.println("Hello 2!");
            throw new IOException("fatal"); // line 17
        }
    }
}

When calling 'message()' on the spy (same happens on a full mock as well), I would expect to see line 17 in the exception cause.
Instead I see this:

Exception in thread "main" java.io.IOException: fatal
	at test.TestSpy$Foo.message(TestSpy.java:15)
	at test.TestSpy.main(TestSpy.java:10)

Line 15 contains 'System.out.println', which is not causing the exception, but is the first expression inside of the method 'message()'.

I debugged this behaviour and came to org.mockito.internal.creation.bytebuddy.MockMethodAdvice.hideRecursiveCall(Throwable, int, Class<?>)
which seems to be the root cause for this.
The stack trace given to that method includes the correct line (line 17 in this case).

My stack trace in this case has 18 entries in total:

java.io.IOException: fatal
	at test.TestSpy$Foo.message(TestSpy.java:17)
	at java.base/java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:710)
	at org.mockito.internal.util.reflection.InstrumentationMemberAccessor$Dispatcher$ByteBuddy$2kmhnFkd.invokeWithArguments(Unknown Source)
	at org.mockito.internal.util.reflection.InstrumentationMemberAccessor.invoke(InstrumentationMemberAccessor.java:230)
	at org.mockito.internal.util.reflection.ModuleMemberAccessor.invoke(ModuleMemberAccessor.java:43)
	at org.mockito.internal.creation.bytebuddy.MockMethodAdvice.tryInvoke(MockMethodAdvice.java:329)
	at org.mockito.internal.creation.bytebuddy.MockMethodAdvice.access$500(MockMethodAdvice.java:56)
	at org.mockito.internal.creation.bytebuddy.MockMethodAdvice$RealMethodCall.invoke(MockMethodAdvice.java:249)
	at org.mockito.internal.invocation.InterceptedInvocation.callRealMethod(InterceptedInvocation.java:141)
	at org.mockito.internal.stubbing.answers.CallsRealMethods.answer(CallsRealMethods.java:44)
	at org.mockito.Answers.answer(Answers.java:98)
	at org.mockito.internal.handler.MockHandlerImpl.handle(MockHandlerImpl.java:106)
	at org.mockito.internal.handler.NullResultGuardian.handle(NullResultGuardian.java:29)
	at org.mockito.internal.handler.InvocationNotifierHandler.handle(InvocationNotifierHandler.java:33)
	at org.mockito.internal.creation.bytebuddy.MockMethodInterceptor.doIntercept(MockMethodInterceptor.java:82)
	at org.mockito.internal.creation.bytebuddy.MockMethodAdvice.handle(MockMethodAdvice.java:147)
	at test.TestSpy$Foo.message(TestSpy.java:15)
	at test.TestSpy.main(TestSpy.java:10)

When the method is finished, 13 entries are left and the most important entry is missing:

java.io.IOException: fatal
	at org.mockito.internal.creation.bytebuddy.MockMethodAdvice.tryInvoke(MockMethodAdvice.java:329)
	at org.mockito.internal.creation.bytebuddy.MockMethodAdvice.access$500(MockMethodAdvice.java:56)
	at org.mockito.internal.creation.bytebuddy.MockMethodAdvice$RealMethodCall.invoke(MockMethodAdvice.java:249)
	at org.mockito.internal.invocation.InterceptedInvocation.callRealMethod(InterceptedInvocation.java:141)
	at org.mockito.internal.stubbing.answers.CallsRealMethods.answer(CallsRealMethods.java:44)
	at org.mockito.Answers.answer(Answers.java:98)
	at org.mockito.internal.handler.MockHandlerImpl.handle(MockHandlerImpl.java:106)
	at org.mockito.internal.handler.NullResultGuardian.handle(NullResultGuardian.java:29)
	at org.mockito.internal.handler.InvocationNotifierHandler.handle(InvocationNotifierHandler.java:33)
	at org.mockito.internal.creation.bytebuddy.MockMethodInterceptor.doIntercept(MockMethodInterceptor.java:82)
	at org.mockito.internal.creation.bytebuddy.MockMethodAdvice.handle(MockMethodAdvice.java:147)
	at test.TestSpy$Foo.message(TestSpy.java:15)
	at test.TestSpy.main(TestSpy.java:10)

Disabling "cleansStackTrace" using MockitoConfiguration does not help - hideRecursiveCall is always called.

This bug/feature is very annoying when testing methods which may throw the same type of exception at different locations.
Eg. in my case I know that the exception was thrown in that very method, but I don't know if it happens in e.g. line 20 or 85.

Same thing happens to RuntimeExceptions, which is also annoying... Seeing a NullPointerException without knowing where it happens is not helpful.

Is there any (configuration) option to disable the 'cleaning' of the stack trace completely?
Any chance of getting this fixed?

Tested Mockito versions: 3.6.0 and 3.8.0
OS: Linux/Ubuntu 20.04 64-Bit
JDK: OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.9+11)
@TimvdLippe
Copy link
Contributor

Thanks for reporting this issue! We would welcome a patch + regression test for this issue.

@spannm
Copy link

spannm commented Mar 23, 2021

Thanks for your great work on Mockito and the contribution to open source it continues to make.

I've come across the very same behavior under a similar setup.
I must agree with the OP, this appears to be a bug, and it would be great to see it fixed.

@hypfvieh hypfvieh mentioned this issue Mar 25, 2021
Merged
@holubec-petr holubec-petr mentioned this issue Nov 26, 2021
Closed
5 tasks
@holubec-petr
Copy link

Unfortunately, this fix broke one of my tests.

The fixed code hides much more stack trace elements than before which breaks my production logic due to missing some important frames.

The exception is thrown by GroovyIcm.getDirectory.

My original stack trace (shortened):

my.company.engine.processors.scripting.api_impl.groovy.GroovyIcm$getDirectory$1.invoke(GroovyIcm.kt:34)
my.company.engine.processors.scripting.api_impl.groovy.GroovyIcm$getDirectory$1.invoke(GroovyIcm.kt:34)
my.company.engine.processors.scripting.groovy.GroovyExceptionUtil$Companion.throwOnNull(GroovyExceptionUtil.kt:34)
my.company.engine.processors.scripting.api_impl.groovy.GroovyIcm.getDirectory(GroovyIcm.kt:34)
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.base/java.lang.reflect.Method.invoke(Method.java:566)
org.mockito.internal.util.reflection.ReflectionMemberAccessor.invoke(ReflectionMemberAccessor.java:48)
org.mockito.internal.creation.bytebuddy.MockMethodAdvice.tryInvoke(MockMethodAdvice.java:333)
org.mockito.internal.creation.bytebuddy.MockMethodAdvice.access$500(MockMethodAdvice.java:60)
org.mockito.internal.creation.bytebuddy.MockMethodAdvice$RealMethodCall.invoke(MockMethodAdvice.java:253)
org.mockito.internal.invocation.InterceptedInvocation.callRealMethod(InterceptedInvocation.java:142)
org.mockito.internal.stubbing.answers.CallsRealMethods.answer(CallsRealMethods.java:45)
org.mockito.Answers.answer(Answers.java:90)
org.mockito.internal.handler.MockHandlerImpl.handle(MockHandlerImpl.java:110)
org.mockito.internal.handler.NullResultGuardian.handle(NullResultGuardian.java:29)
org.mockito.internal.handler.InvocationNotifierHandler.handle(InvocationNotifierHandler.java:34)
org.mockito.internal.creation.bytebuddy.MockMethodInterceptor.doIntercept(MockMethodInterceptor.java:82)
org.mockito.internal.creation.bytebuddy.MockMethodAdvice.handle(MockMethodAdvice.java:151)
my.company.engine.processors.scripting.api_impl.groovy.GroovyIcm.getDirectory(GroovyIcm.kt:34)
my.company.scripting.groovy.api.definitions.icm.IcmApi$getDirectory.call(Unknown Source)
org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:47)
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:125)
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:139)
Script_df5730203a3340a9757f6622995e3fd5.run(Script_df5730203a3340a9757f6622995e3fd5.groovy:1)
my.company.scripting.groovy.GroovyInterpreter.execute(GroovyInterpreter.kt:26)
my.company.engine.processors.scripting.groovy.GroovyScriptProcessor.execute(GroovyScriptProcessor.kt:65)
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.base/java.lang.reflect.Method.invoke(Method.java:566)
org.mockito.internal.util.reflection.ReflectionMemberAccessor.invoke(ReflectionMemberAccessor.java:48)
org.mockito.internal.creation.bytebuddy.MockMethodAdvice.tryInvoke(MockMethodAdvice.java:333)
org.mockito.internal.creation.bytebuddy.MockMethodAdvice.access$500(MockMethodAdvice.java:60)
org.mockito.internal.creation.bytebuddy.MockMethodAdvice$RealMethodCall.invoke(MockMethodAdvice.java:253)
org.mockito.internal.invocation.InterceptedInvocation.callRealMethod(InterceptedInvocation.java:142)
org.mockito.internal.stubbing.answers.CallsRealMethods.answer(CallsRealMethods.java:45)
org.mockito.Answers.answer(Answers.java:90)
org.mockito.internal.handler.MockHandlerImpl.handle(MockHandlerImpl.java:110)
org.mockito.internal.handler.NullResultGuardian.handle(NullResultGuardian.java:29)
org.mockito.internal.handler.InvocationNotifierHandler.handle(InvocationNotifierHandler.java:34)
org.mockito.internal.creation.bytebuddy.MockMethodInterceptor.doIntercept(MockMethodInterceptor.java:82)
org.mockito.internal.creation.bytebuddy.MockMethodAdvice.handle(MockMethodAdvice.java:151)
my.company.engine.processors.scripting.groovy.GroovyScriptProcessor.execute(GroovyScriptProcessor.kt:55)
my.company.engine.processors.scripting.api_impl.groovy.GroovyIcmApiTest.get fails job if path do not exist(GroovyIcmApiTest.kt:127)
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
...

My stack trace after processing (complete):

my.company.engine.processors.scripting.api_impl.groovy.GroovyIcm$getDirectory$1.invoke(GroovyIcm.kt:34)
my.company.engine.processors.scripting.api_impl.groovy.GroovyIcm$getDirectory$1.invoke(GroovyIcm.kt:34)
my.company.engine.processors.scripting.groovy.GroovyExceptionUtil$Companion.throwOnNull(GroovyExceptionUtil.kt:34)
my.company.engine.processors.scripting.api_impl.groovy.GroovyIcm.getDirectory(GroovyIcm.kt:34)
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.base/java.lang.reflect.Method.invoke(Method.java:566)
org.mockito.internal.util.reflection.ReflectionMemberAccessor.invoke(ReflectionMemberAccessor.java:48)
org.mockito.internal.creation.bytebuddy.MockMethodAdvice.tryInvoke(MockMethodAdvice.java:333)
org.mockito.internal.creation.bytebuddy.MockMethodAdvice.access$500(MockMethodAdvice.java:60)
org.mockito.internal.creation.bytebuddy.MockMethodAdvice$RealMethodCall.invoke(MockMethodAdvice.java:253)
org.mockito.internal.invocation.InterceptedInvocation.callRealMethod(InterceptedInvocation.java:142)
org.mockito.internal.stubbing.answers.CallsRealMethods.answer(CallsRealMethods.java:45)
org.mockito.Answers.answer(Answers.java:90)
org.mockito.internal.handler.MockHandlerImpl.handle(MockHandlerImpl.java:110)
org.mockito.internal.handler.NullResultGuardian.handle(NullResultGuardian.java:29)
org.mockito.internal.handler.InvocationNotifierHandler.handle(InvocationNotifierHandler.java:34)
org.mockito.internal.creation.bytebuddy.MockMethodInterceptor.doIntercept(MockMethodInterceptor.java:82)
org.mockito.internal.creation.bytebuddy.MockMethodAdvice.handle(MockMethodAdvice.java:151)
worker.org.gradle.process.internal.worker.GradleWorkerMain.main(GradleWorkerMain.java:74)

Notice that Script_df5730203a3340a9757f6622995e3fd5.run(...) is missing in the processed stack trace.

@holubec-petr holubec-petr mentioned this issue Nov 26, 2021
Closed
5 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
please contribute
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@spannm @hypfvieh @TimvdLippe @holubec-petr