Tomcat's log files rolled over daily but some of today's logs still recorded to yesterday's log file

[Simon McCorkindale <Si...@patsystems.com>]

Hi all,

I have an issue that's somewhat stumping me after having spent several
hours pouring over forums and documents.

Problem:
-------------

I have Tomcat's log file xxx.log defined in
/usr/local/jakarta-tomcat-5.0.28/common/classes/log4j.properties (see
below for its contents) to roll over each day to xxx.log.YYYY-MM-DD.
However, although most of today's log entries are correctly logged into
today's xxx.log, the entries below keep getting logged to yesterday's
xxx.log.YYYY-MM-DD. 

2008-07-03 08:12:27,055 [TP-Processor3] INFO  - connection timeout
reached

... same message is repeated at irregular intervals during the day...
then the machine is manually rebooted in the evening at about
18:00-19:00...

2008-07-03 18:06:30,365 [TP-Processor8] INFO  - connection timeout
reached
2008-07-03 18:16:35,826 [Thread-32] INFO  - Pausing Coyote HTTP/1.1 on
http-8585
2008-07-03 18:16:35,845 [Thread-32] ERROR - Protocol handler pause
failed
java.net.SocketException: Network is unreachable
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:305)
        at
java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:171)
        at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:158)
        at java.net.Socket.connect(Socket.java:452)
        at java.net.Socket.connect(Socket.java:402)
        at java.net.Socket.<init>(Socket.java:309)
        at java.net.Socket.<init>(Socket.java:153)
        at
org.apache.jk.common.ChannelSocket.unLockSocket(ChannelSocket.java:460)
        at
org.apache.jk.common.ChannelSocket.pause(ChannelSocket.java:272)
        at org.apache.jk.server.JkMain.pause(JkMain.java:657)
        at
org.apache.jk.server.JkCoyoteHandler.pause(JkCoyoteHandler.java:202)
        at
org.apache.coyote.tomcat5.CoyoteConnector.pause(CoyoteConnector.java:144
4)
        at
org.apache.catalina.core.StandardService.stop(StandardService.java:521)
        at
org.apache.catalina.core.StandardServer.stop(StandardServer.java:2347)
        at org.apache.catalina.startup.Catalina.stop(Catalina.java:605)
        at
org.apache.catalina.startup.Catalina$CatalinaShutdownHook.run(Catalina.j
ava:648)
2008-07-03 18:16:36,848 [Thread-32] INFO  - Stopping service Catalina
2008-07-03 18:16:36,849 [Thread-32] INFO  - Removing web application at
context path /app1
2008-07-03 18:16:36,854 [Thread-32] INFO  - unregistering logger
Catalina:type=Logger,path=/app1,host=localhost
2008-07-03 18:16:36,855 [Thread-32] INFO  - Removing web application at
context path /app2
2008-07-03 18:16:36,862 [Thread-32] INFO  - unregistering logger
Catalina:type=Logger,path=/app2,host=localhost
2008-07-03 18:16:36,863 [Thread-32] INFO  - Removing web application at
context path /app3
2008-07-03 18:16:37,293 [Thread-32] INFO  - Waiting for 2 instance(s) to
be deallocated
2008-07-03 18:16:38,388 [Thread-32] INFO  - Waiting for 2 instance(s) to
be deallocated
2008-07-03 18:16:39,488 [Thread-32] INFO  - Waiting for 2 instance(s) to
be deallocated
2008-07-03 18:16:39,601 [Thread-32] INFO  - unregistering logger
Catalina:type=Logger,path=/app3,host=localhost
2008-07-03 18:16:39,638 [Thread-32] INFO  - Removing web application at
context path /app2
2008-07-03 18:16:39,648 [Thread-32] INFO  - unregistering logger
Catalina:type=Logger,host=localhost
2008-07-03 18:16:39,649 [Thread-32] INFO  - unregistering logger
Catalina:type=Logger
2008-07-03 18:16:39,650 [Thread-32] INFO  - Stopping Coyote HTTP/1.1 on
http-8585

Before the server is rebooted in the evening, a "$lsof | grep xxx.log"
shoes that both today's and yesterday's logs are opened by the same JVM
process. After the server is rebooted, I see only today's xxx.log is
opened twice by the same JVM process. My guess is that whatever Java
thread writes the first log entry of the following day, kicks log4j to
actually roll over  the log file, but the other Java thread is not
updated, thus it's file handle seems to still point to xxx.log, which is
where the split starts to happen.

1) Has anybody seen such problems as this before?

2) Is there a way to see what files are currently open by what threads
within a JVM process? That way I could try and track down who is the
culprit still clinging onto the stale file handle. Going on the log
entries above it seems Tomcat's JK / Coyote connectors are incorrectly
logging the "correction timeout reached" records into yesterday's file

The setup:
---------------

- 3 Red Hat Enterprise Linux AS3 servers
- Apache v2.0.54 on the first server
- Tomcat v5.0.28 load balanced on the 3 servers (and the log4j.jar that
comes with Tomcat v5.0.28)
- mod_jk2 v1.2.5
- Java SDK 1.4.2

Configuration files:
--------------------------

/usr/webapp/jakarta-tomcat-5.0.28/common/classes/log4j.properties:

log4j.rootLogger=INFO,R
log4j.appender.R=org.apache.log4j.DailyRollingFileAppender
log4j.appender.R.File=/path/to/tomcat/logs/xxx.log
log4j.appender.R.DatePattern='.'yyyy-MM-dd
log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern=%d [%t] %-5p - %m%n

Thank you in advance.

Simon McCorkindale
Technical Support Engineer


DISCLAIMER: This e-mail is confidential and may also be legally privileged. If you are not the intended recipient, use of the information contained in this e-mail (including disclosure, copying or distribution) is prohibited and may be unlawful. Please inform the sender and delete the message immediately from your system.  This e-mail is attributed to the sender and may not necessarily reflect the views of the Patsystems Group and no member of the Patsystems Group accepts any liability for any action taken in reliance on the contents of this e-mail (other than where it has a legal or regulatory obligation to do so) or for the consequences of any computer viruses which may have been transmitted by this e-mail. The Patsystems Group comprises Patsystems plc and its subsidiary group of companies.