[DAEMON-276] commons-daemon.log blows up when stopping Windows service

• Type: Bug
• Status: Resolved
• Priority: Blocker
• Resolution: Fixed
• Affects Version/s: 1.0.12
• Fix Version/s: 1.0.13

Environment

Tomcat 7.0.36 Release candidate, Oracle JRE 7u13 32-bit, Windows 7 Home basic 64-bit

• Assignee: Mladen Turk
• Reporter: Konstantin Kolinko
• Created: 05/Feb/13 00:48
• Updated: 06/Feb/13 12:44
• Resolved: 06/Feb/13 05:21

Description

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.