Skip to content

False positive test on timeout is generated by Symbolic engine #2498

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.

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

Closed
alisevych opened this issue Aug 10, 2023 · 1 comment
Closed

False positive test on timeout is generated by Symbolic engine #2498

alisevych opened this issue Aug 10, 2023 · 1 comment
Assignees
Labels
comp-instrumented-process Issue is related to Instrumented process comp-spring Issue is related to Spring projects support ctg-bug Issue is a bug priority-blocker Bug blocking some of the main features

Comments

@alisevych
Copy link
Member

Description

False positive test on timeout is generated by Symbolic engine on sm***t project: DCMI class, qcbu method

To Reproduce

  1. Install UnitTestBot plugin built from main in IntelliJ IDEA Ultimate 2023.2
  2. Open sm***t project
  3. Open DCMI class
  4. Generate tests with Spring configuration Sm***tApplication, UnitTests, other settings as default
  5. Find tests on timeout and run them

Expected behavior

No tests on timeout should be generated for the class.

Actual behavior

There are tests on timeout being generated.
They fail with NPE.
There are java.lang.InterruptedException and java.lang.ThreadDeath in utbot-engine-current.log (see below)

Screenshots, logs

    @Test
    @Timeout(value = 1000L, unit = TimeUnit.MILLISECONDS)
    public void test***_DCM***() throws ClassNotFoundException, IllegalAccessException, NoSuchFieldException, InvocationTargetException, NoSuchMethodException {
        (when(dtcmMock.get***(any()))).thenReturn(((List) null));
        setField(dscmi, "***", "dscm", dscmMock);
        
        /* This execution may take longer than the 1000 ms timeout
         and therefore fail due to exceeding the timeout. */
        assertTimeoutPreemptively(Duration.ofMillis(1000L), () -> dscmi.get***(null));
    }
13:52:14.763 | ERROR | InstrumentedProcess       | RdCategory: DynamicClassTransformer   | Error while transforming: java.lang.InterruptedException
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1223)
	at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:340)
	at org.utbot.common.StopWatch.stop(StopWatch.kt:66)
	at org.utbot.instrumentation.agent.DynamicClassTransformer.transform(DynamicClassTransformer.kt:38)
	at sun.instrument.TransformerManager.transform(TransformerManager.java:188)
	at sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:428)
	at java.lang.ClassLoader.defineClass1(Native Method)
	at java.lang.ClassLoader.defineClass(ClassLoader.java:757)
	at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:142)
	at java.net.URLClassLoader.defineClass(URLClassLoader.java:473)
	at java.net.URLClassLoader.access$100(URLClassLoader.java:74)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:369)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:363)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.net.URLClassLoader.findClass(URLClassLoader.java:362)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:419)
	at org.utbot.instrumentation.process.HandlerClassesLoader.loadClass(InstrumentedProcessMain.kt:54)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:352)
	at ch.qos.logback.classic.PatternLayout.<clinit>(PatternLayout.java:111)
	at ch.qos.logback.classic.encoder.PatternLayoutEncoder.start(PatternLayoutEncoder.java:24)
	at ch.qos.logback.core.joran.action.NestedComplexPropertyIA.end(NestedComplexPropertyIA.java:161)
	at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:309)
	at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:193)
	at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:179)
	at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:62)
	at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:165)
	at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:152)
	at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:110)
	at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:53)
	at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:64)
	at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:134)
	at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:84)
	at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)
	at org.slf4j.LoggerFactory.bind(LoggerFactory.java:150)
	at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:124)
	at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:417)
	at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:362)
	at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:388)
	at com.***
	at sun.misc.Unsafe.allocateInstance(Native Method)
	at org.utbot.framework.plugin.api.util.ReflectionUtilsKt.getAnyInstance(ReflectionUtils.kt:45)
	at org.utbot.instrumentation.instrumentation.execution.constructors.InstrumentationContextAwareValueConstructor.constructObject(InstrumentationContextAwareValueConstructor.kt:142)
	at org.utbot.instrumentation.instrumentation.execution.constructors.InstrumentationContextAwareValueConstructor.construct(InstrumentationContextAwareValueConstructor.kt:107)
	at org.utbot.instrumentation.instrumentation.execution.constructors.InstrumentationContextAwareValueConstructor.constructMethodParameters(InstrumentationContextAwareValueConstructor.kt:88)
	at org.utbot.instrumentation.instrumentation.execution.phases.ValueConstructionPhase.constructParameters(ValueConstructionPhase.kt:47)
	at org.utbot.instrumentation.instrumentation.execution.phases.PhasesController$applyPreprocessing$constructedData$1.invoke(PhasesController.kt:96)
	at org.utbot.instrumentation.instrumentation.execution.phases.PhasesController$applyPreprocessing$constructedData$1.invoke(PhasesController.kt:95)
	at org.utbot.instrumentation.instrumentation.execution.phases.PhasesController$executePhaseInTimeout$1$result$1.invoke(PhasesController.kt:73)
	at org.utbot.common.ThreadBasedExecutor$invokeWithTimeout$1.invoke(ThreadUtil.kt:49)
	at org.utbot.common.ThreadBasedExecutor$ensureThreadIsAlive$1.invoke(ThreadUtil.kt:97)
	at org.utbot.common.ThreadBasedExecutor$ensureThreadIsAlive$1.invoke(ThreadUtil.kt:93)
	at kotlin.concurrent.ThreadsKt$thread$thread$1.run(Thread.kt:30)
 
13:52:14.766 | INFO  | InstrumentedProcess       | RdCategory: DynamicClassTransformer   | Transformed: ch/qos/logback/classic/pattern/ContextNameConverter 
13:52:14.776 | ERROR | InstrumentedProcess       | RdCategory: DynamicClassTransformer   | Error while transforming: java.lang.ThreadDeath
	at java.lang.Thread.stop(Thread.java:858)
	at org.utbot.common.ThreadBasedExecutor.invokeWithTimeout-RgG5Fkc(ThreadUtil.kt:72)
	at org.utbot.instrumentation.instrumentation.execution.phases.PhasesController$executePhaseInTimeout$1.invoke(PhasesController.kt:70)
	at org.utbot.instrumentation.instrumentation.execution.phases.PhasesController$executePhaseInTimeout$1.invoke(PhasesController.kt:65)
	at org.utbot.instrumentation.instrumentation.execution.phases.ExecutionPhaseKt.start(ExecutionPhase.kt:25)
	at org.utbot.instrumentation.instrumentation.execution.phases.PhasesController.executePhaseInTimeout(PhasesController.kt:65)
	at org.utbot.instrumentation.instrumentation.execution.phases.PhasesController.applyPreprocessing(PhasesController.kt:95)
	at org.utbot.instrumentation.instrumentation.execution.SimpleUtExecutionInstrumentation$invoke$1$1.invoke(SimpleUtExecutionInstrumentation.kt:65)
	at org.utbot.instrumentation.instrumentation.execution.SimpleUtExecutionInstrumentation$invoke$1$1.invoke(SimpleUtExecutionInstrumentation.kt:62)
	at org.utbot.instrumentation.instrumentation.execution.UtExecutionInstrumentation$invoke$1.invoke(UtExecutionInstrumentation.kt:46)
	at org.utbot.instrumentation.instrumentation.execution.UtExecutionInstrumentation$invoke$1.invoke(UtExecutionInstrumentation.kt:45)
	at org.utbot.instrumentation.instrumentation.execution.SimpleUtExecutionInstrumentation.invoke(SimpleUtExecutionInstrumentation.kt:62)
	at org.utbot.instrumentation.instrumentation.execution.UtExecutionInstrumentation$DefaultImpls.invoke(UtExecutionInstrumentation.kt:45)
	at org.utbot.instrumentation.instrumentation.execution.SimpleUtExecutionInstrumentation.invoke(SimpleUtExecutionInstrumentation.kt:26)
	at org.utbot.instrumentation.instrumentation.execution.SimpleUtExecutionInstrumentation.invoke(SimpleUtExecutionInstrumentation.kt:26)
	at org.utbot.instrumentation.process.InstrumentedProcessMainKt$setup$2.invoke(InstrumentedProcessMain.kt:130)
	at org.utbot.instrumentation.process.InstrumentedProcessMainKt$setup$2.invoke(InstrumentedProcessMain.kt:127)
	at org.utbot.rd.IdleWatchdog$measureTimeForActiveCall$1$2$1.invoke(ClientProcessUtil.kt:115)
	at org.utbot.rd.IdleWatchdog.wrapActive(ClientProcessUtil.kt:88)
	at org.utbot.rd.IdleWatchdog$measureTimeForActiveCall$1.invoke(ClientProcessUtil.kt:114)
	at com.jetbrains.rd.framework.IRdEndpoint$set$1.invoke(TaskInterfaces.kt:182)
	at com.jetbrains.rd.framework.IRdEndpoint$set$1.invoke(TaskInterfaces.kt:182)
	at com.jetbrains.rd.framework.impl.RdCall.onWireReceived(RdTask.kt:362)
	at com.jetbrains.rd.framework.MessageBroker$invoke$2$2.invoke(MessageBroker.kt:57)
	at com.jetbrains.rd.framework.MessageBroker$invoke$2$2.invoke(MessageBroker.kt:56)
	at com.jetbrains.rd.framework.impl.ProtocolContexts.readMessageContextAndInvoke(ProtocolContexts.kt:148)
	at com.jetbrains.rd.framework.MessageBroker$invoke$2.invoke(MessageBroker.kt:56)
	at com.jetbrains.rd.framework.MessageBroker$invoke$2.invoke(MessageBroker.kt:54)
	at com.jetbrains.rd.util.threading.SingleThreadSchedulerBase.queue$lambda-3(SingleThreadScheduler.kt:41)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:750)
 
...

13:52:15.846 | ERROR | InstrumentedProcess       | RdCategory: DynamicClassTransformer   | Error while transforming: java.lang.InterruptedException
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1223)
	at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:340)
	at org.utbot.common.StopWatch.stop(StopWatch.kt:66)
	at org.utbot.instrumentation.agent.DynamicClassTransformer.transform(DynamicClassTransformer.kt:38)
	at sun.instrument.TransformerManager.transform(TransformerManager.java:188)
	at sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:428)
	at java.lang.ClassLoader.defineClass1(Native Method)
	at java.lang.ClassLoader.defineClass(ClassLoader.java:757)
	at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:142)
	at java.net.URLClassLoader.defineClass(URLClassLoader.java:473)
	at java.net.URLClassLoader.access$100(URLClassLoader.java:74)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:369)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:363)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.net.URLClassLoader.findClass(URLClassLoader.java:362)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:419)
	at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:352)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:352)
	at org.utbot.instrumentation.instrumentation.execution.phases.PhasesController$executePhaseInTimeout$1$result$1.invoke(PhasesController.kt:125)
	at org.utbot.common.ThreadBasedExecutor$invokeWithTimeout$1.invoke(ThreadUtil.kt:49)
	at org.utbot.common.ThreadBasedExecutor$ensureThreadIsAlive$1.invoke(ThreadUtil.kt:97)
	at org.utbot.common.ThreadBasedExecutor$ensureThreadIsAlive$1.invoke(ThreadUtil.kt:93)
	at kotlin.concurrent.ThreadsKt$thread$thread$1.run(Thread.kt:30)

Environment

IntelliJ IDEA version - Ultimate 2023.2
Project - sm***t, Maven
JDK - 1.8

Additional context

Reproducing for customer.
Probably related issue:

@alisevych alisevych added ctg-bug Issue is a bug comp-instrumented-process Issue is related to Instrumented process comp-spring Issue is related to Spring projects support labels Aug 10, 2023
@alisevych alisevych added this to the September Release milestone Aug 10, 2023
@EgorkaKulikov EgorkaKulikov added the priority-blocker Bug blocking some of the main features label Aug 24, 2023
@EgorkaKulikov EgorkaKulikov linked a pull request Aug 24, 2023 that will close this issue
6 tasks
@alisevych alisevych self-assigned this Sep 18, 2023
@alisevych
Copy link
Member Author

Closing as not reproducing any more with plugin built from the latest main.

@github-project-automation github-project-automation bot moved this from Todo to Done in UTBot Java Sep 18, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
comp-instrumented-process Issue is related to Instrumented process comp-spring Issue is related to Spring projects support ctg-bug Issue is a bug priority-blocker Bug blocking some of the main features
Projects
Archived in project
Development

No branches or pull requests

2 participants