IllegalThreadStateException on shutdown from maven exec plugin

[davidmoten]

When I run a java program that uses RxJava via the maven exec plugin (mvn exec:java) I get this warning on program completion.

[WARNING] NOTE: 1 thread(s) did not finish despite being asked to  via interruption. This is not a problem with exec:java, it is a problem with the running code. Although not serious, it should be remedied.

Is this something we can address?

Full trace:

[WARNING] Warning: killAfter is now deprecated. Do you need it ? Please comment on MEXEC-6.
[WARNING] thread Thread[RxComputationThreadPool-1,5,au.gov.amsa.risky.format.NetcdfFixesWriterMain] was interrupted but is still alive after waiting at least 14999msecs
[WARNING] thread Thread[RxComputationThreadPool-1,5,au.gov.amsa.risky.format.NetcdfFixesWriterMain] will linger despite being asked to die via interruption
[WARNING] NOTE: 1 thread(s) did not finish despite being asked to  via interruption. This is not a problem with exec:java, it is a problem with the running code. Although not serious, it should be remedied.
[WARNING] Couldn't destroy threadgroup org.codehaus.mojo.exec.ExecJavaMojo$IsolatedThreadGroup[name=au.gov.amsa.risky.format.NetcdfFixesWriterMain,maxpri=10]
java.lang.IllegalThreadStateException
        at java.lang.ThreadGroup.destroy(ThreadGroup.java:775)
        at org.codehaus.mojo.exec.ExecJavaMojo.execute(ExecJavaMojo.java:328)
        at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:101)
        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:209)
        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
        at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
        at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:84)
        at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:59)
        at org.apache.maven.lifecycle.internal.LifecycleStarter.singleThreadedBuild(LifecycleStarter.java:183)
        at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:161)
        at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:320)
        at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:156)
        at org.apache.maven.cli.MavenCli.execute(MavenCli.java:537)
        at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:196)
        at org.apache.maven.cli.MavenCli.main(MavenCli.java:141)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
        at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
        at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
        at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)

[akarnokd]

Can you do a threaddump in that 15 seconds to see who is blocking the executor?

[davidmoten]

This is the program I ran

import rx.Observable;
import rx.schedulers.Schedulers;

public class Main {
    public static void main(String[] args) throws InterruptedException {
        Observable.just(1).subscribeOn(Schedulers.computation()).toBlocking()
                .first();
        System.out.println("finished");
    }
}

Here's the thread dump during the 15s wait:

Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.40-b25 mixed mode):

"Attach Listener" #13 daemon prio=9 os_prio=0 tid=0x00007fc908001000 nid=0xd7b runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"RxComputationThreadPool-1" #12 daemon prio=5 os_prio=0 tid=0x00007fc8f4020000 nid=0xd52 waiting on condition [0x00007fc921365000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000ef864920> (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:1067)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

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

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

"C2 CompilerThread2" #7 daemon prio=9 os_prio=0 tid=0x00007fc9540c5000 nid=0xd4d waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007fc9540c3800 nid=0xd4c waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007fc9540c0800 nid=0xd4b waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

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

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007fc954087000 nid=0xd49 in Object.wait() [0x00007fc922e48000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
    - locked <0x00000000f2585148> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007fc954084800 nid=0xd48 in Object.wait() [0x00007fc922f49000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
    - locked <0x00000000f259a048> (a java.lang.ref.Reference$Lock)

"main" #1 prio=5 os_prio=0 tid=0x00007fc95400a000 nid=0xd3e in Object.wait() [0x00007fc959f80000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.lang.Thread.join(Thread.java:1253)
    - locked <0x00000000ef8c1770> (a java.lang.Thread)
    at org.codehaus.mojo.exec.ExecJavaMojo.joinThread(ExecJavaMojo.java:408)
    at org.codehaus.mojo.exec.ExecJavaMojo.terminateThreads(ExecJavaMojo.java:451)
    at org.codehaus.mojo.exec.ExecJavaMojo.execute(ExecJavaMojo.java:324)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:133)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:208)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:108)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:76)
    at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
    at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:116)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:361)
    at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:155)
    at org.apache.maven.cli.MavenCli.execute(MavenCli.java:584)
    at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:213)
    at org.apache.maven.cli.MavenCli.main(MavenCli.java:157)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
    at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
    at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)

"VM Thread" os_prio=0 tid=0x00007fc95407f800 nid=0xd47 runnable 

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007fc95401f000 nid=0xd3f runnable 

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007fc954021000 nid=0xd40 runnable 

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007fc954022800 nid=0xd41 runnable 

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007fc954024800 nid=0xd42 runnable 

"GC task thread#4 (ParallelGC)" os_prio=0 tid=0x00007fc954026000 nid=0xd43 runnable 

"GC task thread#5 (ParallelGC)" os_prio=0 tid=0x00007fc954028000 nid=0xd44 runnable 

"GC task thread#6 (ParallelGC)" os_prio=0 tid=0x00007fc954029800 nid=0xd45 runnable 

"GC task thread#7 (ParallelGC)" os_prio=0 tid=0x00007fc95402b800 nid=0xd46 runnable 

"VM Periodic Task Thread" os_prio=0 tid=0x00007fc9540d7000 nid=0xd50 waiting on condition 

JNI global references: 48

[akarnokd]

Sending interrupt to a threadpool doesn't work; one needs to call shutdown on them directly. But since RxJava doesn't support shutdown, you can't really do this.

[davidmoten]

Could we support manual shutdown so that I can make some call to a static method at the end of my program and have stuff cleaned up?

[akarnokd]

There was a PR for shutting down schedulers (and allow them to start again) but it died.

[akarnokd]

Is this still relevant? Maybe we should reopen/continue a discussion about shutdownable schedulers elsewhere.

[akarnokd]

See #3149.