Some Eclipse Foundation services are deprecated, or will be soon. Please ensure you've read this important communication.

Bug 350825

Summary: Shutdown command hangs
Product: [RT] Virgo Reporter: Glyn Normington <glyn.normington>
Component: runtimeAssignee: Glyn Normington <glyn.normington>
Status: CLOSED FIXED QA Contact:
Severity: normal    
Priority: P3 CC: b.kapukaranov, hsiliev
Version: 3.0.0.M06   
Target Milestone: 3.0.0.RC1   
Hardware: PC   
OS: Mac OS X - Carbon (unsup.)   
Whiteboard:
Bug Depends on:    
Bug Blocks: 351533    

Description Glyn Normington CLA 2011-06-30 09:35:48 EDT 
The shutdown command produces an enormous stack trace on the console but fails to shut Virgo down:

java.lang.IllegalStateException: The System Bundle could not be resolved: 
	at org.eclipse.osgi.internal.baseadaptor.BaseStorage.checkSystemState(BaseStorage.java:820)
	at org.eclipse.osgi.internal.baseadaptor.BaseStorage.getStateManager(BaseStorage.java:793)
	at org.eclipse.osgi.baseadaptor.BaseAdaptor.getState(BaseAdaptor.java:379)
	at org.eclipse.osgi.framework.internal.core.PackageAdminImpl.doResolveBundles(PackageAdminImpl.java:209)
	at org.eclipse.osgi.framework.internal.core.PackageAdminImpl.resolveBundles(PackageAdminImpl.java:191)
	at org.eclipse.osgi.framework.internal.core.PackageAdminImpl.resolveBundles(PackageAdminImpl.java:183)
	at org.eclipse.osgi.framework.internal.core.BundleHost.checkLoader(BundleHost.java:187)
	at org.eclipse.osgi.framework.internal.core.BundleHost.loadClass(BundleHost.java:225)
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.loadClass(AbstractBundle.java:1207)
	at org.springframework.osgi.util.BundleDelegatingClassLoader.findClass(BundleDelegatingClassLoader.java:99)
	at org.springframework.osgi.util.BundleDelegatingClassLoader.loadClass(BundleDelegatingClassLoader.java:156)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:248)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.loadClass(PackagingDataCalculator.java:198)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.bestEffortLoadClass(PackagingDataCalculator.java:226)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.computeBySTEP(PackagingDataCalculator.java:132)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.populateUncommonFrames(PackagingDataCalculator.java:107)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.populateFrames(PackagingDataCalculator.java:99)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.calculate(PackagingDataCalculator.java:58)
	at ch.qos.logback.classic.spi.ThrowableProxy.calculatePackagingData(ThrowableProxy.java:100)
	at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:126)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:469)
	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:425)
	at ch.qos.logback.classic.Logger.error(Logger.java:588)
	at org.eclipse.virgo.medic.log.osgi.OSGiLogServiceListener.log(OSGiLogServiceListener.java:92)
	at org.eclipse.virgo.medic.log.osgi.OSGiLogServiceListener.logged(OSGiLogServiceListener.java:45)
	at org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory.safeLogged(ExtendedLogReaderServiceFactory.java:84)
	at org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory$LogTask.run(ExtendedLogReaderServiceFactory.java:33)
	at org.eclipse.equinox.log.internal.SerializedTaskQueue$1.run(SerializedTaskQueue.java:33)
java.lang.IllegalStateException: Bundle "file:lib/kernel/org.eclipse.virgo.kernel.shell-3.0.0.BUILD-20110630122727.jar" has been uninstalled
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.checkValid(AbstractBundle.java:1174)
	at org.eclipse.osgi.framework.internal.core.BundleHost.checkLoader(BundleHost.java:183)
	at org.eclipse.osgi.framework.internal.core.BundleHost.loadClass(BundleHost.java:225)
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.loadClass(AbstractBundle.java:1207)
	at org.springframework.osgi.util.BundleDelegatingClassLoader.findClass(BundleDelegatingClassLoader.java:99)
	at org.springframework.osgi.util.BundleDelegatingClassLoader.loadClass(BundleDelegatingClassLoader.java:156)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:248)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.loadClass(PackagingDataCalculator.java:198)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.bestEffortLoadClass(PackagingDataCalculator.java:226)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.computeBySTEP(PackagingDataCalculator.java:132)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.populateUncommonFrames(PackagingDataCalculator.java:107)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.populateFrames(PackagingDataCalculator.java:99)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.calculate(PackagingDataCalculator.java:58)
	at ch.qos.logback.classic.spi.ThrowableProxy.calculatePackagingData(ThrowableProxy.java:100)
	at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:126)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:469)
	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:425)
	at ch.qos.logback.classic.Logger.error(Logger.java:588)
	at org.eclipse.virgo.medic.log.osgi.OSGiLogServiceListener.log(OSGiLogServiceListener.java:92)
	at org.eclipse.virgo.medic.log.osgi.OSGiLogServiceListener.logged(OSGiLogServiceListener.java:45)
	at org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory.safeLogged(ExtendedLogReaderServiceFactory.java:84)
	at org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory$LogTask.run(ExtendedLogReaderServiceFactory.java:33)
	at org.eclipse.equinox.log.internal.SerializedTaskQueue$1.run(SerializedTaskQueue.java:33)
java.lang.IllegalStateException: Bundle "file:lib/kernel/org.eclipse.virgo.kernel.shell-3.0.0.BUILD-20110630122727.jar" has been uninstalled
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.checkValid(AbstractBundle.java:1174)
	at org.eclipse.osgi.framework.internal.core.BundleHost.checkLoader(BundleHost.java:183)
	at org.eclipse.osgi.framework.internal.core.BundleHost.loadClass(BundleHost.java:225)
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.loadClass(AbstractBundle.java:1207)
	at org.springframework.osgi.util.BundleDelegatingClassLoader.findClass(BundleDelegatingClassLoader.java:99)
	at org.springframework.osgi.util.BundleDelegatingClassLoader.loadClass(BundleDelegatingClassLoader.java:156)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:248)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.loadClass(PackagingDataCalculator.java:198)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.bestEffortLoadClass(PackagingDataCalculator.java:226)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.computeBySTEP(PackagingDataCalculator.java:132)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.populateUncommonFrames(PackagingDataCalculator.java:107)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.populateFrames(PackagingDataCalculator.java:99)
	at ch.qos.logback.classic.spi.PackagingDataCalculator.calculate(PackagingDataCalculator.java:58)
	at ch.qos.logback.classic.spi.ThrowableProxy.calculatePackagingData(ThrowableProxy.java:100)
	at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:126)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:469)
	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:425)
	at ch.qos.logback.classic.Logger.error(Logger.java:588)
	at org.eclipse.virgo.medic.log.osgi.OSGiLogServiceListener.log(OSGiLogServiceListener.java:92)
	at org.eclipse.virgo.medic.log.osgi.OSGiLogServiceListener.logged(OSGiLogServiceListener.java:45)
	at org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory.safeLogged(ExtendedLogReaderServiceFactory.java:84)
	at org.eclipse.equinox.log.internal.ExtendedLogReaderServiceFactory$LogTask.run(ExtendedLogReaderServiceFactory.java:33)
	at org.eclipse.equinox.log.internal.SerializedTaskQueue$1.run(SerializedTaskQueue.java:33)

... followed by hundreds more stack frames with the same content
Comment 1 Glyn Normington CLA 2011-07-06 11:28:10 EDT 
Note that the kernel smoke test produces the same stack trace, so this may have nothing to do with the new shell.
Comment 2 Hristo Iliev CLA 2011-07-07 14:46:29 EDT 
After using "shutdown" from the console the thread dump contains clues that the console streams are not stopped, so perhaps this is the reason for the hanging shutdown.

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

"Thread-37" prio=6 tid=0x000000004c663800 nid=0x1008 in Object.wait() [0x00000000559ff000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x000000003a6a3940> (a org.eclipse.equinox.console.common.ConsoleInputStream)
        at java.lang.Object.wait(Object.java:485)
        at org.eclipse.equinox.console.common.ConsoleInputStream.read(ConsoleInputStream.java:30)
        - locked <0x000000003a6a3940> (a org.eclipse.equinox.console.common.ConsoleInputStream)
        at org.eclipse.equinox.console.common.ConsoleInputStream.read(ConsoleInputStream.java:121)
        - locked <0x000000003a6a3940> (a org.eclipse.equinox.console.common.ConsoleInputStream)
        at java.io.InputStream.read(InputStream.java:85)
        at org.eclipse.equinox.console.common.InputHandler.run(InputHandler.java:42)

"Thread-36" prio=6 tid=0x000000004c663000 nid=0xcf4 runnable [0x00000000558ff000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:129)
        at java.net.SocketInputStream.read(SocketInputStream.java:90)
        at org.eclipse.equinox.console.common.InputHandler.run(InputHandler.java:42)

"Thread-35" prio=6 tid=0x000000004d091000 nid=0xea4 in Object.wait() [0x00000000557fe000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x000000003a6c6440> (a org.eclipse.equinox.console.common.ConsoleInputStream)
        at java.lang.Object.wait(Object.java:485)
        at org.eclipse.equinox.console.common.ConsoleInputStream.read(ConsoleInputStream.java:30)
        - locked <0x000000003a6c6440> (a org.eclipse.equinox.console.common.ConsoleInputStream)
        at org.apache.felix.gogo.shell.Console.getLine(Console.java:117)
        at org.apache.felix.gogo.shell.Console.run(Console.java:53)
        at org.apache.felix.gogo.shell.Shell.console(Shell.java:203)
        at org.apache.felix.gogo.shell.Shell.gosh(Shell.java:128)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.apache.felix.gogo.runtime.Reflective.method(Reflective.java:136)
        at org.apache.felix.gogo.runtime.CommandProxy.execute(CommandProxy.java:82)
        at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:469)
        at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:395)
        at org.apache.felix.gogo.runtime.Pipe.run(Pipe.java:108)
        at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:183)
        at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:120)
        at org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.java:89)
        at org.eclipse.equinox.console.telnet.TelnetConnection.run(TelnetConnection.java:94)

"DestroyJavaVM" prio=6 tid=0x000000004cd42800 nid=0x880 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"RMI TCP Accept-0" daemon prio=6 tid=0x000000004c574800 nid=0xf58 runnable [0x000000004ca0f000]
   java.lang.Thread.State: RUNNABLE
        at java.net.PlainSocketImpl.socketAccept(Native Method)
        at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:390)
        - locked <0x000000000b0c4da0> (a java.net.SocksSocketImpl)
        at java.net.ServerSocket.implAccept(ServerSocket.java:453)
        at java.net.ServerSocket.accept(ServerSocket.java:421)
        at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(LocalRMIServerSocketFactory.java:34)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:369)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:341)
        at java.lang.Thread.run(Thread.java:619)

"RMI TCP Accept-9875" daemon prio=6 tid=0x000000004c574000 nid=0xab0 runnable [0x000000004c46f000]
   java.lang.Thread.State: RUNNABLE
        at java.net.PlainSocketImpl.socketAccept(Native Method)
        at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:390)
        - locked <0x000000000b02fb58> (a java.net.SocksSocketImpl)
        at java.net.ServerSocket.implAccept(ServerSocket.java:453)
        at java.net.ServerSocket.accept(ServerSocket.java:421)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:369)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:341)
        at java.lang.Thread.run(Thread.java:619)

"RMI TCP Accept-0" daemon prio=6 tid=0x000000004c6c1800 nid=0xa7c runnable [0x000000004c2af000]
   java.lang.Thread.State: RUNNABLE
        at java.net.PlainSocketImpl.socketAccept(Native Method)
        at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:390)
        - locked <0x000000000b0c4a28> (a java.net.SocksSocketImpl)
        at java.net.ServerSocket.implAccept(ServerSocket.java:453)
        at java.net.ServerSocket.accept(ServerSocket.java:421)
        at javax.rmi.ssl.SslRMIServerSocketFactory$1.accept(SslRMIServerSocketFactory.java:191)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:369)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:341)
        at java.lang.Thread.run(Thread.java:619)

"Low Memory Detector" daemon prio=6 tid=0x000000004b706800 nid=0x1090 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=10 tid=0x000000004b704000 nid=0x2a4 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x0000000000629000 nid=0xecc waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Attach Listener" daemon prio=10 tid=0x0000000000628000 nid=0xe70 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x0000000000627000 nid=0x88c waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=8 tid=0x0000000000614800 nid=0xa94 in Object.wait() [0x000000004b6bf000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x000000000ad762d0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
        - locked <0x000000000ad762d0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x000000000060c000 nid=0x4d8 in Object.wait() [0x000000004b5bf000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x000000000ad76248> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:485)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
        - locked <0x000000000ad76248> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x0000000000604000 nid=0x650 runnable

"GC task thread#0 (ParallelGC)" prio=6 tid=0x0000000000563800 nid=0x68c runnable

"GC task thread#1 (ParallelGC)" prio=6 tid=0x0000000000565800 nid=0x598 runnable

"VM Periodic Task Thread" prio=10 tid=0x000000004c62e000 nid=0x290 waiting on condition

JNI global references: 1187

Heap
 PSYoungGen      total 335040K, used 188317K [0x00000000355b0000, 0x000000004ab00000, 0x000000004ab00000)
  eden space 323776K, 55% used [0x00000000355b0000,0x00000000403a00a8,0x00000000491e0000)
  from space 11264K, 90% used [0x000000004a000000,0x000000004a9f74a8,0x000000004ab00000)
  to   space 12864K, 0% used [0x00000000491e0000,0x00000000491e0000,0x0000000049e70000)
 PSOldGen        total 43712K, used 28796K [0x000000000ab00000, 0x000000000d5b0000, 0x00000000355b0000)
  object space 43712K, 65% used [0x000000000ab00000,0x000000000c71f0c0,0x000000000d5b0000)
 PSPermGen       total 48896K, used 48836K [0x0000000005700000, 0x00000000086c0000, 0x000000000ab00000)
  object space 48896K, 99% used [0x0000000005700000,0x00000000086b12a8,0x00000000086c0000)
Comment 3 Glyn Normington CLA 2011-07-08 05:57:22 EDT 
Fixed an NPE in the shell which seems to cause the problem. See kernel commit 6beb6a4bee22a1929bb7574845624f3fa076af2e.

Now shutdown from the shell results in shutdown messages appearing in the shell, which is a bit funky and is certainly not the way we have seen this work in the past. I raised bug 351533 to capture this.