Hung state when showTestOutput = false, 5.8+ versions

[pagmoro]

When showTestOutput = false , TestSuite run hangs indefinitely , seen in both 5.8.1 and 5.8.0 versions Note: I only have 1 feature with 2 Scenarios which takes 7 seconds to execute when showTestOutput = true

Options:

@RunWith(Courgette.class)
@CourgetteOptions(
    threads = 10,
    runLevel = CourgetteRunLevel.FEATURE,
    rerunFailedScenarios = true,
    rerunAttempts = 1,
    showTestOutput = false,
    reportTargetDir = "build",
    cucumberOptions = @CucumberOptions(
        features = "src/integrationTest/resources/features/",
        glue = {"classpath:com.mysteps", "classpath:com.mypackage"},
        plugin = {"pretty"}
))

Thread Dump of io.cucumber.core.cli.Main process:

2021-01-16 23:34:18
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.181-b25 mixed mode):

"Thread-1" #14 daemon prio=5 os_prio=0 tid=0x000000003d3a7000 nid=0x1c18 runnable [0x000000003d89f000]
   java.lang.Thread.State: RUNNABLE
at sun.nio.ch.Iocp.getQueuedCompletionStatus(Native Method)
at sun.nio.ch.Iocp.access$300(Iocp.java:46)
at sun.nio.ch.Iocp$EventHandlerTask.run(Iocp.java:333)
at java.lang.Thread.run(Thread.java:748)

"sshd-SshClient[72ade7e3]-timer-thread-1" #13 daemon prio=5 os_prio=0 tid=0x000000003cfc9800 nid=0x3820 waiting on 
condition [0x000000003b9be000]
   java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for  <0x00000003c2015cc8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

"logback-1" #12 daemon prio=5 os_prio=0 tid=0x000000003e3c0800 nid=0x42a8 waiting on condition [0x000000003f35e000]
   java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for  <0x00000003c226f700> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

"Service Thread" #10 daemon prio=9 os_prio=0 tid=0x000000003a07e800 nid=0x2508 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread3" #9 daemon prio=9 os_prio=2 tid=0x000000003a012000 nid=0x4058 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread2" #8 daemon prio=9 os_prio=2 tid=0x0000000039fea800 nid=0x5178 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #7 daemon prio=9 os_prio=2 tid=0x0000000039fe1800 nid=0x60a4 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #6 daemon prio=9 os_prio=2 tid=0x0000000039fd8000 nid=0x2ed4 waiting on condition [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE

"Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x0000000039fd6800 nid=0x1bfc waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=2 tid=0x0000000039fd5800 nid=0x2308 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x0000000036c2f000 nid=0x62bc in Object.wait() [0x000000003afcf000]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000003c203e050> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
- locked <0x00000003c203e050> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)

    "Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x0000000036c2c800 nid=0x5dc0 in Object.wait() 
[0x000000003b2bf000]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000003c203e220> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
- locked <0x00000003c203e220> (a java.lang.ref.Reference$Lock)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"main" #1 prio=5 os_prio=0 tid=0x00000000028cc000 nid=0x497c runnable [0x0000000002d8e000]
   java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:326)
at java.io.BufferedOutputStream.write(BufferedOutputStream.java:122)
- locked <0x00000003c20c0cb0> (a java.io.BufferedOutputStream)
at java.io.PrintStream.write(PrintStream.java:480)
- locked <0x00000003c20c0c90> (a java.io.PrintStream)
at java.io.PrintStream.write(PrintStream.java:480)
- locked <0x00000003c2185348> (a io.cucumber.core.plugin.PluginFactory$1)
at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295)
at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
- locked <0x00000003c2185330> (a io.cucumber.core.plugin.UTF8OutputStreamWriter)
at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
at io.cucumber.core.plugin.NiceAppendable.tryFlush(NiceAppendable.java:59)
at io.cucumber.core.plugin.NiceAppendable.println(NiceAppendable.java:68)
at io.cucumber.core.plugin.PrettyFormatter.printStep(PrettyFormatter.java:129)
at io.cucumber.core.plugin.PrettyFormatter.handleTestStepFinished(PrettyFormatter.java:68)
at io.cucumber.core.plugin.PrettyFormatter$$Lambda$54/87765719.receive(Unknown Source)
at io.cucumber.core.eventbus.AbstractEventPublisher.send(AbstractEventPublisher.java:51)
at io.cucumber.core.eventbus.AbstractEventBus.send(AbstractEventBus.java:12)
at io.cucumber.core.runner.TestStep.emitTestStepFinished(TestStep.java:124)
at io.cucumber.core.runner.TestStep.run(TestStep.java:74)
at io.cucumber.core.runner.PickleStepTestStep.run(PickleStepTestStep.java:51)
at io.cucumber.core.runner.TestCase.run(TestCase.java:104)
at io.cucumber.core.runner.Runner.runPickle(Runner.java:71)
at io.cucumber.core.runtime.Runtime.lambda$execute$5(Runtime.java:110)
at io.cucumber.core.runtime.Runtime$$Lambda$131/1448525331.accept(Unknown Source)
at io.cucumber.core.runtime.CucumberExecutionContext.runTestCase(CucumberExecutionContext.java:117)
at io.cucumber.core.runtime.Runtime.lambda$execute$6(Runtime.java:110)
at io.cucumber.core.runtime.Runtime$$Lambda$130/1206569586.run(Unknown Source)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at io.cucumber.core.runtime.Runtime$SameThreadExecutorService.execute(Runtime.java:233)
at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:112)
at io.cucumber.core.runtime.Runtime.lambda$run$2(Runtime.java:86)
at io.cucumber.core.runtime.Runtime$$Lambda$129/129153987.apply(Unknown Source)
at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
at java.util.stream.SliceOps$1$1.accept(SliceOps.java:204)
at java.util.ArrayList$ArrayListSpliterator.tryAdvance(ArrayList.java:1359)
at java.util.stream.ReferencePipeline.forEachWithCancel(ReferencePipeline.java:126)
at java.util.stream.AbstractPipeline.copyIntoWithCancel(AbstractPipeline.java:498)
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:485)
at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708)
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499)
at io.cucumber.core.runtime.Runtime.run(Runtime.java:87)
at io.cucumber.core.cli.Main.run(Main.java:92)
at io.cucumber.core.cli.Main.main(Main.java:34)

"VM Thread" os_prio=2 tid=0x0000000039f72800 nid=0x2bc8 runnable 

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00000000028e1800 nid=0x440c runnable 

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00000000028e3800 nid=0x438c runnable 

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00000000028e5000 nid=0x581c runnable 

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00000000028e6800 nid=0x17e4 runnable 

"GC task thread#4 (ParallelGC)" os_prio=0 tid=0x00000000028ea000 nid=0x65f8 runnable 

"GC task thread#5 (ParallelGC)" os_prio=0 tid=0x00000000028eb000 nid=0x24b8 runnable 

"GC task thread#6 (ParallelGC)" os_prio=0 tid=0x00000000028ec000 nid=0x65ac runnable 

"GC task thread#7 (ParallelGC)" os_prio=0 tid=0x00000000028ef800 nid=0x1cfc runnable 

"VM Periodic Task Thread" os_prio=2 tid=0x000000003a052800 nid=0x2c7c waiting on condition 

JNI global references: 796

[prashant-ramcharan]

Hi, I'm unable to reproduce this.

Looking at the stacktrace it looks like the issue is originating from the Cucumber PrettyFormatter.

Can you remove the pretty Cucumber plugin and try again?

1. Does this happen on every machine you run the tests on?
2. Did you try running it in CI or another machine to determine if you get the same result?
3. What version of Java are you using?

[pagmoro]

Hi @prashant-ramcharan ,

Removing the pretty Cucumber plugin does not help. It gets stuck on both my local machine and in Jenkins. I am using Java 1.8 Also , I was unable to reproduce this in the sample project , but it happens consistently for both 5.8.0 and 5.8.1 in my actual project. Again , not a showstopper , but false is the default option for showTestOutput , so would be nice to have it fixed.

Thanks!

[prashant-ramcharan]

Hi @pagmoro

Is it possible to share a demo project that I can use to reproduce this?

I tried with example projects and few of my own personal projects using Java 8 and 11 and I was unable to reproduce this.

[pagmoro]

I was able to reproduce this in my sample project as suspected by introducing file logging (same as my actual project).

I'm attaching the logback-test.xml here , you should be able to reproduce it with this. We have a requirement of logging everything to both the console and a file , this seems to be causing issues with showOutput=false

Gradle Dependencies:

dependencies {
    testImplementation  "io.github.prashant-ramcharan:courgette-jvm:5.8.0"
    testImplementation "ch.qos.logback:logback-classic:1.2.2"
    testImplementation "org.slf4j:slf4j-api:1.7.28"
}

logback-test.xml:

<?xml version='1.0'  encoding='utf-8'?>

  <configuration debug="true" >
   <property name="LOG_DIR" value="${java.io.tmpdir}" />

    <appender name="ROLLING" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_DIR}/pagmoro-test.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${LOG_DIR}/pagmoro-test-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>500MB</maxFileSize>
            <maxHistory>5</maxHistory>
            <cleanHistoryOnStart>true</cleanHistoryOnStart>
        </rollingPolicy>
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{0} - %msg%n</pattern>
        </encoder>
    </appender>

    <appender class="ch.qos.logback.core.ConsoleAppender" name="STDOUT">
        <encoder>
            <pattern>%simtime %d{HH:mm:ss.SSS} [%thread] %-5level %logger{0} - %msg%n </pattern>
        </encoder>
    </appender>

    <root level="INFO">
       <appender-ref ref="ROLLING" />
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

[prashant-ramcharan]

Thanks @pagmoro - I'll take a look.

[prashant-ramcharan]

@pagmoro I still cannot reproduce this even with the logging enabled so it must be related to something else in your project that I don't have in mine.

Project: courgette-jvm-issue-240.zip

I tried with the above project that I just spun up.

Perhaps you can try with this project?

Verified with:

• Java 8
• Gradle 6.2.1

[pagmoro]

Thank you @prashant-ramcharan - I was able to reproduce this in my environment with your project above without any changes. I can see Intellij reporting "Tests passed: 2 of 2 tests" , but the program continues indefinitely apparently doing nothing (possibly waiting on I/O).

If I change one of the Suites to showTestOutput=true , and the other to false , then run the "test" gradle task and kill it after a while of showing nothing on the screen , the logs for Suite with showTestOutput=true is shown after the force stop and as expected the logs for the other Suite (with showTestOutPut=false) is not seen. It does look like it is hung after executing the 2 tests.

Ofcourse if both suites have showTestOutput=true, everything runs fine.

Are you trying this on MacOS? Our Jenkins build is on Linux and my PC is windows , and it fails on both.

Correction: The 2 of 2 Tests is for the one with showTestOutput = true. The tests are not run at all for the other one. 2nd Correction: Appears that after terminating the program all the output appears in the logs

[pagmoro]

Also - I'm assuming the intention of showTestOutput is to control output to the STDOUT only? In my case output is sent to console as well as a log file. Would ideally want file logging to continue , but even if both file logging and console are disabled with showTestOutput=false , the program should not hang. Possibly logback is trying to write but cant.

[prashant-ramcharan]

The showTestOutput simply redirects the output from sub processes (spawned threads) to the main process.

Setting showTestOutput=true does not mean logging to files or the consoles is disabled, it simply means we redirect the output from the sub process to the parent process (i.e the process builder).

When showTestOutput=false, this just means it does not redirect the output to the main process.

Let me run the project I pasted above on Jenkins (linux box) and will see if I can reproduce this.

[prashant-ramcharan]

@pagmoro

Just tried on Jenkins (running in docker on a Linux platform) and I cant reproduce this.

With showTestOutput = false

With showTestOutput = true

[prashant-ramcharan]

I was able to reproduce this on Windows though. I will investigate further.

Thanks.

[prashant-ramcharan]

@pagmoro This should now be fixed in version 5.9.0

[pagmoro]

Thats great! Will revert if any issues. Thank you.

[pagmoro]

Looks good to me - thank you !