[
https://issues.apache.org/jira/browse/DAEMON-276?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13571233#comment-13571233
]
Rainer Jung commented on DAEMON-276:
------------------------------------
I could reproduce on Win 7 Pro 64 Bits.
First tried with JRE 1.6.0_39, no problem. Then tried with 1.7.0_13 and after
some retsarts suddenly it could no longer restart (stopped but did not start up
again). From then on all start attempts failed with a timeout. Popup says error
1053, event log says 7009 and 7000 (30000 ms timeout).
When starting tomcat7.exe from the commendline, it starts, but takes longer
than 30 seconds:
[2013-02-05 12:00:46] [info] [19204] Commons Daemon procrun (1.0.12.0 64-bit)
started
[2013-02-05 12:01:02] [info] [19204] Debugging 'Tomcat7' service...
[2013-02-05 12:01:18] [info] [19204] Starting service...
[2013-02-05 12:01:34] [info] [19204] Service started in 1138 ms.
Tomcat logging starts at:
05.02.2013 12:01:34 org.apache.catalina.core.AprLifecycleListener init
so about 48 seconds somewhere in the service code.
In addition the following things seem strange in the daemon logging:
Error during restart:
[2013-02-05 11:50:06] [info] [ 7820] Stopping service...
[2013-02-05 11:50:07] [info] [ 7820] Service stopped.
[2013-02-05 11:50:07] [info] [11636] Run service finished.
[2013-02-05 11:50:07] [error] [ 7820] Failed to set service status
[2013-02-05 11:50:07] [info] [11636] Commons Daemon procrun finished
[2013-02-05 11:50:07] [info] [10912] Commons Daemon procrun (1.0.12.0 64-bit)
started
[2013-02-05 11:50:07] [info] [10912] Running 'Tomcat7' Service...
[2013-02-05 11:50:07] [info] [16536] Starting service...
[2013-02-05 11:50:09] [info] [16536] Service started in 1138 ms.
Error during stop:
[2013-02-05 11:50:42] [info] [18852] Stopping service...
[2013-02-05 11:50:43] [info] [18852] Service stopped.
[2013-02-05 11:50:43] [error] [18852] Failed to set service status
[2013-02-05 11:50:43] [error] [18852] Das Handle ist ungültig.
[2013-02-05 11:50:43] [info] [ 1160] Run service finished.
[2013-02-05 11:50:43] [info] [ 1160] Commons Daemon procrun finished
Suspicious truncated/joined log line during restart:
[2013-02-05 11:50:27] [info] [16244] Stopping service...
[2013-02-05 11:50:28] [info] [16244] Service stopped.
[2013-02-05 11:50:28] [info] [ 8396] Run service finished.
[2013-02-05 11:50:28] [info] [2013-02-05 11:50:28] [info] [10764] Commons
Daemon procrun (1.0.12.0 64-bit) started
[2013-02-05 11:50:28] [info] [10764] Running 'Tomcat7' Service...
[2013-02-05 11:50:28] [info] [17508] Starting service...
[2013-02-05 11:50:30] [info] [17508] Service started in 1123 ms.
Once the service is in this state, I found no way of making it start/stop
quickly again (didn't try rebooting).
Following are three thread stacks I copied using SysInternals ProcExp during
hanging service startup. There was only one thread in the process:
ntoskrnl.exe!KeWaitForMultipleObjects+0xc0a
ntdll.dll!NtDelayExecution+0xa
KERNELBASE.dll!SleepEx+0xb3
Tomcat7.exe+0x583b
Tomcat7.exe+0xec60
Tomcat7.exe+0xf2a9
kernel32.dll!BaseThreadInitThunk+0xd
ntdll.dll!RtlUserThreadStart+0x21
ntoskrnl.exe!KeWaitForMultipleObjects+0xc0a
ntoskrnl.exe!KeAcquireSpinLockAtDpcLevel+0x732
ntoskrnl.exe!KeWaitForMutexObject+0x19f
ntoskrnl.exe!_misaligned_access+0xba4
ntoskrnl.exe!_misaligned_access+0x1821
ntoskrnl.exe!KeAcquireSpinLockAtDpcLevel+0x93d
ntoskrnl.exe!KeDelayExecutionThread+0x186
ntoskrnl.exe!NtWaitForSingleObject+0x17a
ntoskrnl.exe!KeSynchronizeExecution+0x3a23
ntdll.dll!NtDelayExecution+0xa
KERNELBASE.dll!SleepEx+0xb3
Tomcat7.exe+0x583b
Tomcat7.exe+0xec60
Tomcat7.exe+0xf2a9
kernel32.dll!BaseThreadInitThunk+0xd
ntdll.dll!RtlUserThreadStart+0x21
ntoskrnl.exe!KeWaitForMultipleObjects+0xc0a
ntoskrnl.exe!KeAcquireSpinLockAtDpcLevel+0x732
ntoskrnl.exe!KeWaitForMutexObject+0x19f
ntoskrnl.exe!_misaligned_access+0xba4
ntoskrnl.exe!_misaligned_access+0x1821
ntoskrnl.exe!KeAcquireSpinLockAtDpcLevel+0x93d
ntoskrnl.exe!KeDelayExecutionThread+0x186
ntoskrnl.exe!NtWaitForSingleObject+0x17a
ntoskrnl.exe!KeSynchronizeExecution+0x3a23
ntdll.dll!NtDelayExecution+0xa
KERNELBASE.dll!SleepEx+0xb3
Tomcat7.exe+0x583b
Tomcat7.exe+0xe96e
Tomcat7.exe+0xed9b
Tomcat7.exe+0xf2a9
kernel32.dll!BaseThreadInitThunk+0xd
ntdll.dll!RtlUserThreadStart+0x21
> commons-daemon.log blows up when stopping Windows service
> ---------------------------------------------------------
>
> Key: DAEMON-276
> URL: https://issues.apache.org/jira/browse/DAEMON-276
> Project: Commons Daemon
> Issue Type: Bug
> Affects Versions: 1.0.12
> Environment: Tomcat 7.0.36 Release candidate, Oracle JRE 7u13 32-bit,
> Windows 7 Home basic 64-bit
> Reporter: Konstantin Kolinko
> Assignee: Mladen Turk
> Priority: Blocker
> Attachments: logs_Win7_2.zip, logs_WinXP_3.zip
>
>
> Encountered this when testing Tomcat 7.0.36 RC installed as a service. On
> Windows 7, using JRE 7u13.
> Steps to reproduce:
> 1. Start Tomcat service
> 2. Wait until all web applications start up
> 3. Restart the service
> 4. Windows says that the service cannot be started.
> At this point the commons-daemon.2013-02-05.log file started to grow rapidly.
> In half a minute it grew up to several Gb.
> This can be resolved by killing Tomcat7.exe via Task manager.
> In the log file I see
> [2013-02-05 03:44:38] [info] [11996] Commons Daemon procrun (1.0.12.0
> 32-bit) started
> [2013-02-05 03:44:38] [info] [11996] Running 'Tomcat7' Service...
> [2013-02-05 03:44:38] [info] [11980] Starting service...
> [2013-02-05 03:44:39] [info] [11980] Service started in 1357 ms.
> [2013-02-05 03:45:48] [info] [12276] Stopping service...
> [2013-02-05 03:45:49] [info] [12276] Service stopped.
> [2013-02-05 03:45:49] [info]
> The last line is followed by several Gb of nul character. In hex editor:
> 00000001A0: 39 5D 20 5B 69 6E 66 6F ¦ 5D 20 20 00 00 00 00 00 9] [info]
> 00000001B0: 00 00 00 00 00 00 00 00 ¦ 00 00 00 00 00 00 00 00
> 00000001C0: 00 00 00 00 00 00 00 00 ¦ 00 00 00 00 00 00 00 00
> I tried to reproduce this by stopping or by restarting the service, but this
> rapid growth of the log file did not occur. There is a different evidence,
> though.
> The log file below was produced by the following actions:
> 1. Start
> 2. Stop
> 3. Start
> 4. Restart
> This produced the following:
> [2013-02-05 04:14:15] [info] [ 3988] Commons Daemon procrun (1.0.12.0
> 32-bit) started
> [2013-02-05 04:14:15] [info] [ 3988] Running 'Tomcat7' Service...
> [2013-02-05 04:14:15] [info] [ 1536] Starting service...
> [2013-02-05 04:14:16] [info] [ 1536] Service started in 1357 ms.
> [2013-02-05 04:15:36] [info] [ 3456] Stopping service...
> [2013-02-05 04:15:37] [info] [ 3456] Service stopped.
> [2013-02-05 04:15:37] [info] [ 3988] Run service finished.
> [2013-02-05 04:15:37] [info] [ 3988] Commons Daemon procrun finished
> [2013-02-05 04:17:32] [info] [ 3968] Commons Daemon procrun (1.0.12.0
> 32-bit) started
> [2013-02-05 04:17:32] [info] [ 3968] Running 'Tomcat7' Service...
> [2013-02-05 04:17:32] [info] [ 3552] Starting service...
> [2013-02-05 04:17:34] [info] [ 3552] Service started in 1310 ms.
> [2013-02-05 04:18:29] [info] [ 3764] Stopping service...
> [2013-02-05 04:18:30] [info] [ 3764] Service stopped.
> [2013-02-05 04:18:30] [ 3968] Run service finished.
> [2013-02-05 04:18:30] [info] [ 3968] Commons Daemon procrun finished
> [2013-02-05 04:18:31] [info] [ 1260] Commons Daemon procrun (1.0.12.0
> 32-bit) started
> [2013-02-05 04:18:31] [info] [ 1260] Running 'Tomcat7' Service...
> [2013-02-05 04:18:31] [info] [ 1204] Starting service...
> [2013-02-05 04:18:32] [info] [ 1204] Service started in 1357 ms.
> There is a problem with a line at "2013-02-05 04:18:30" (Run service
> finished). The "[info] " characters are missing.
> Note that the same line at "2013-02-05 04:15:37" was printed correctly.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
