CODEWITHSUNDEEP
apache-cameljava-service-wrapper
erezul
erezul

Reputation: 527

Tanuki service wrapper starts Camel OK and IMMEDIATELY shuts it down

I'm trying to run a Camel (Spring based) project on tanuki service wrapper as a windows service. I tried both integration methods #1 and #2: WrapperSimpleApp, WrapperStartStopApp and both resulted in the following behavior:

Camel started OK and IMMEDIATELY wrapper shuts it down!

At first I suspected this has to do with Camel non daemon threads, but after playing with the integration methods and org.tanukisoftware.wrapper.WrapperStartStopApp.systemThreadCount system property, I realized there must be another reason why wrapper shuts down the JVM.

Would anyone know why?

Here is wrapper and Camel log - note 2nd and 3rd lines:

INFO   | jvm 1    | 2012/09/01 20:39:45.643 | srvmain | 2012-09-01 20:39:45,596     INFO  spring.SpringCamelContext Apache Camel 2.6.0 (CamelContext: main-camel-context) started in 1.450 seconds
INFO   | jvm 1    | 2012/09/01 20:39:45.643 | srvmain | WrapperSimpleApp Debug: main method completed
INFO   | jvm 1    | 2012/09/01 20:39:45.643 | srvmain | WrapperManager Debug: ShutdownHook started
INFO   | jvm 1    | 2012/09/01 20:39:45.643 | srvmain | WrapperManager Debug: WrapperManager.stop(0) called by thread: Wrapper-Shutdown-Hook
INFO   | jvm 1    | 2012/09/01 20:39:45.643 | srvmain | WrapperManager Debug: Send a packet STOP : 0
INFO   | jvm 1    | 2012/09/01 20:39:45.643 | srvmain | WrapperManager Debug: Pausing for 1,000ms to allow a clean shutdown...
DEBUG  | wrapperp | 2012/09/01 20:39:45.643 | srvmain | read a packet STOP : 0
DEBUG  | wrapper  | 2012/09/01 20:39:45.643 | srvmain | JVM requested a shutdown. (0)
DEBUG  | wrapper  | 2012/09/01 20:39:45.643 | srvmain | wrapperStopProcess(0, FALSE) called.
DEBUG  | wrapper  | 2012/09/01 20:39:45.643 | srvmain | Sending stop signal to JVM
DEBUG  | wrapperp | 2012/09/01 20:39:45.643 | srvmain | send a packet STOP : NULL
INFO   | jvm 1    | 2012/09/01 20:39:45.752 | srvmain | WrapperManager Debug: Received a packet STOP :
INFO   | jvm 1    | 2012/09/01 20:39:45.752 | srvmain | WrapperManager Debug: Stopped checking for control events.
INFO   | jvm 1    | 2012/09/01 20:39:46.735 | srvmain | WrapperManager Debug: Thread, Wrapper-Shutdown-Hook, handling the shutdown process.
INFO   | jvm 1    | 2012/09/01 20:39:46.735 | srvmain | WrapperManager Debug: calling listener.stop()
INFO   | jvm 1    | 2012/09/01 20:39:46.735 | srvmain | WrapperSimpleApp Debug: stop(0)
INFO   | jvm 1    | 2012/09/01 20:39:46.735 | srvmain | WrapperManager Debug: returned from listener.stop() -> 0
INFO   | jvm 1    | 2012/09/01 20:39:46.735 | srvmain | WrapperManager Debug: shutdownJVM(0) Thread: Wrapper-Shutdown-Hook
INFO   | jvm 1    | 2012/09/01 20:39:46.735 | srvmain | WrapperManager Debug: wait for 0 shutdown locks to be released.
INFO   | jvm 1    | 2012/09/01 20:39:46.735 | srvmain | WrapperManager Debug: Send a packet STOPPED : 0
DEBUG  | wrapperp | 2012/09/01 20:39:46.735 | srvmain | read a packet STOPPED : 0
DEBUG  | wrapper  | 2012/09/01 20:39:46.735 | srvmain | JVM signaled that it was stopped.
INFO   | jvm 1    | 2012/09/01 20:39:46.954 | srvmain | WrapperManager Debug: Closing backend connection.
INFO   | jvm 1    | 2012/09/01 20:39:46.954 | srvmain | WrapperManager Debug: Closed backend socket (Normal): java.net.SocketException: socket closed
INFO   | jvm 1    | 2012/09/01 20:39:46.954 | srvmain | WrapperManager Debug: Returned from backend handler.
DEBUG  | wrapperp | 2012/09/01 20:39:46.954 | srvmain | socket read no code (closed?).
DEBUG  | wrapperp | 2012/09/01 20:39:46.954 | srvmain | Closing backend socket.
INFO   | jvm 1    | 2012/09/01 20:39:47.500 | srvmain | WrapperManager Debug: Server daemon shut down
INFO   | jvm 1    | 2012/09/01 20:39:47.500 | srvmain | WrapperManager Debug: ShutdownHook complete
ERROR  | wrapper  | 2012/09/01 20:40:07.608 | srvmain | Shutdown failed: Timed out waiting for the JVM to terminate.
ERROR  | wrapper  | 2012/09/01 20:40:07.827 | srvmain | JVM did not exit on request, terminated
STATUS | wrapper  | 2012/09/01 20:40:08.778 | srvmain | <-- Wrapper Stopped

Here is a thread dump I ran on Camel (standalone):

"RMI TCP Connection(idle)" daemon prio=6 tid=0x000000000f194800 nid=0x1a24 waiting on condition [0x000000001062e000]
"RMI TCP Connection(6)-10.244.123.73" daemon prio=6 tid=0x000000000f194000 nid=0x1218 runnable [0x000000001038e000]
"RMI TCP Connection(4)-10.244.123.73" daemon prio=6 tid=0x000000000f193000 nid=0x188c in Object.wait() [0x00000000104ad000]
"RMI TCP Connection(idle)" daemon prio=6 tid=0x000000000eb1f000 nid=0xbf8 waiting on condition [0x000000001020f000]
"JMX server connection timeout 20" daemon prio=6 tid=0x000000000e4e1800 nid=0x1804 in Object.wait() [0x00000000100af000]
"RMI TCP Connection(idle)" daemon prio=6 tid=0x000000000eba3000 nid=0x10e8 waiting on condition [0x000000000fe7e000]
"RMI Scheduler(0)" daemon prio=6 tid=0x000000000f5c3000 nid=0x103c waiting on condition [0x000000000ff8f000]
"RMI TCP Connection(idle)" daemon prio=6 tid=0x000000000e0d0800 nid=0xd5c waiting on condition [0x000000000fd1e000]
"Camel (main-camel-context) thread #1 - file://./toAggregator" daemon prio=6 tid=0x000000000e0bf800 nid=0x18e4 runnable [0x000000000dcaf000]
"Camel (main-camel-context) thread #0 - AggregateTimeoutChecker" daemon prio=6 tid=0x000000000ecad800 nid=0x1b54 waiting on condition [0x000000000fb6f
"RMI TCP Accept-0" daemon prio=6 tid=0x000000000d4e6800 nid=0x1ba0 runnable [0x000000000de0e000]
"RMI TCP Accept-7780" daemon prio=6 tid=0x000000000d586800 nid=0xff0 runnable [0x000000000e8fe000]
"RMI TCP Accept-0" daemon prio=6 tid=0x000000000d55e000 nid=0x38c runnable [0x000000000e7df000]
"Service Thread" daemon prio=6 tid=0x000000000b7d3800 nid=0x1980 runnable [0x0000000000000000]
"C2 CompilerThread1" daemon prio=10 tid=0x000000000b7d0800 nid=0x1be4 waiting on condition [0x0000000000000000]
"C2 CompilerThread0" daemon prio=10 tid=0x000000000b7c3800 nid=0x594 waiting on condition [0x0000000000000000]
"Attach Listener" daemon prio=10 tid=0x000000000b7c2800 nid=0x10bc runnable [0x0000000000000000]
"Signal Dispatcher" daemon prio=10 tid=0x000000000b7bb000 nid=0x1b2c waiting on condition [0x0000000000000000]
"Finalizer" daemon prio=8 tid=0x0000000002416000 nid=0x1b94 in Object.wait() [0x000000000cd5e000]
"Reference Handler" daemon prio=10 tid=0x000000000240f000 nid=0x9a0 in Object.wait() [0x000000000caae000]
"Thread-1" prio=6 tid=0x000000000e530800 nid=0xc50 runnable [0x000000000da7f000]
"DestroyJavaVM" prio=6 tid=0x000000000231f000 nid=0x199c in Object.wait() [0x00000000026ff000]
"VM Thread" prio=10 tid=0x000000000b732800 nid=0x17a0 runnable
"GC task thread#0 (ParallelGC)" prio=6 tid=0x0000000002365000 nid=0x1a94 runnable
"GC task thread#1 (ParallelGC)" prio=6 tid=0x0000000002367000 nid=0x4e8 runnable
"GC task thread#2 (ParallelGC)" prio=6 tid=0x0000000002368800 nid=0xf44 runnable
"GC task thread#3 (ParallelGC)" prio=6 tid=0x000000000236a000 nid=0xd30 runnable
"VM Periodic Task Thread" prio=10 tid=0x000000000d4fb800 nid=0x384 waiting on condition

Upvotes: 1

Views: 1154

Answers (1)

erezul
erezul

Reputation: 527

Well, the issue was indeed lake of non daemon threads, due to the way Camel was started.

Camel was started using oeg.apache.camel.spring.Main.start() rather than run().

start() just starts Camel counting on the main thread to somehow keep running. this is suitable when running in an application. run(), on the other hand, blocks the main thread till Camel or the JVM exit.

It is also usefull to call enableHangupSupport() to register a shutdown hook to allow Camel to gracefully shutdown on JVM exit.

I must give credit where credit is due :-) thanks to the super professional team of tanuki java service wrapper for figuring this out for me.

Upvotes: 1

Related Questions