Community
Participate
Working Groups
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
Note that the kernel smoke test produces the same stack trace, so this may have nothing to do with the new shell.
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)
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.
