Log4j suddenly stops logging

Question

I'm build a Portlet application deployed to a WebSphere Portal Server running on Linux. Every Portlet WAR uses Log4j for logging with a configuration like this, having every WAR two Log files:

log4j.logger.im.the.package=DEBUG, InfoAppender, DebugAppender

log4j.appender.InfoAppender=org.apache.log4j.RollingFileAppender
log4j.appender.InfoAppender.Threshold=INFO
log4j.appender.InfoAppender.File=/tmp/infoWARName.log
log4j.appender.InfoAppender.layout=org.apache.log4j.PatternLayout
log4j.appender.InfoAppender.layout.ConversionPattern=%d %p [%c] - %m%n

log4j.appender.DebugAppender=org.apache.log4j.RollingFileAppender
log4j.appender.DebugAppender.Threshold=DEBUG
log4j.appender.DebugAppender.File=/tmp/debugWARName.log
log4j.appender.DebugAppender.layout=org.apache.log4j.PatternLayout
log4j.appender.DebugAppender.layout.ConversionPattern=%d %p [%c] - %m%n

After deployment, everything works like charm and log files started filling. After some hours, and at the same time, the Logging stops and info.log and debug.log aren't updated at all. We need to redeploy the Portlet WAR in the server to get the logging starting again.

Any ideas?

Update:

I'm starting to suspect it has to do with my Logging JARS. Currently, this are the JAR's inside my WEB-INF/lib folder:

com.springsource.org.apache.commons.logging-1.1.1.jar
com.springsource.org.apache.log4j-1.2.15.jar
com.springsource.slf4j.api-1.5.6.jar
slf4j-log4j12-1.5.6.jar

Second Update:

At hours from the bounty to end, this is how Log4j is configured in every Portlet Application. Here's web.xml:

<context-param>
    <param-name>log4jConfigLocation</param-name>
    <param-value>classpath:miAppLog4j.properties</param-value>
</context-param>
<listener>
    <listener-class>org.springframework.web.util.Log4jConfigListener</listener-class>
</listener>

And miAppLog4j.properties file is located in folder external to the WAR and to the Portal. We made it availbale in Portlet Classpath through a Shared Library in WebSphere Portal.

Answer 1

You've provided some basic information, so I can only sketch some candidate causes and likelihood:

1. Problem with file locks/handles/IO stream

• Triggerred by log rolling?

  Negative in your case. Your two separate log files (info and debug) stop at the same time for any given WAR. Each file rolls at the default maximum size (10MB). It's very unlikely that both logs would always roll at the same time. The error must not be triggered by log rolling. Extra confirmation by configuring log4j.appender.InfoAppender.MaxFileSize=200MB

• Triggerred by users manipulating Linux files?

  Negative in your case. It's possible that user/sysadmin manipulating files could create locks or stale file handles. Linux should never have problems with a user tail-ing a file (but windows does). Linux can have problems with users zipping or editing files. But your problem seems very repeatable, making this unlikely unless you have automated scripts manipulating log files.

• Triggerred by "competitive" config settings in Websphere or Spring, with duplicate use of same log files by server/framework?

  Seems unlikely in your case. Seems you haven't been setting Websphere commons logging configuration. Commons logging is automatically included in the websphere server parent ClassLoader and can be configured to "wrap" to Log4J by configuring:

  File commons-logging.properties

  # Set application classloader mode as PARENT_LAST when deploying in WAS as .ear
  priority=1
  org.apache.commons.logging.LogFactory=org.apache.commons.logging.impl.LogFactoryImpl
  

• Triggered by hardware problems/disk failure?

  ??? Seems strange that such a problem would be very repeatable.

2. Problem with java threads?

• thread death or deadlock

• massive thread processing/contention in "other" code, so that code with logging is not run

  From your description, I assume that the application is still running and working fine with normal performance and functionality, but the logs are not written. Can you confirm? If so, then it's not a thread problem with the webapp threads.

  Also I can confirm that it isn't a thread problem within the Log4J logic, because the only time it creates/uses its own thread is when one of AsynchAppender/ExternallyRolledFileAppender/SocketAppender/TelnetAppender is used OR when PropertyConfigurator.configureAndWatch or DOMConfigurator.configureAndWatch method is called.

  i.e. Negative.

3. Changes to Log4J classes in ClassLoaders, with use of different configuration?

• Parent ClassLoader clashes with Webapp ClassLoader

  E.g. Your webapps initially start with thier own configured classes from WEBINF directory and all is good, but later after some time a different app causes (or one of the portal server admin tools) causes a clashing class to be loaded into the parent ClassLoader and your app "picks up" this new illegal version of the class and fails.

  Quite possibly a problem - thousands of users on Google have struggled with Websphere class loaders.

Suggested Action:

• ensure all your web apps use PARENT_LAST ClassLoading - go to the Admin console and ensure that they have PARENT_LAST set within ALL WebApp configurations

• ensure you are getting Log4J internal error messages written to the console E.g. Deliberately test by forceably deleting the error log as admin while app is running, creating a stale handle. If "Log4J:" error messages do not appear in console, then this is a serious problem.
  Next time the problem occurs, trap any such console messages and report them. Also, you can set "-D log4j.debug" on JVM/websphere startup, to find out precisly what Log4J was doing before/during the problem - messages will go to console.

• do you really need to set the logging level to DEBUG for all of your packages & classes? Better to set to INFO or WARN and only selectively set on when you are debugging specific problems?

That's alot of text.......... B^)