commons-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Rainer Jung (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (DAEMON-276) commons-daemon.log blows up when stopping Windows service
Date Tue, 05 Feb 2013 11:27:13 GMT

    [ 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

Mime
View raw message