Weblogic 12c with Log4j2 stops logging after stop/start

Question

I got a pecurliar behaviour when we stop a war in Weblogic 12c and then start it again. For some reason beyond my understanding Log4j2 stops writing to the log. It creates a new logfile but no entries are written.

I have debugged and sees that Log4jServletContainerInitializer and Log4jServletContextListener gets called just like they do when installing the war. I didn't notice any differences (unfortunally thats only a test of my attention span).

So do you have any idea of what might differ between install and start in regards of Log4J2 in Weblogic 12c and perhaps where to look for errors?

Answer 1

Your problem:

For some reason beyond my understanding Log4j2 stops writing to the log. It creates a new logfile but no entries are written.

---

Root Cause Analysis:

It is actually happen for some issues.

1. If your configuration for log4j is not correctly done in log4j.properties file.
2. If your append properties are not made true.
3. If you use two loggers like Log4J and JUL, which uses the same appneder(Stdout).
4. If your log4j jar file is not properly set to your classpath.

---

Solution:

Ans-1: In your classpath, there is a setting of library that intercepts Log4J calls and converts them to JUL calls. Then it may cause this issue. So specify correctly that which importing is actually needed. java.util.logging.Logger or org.apache.log4j.Logger

Ans-2: Properties are case sensitive. so your file name would be same with appender. and don't forget to make the appender to true.

log4j.appender.mainAppender.File=yourLogFile.log
log4j.appender.mainAppender.Append=true

Ans-3: for Hibernate in particular, include slf4j in order to ensure that all the loggers co-operate with it.

---

Ans-4: Sometimes this problem occurs for tomcat. If tomcat security enabled, and there were several permissions missing from the policy files, then this type of issue occurs. After giving permissions, it will work fine.

---

What Log4J does actually?

Log4J will only print messages which are info and up, and it will print them to both console and file. You can change this behaviour by changing INFO to ALL in log4j.rootLogger. If that doesn't work, add -Dlog4j.debug=true to your JVM arguments - that will make Log4J emit debug messages about itself (to System.out), so you can see what's going on. Credit goes to @Isaac

Resource Link:

1. Log4J creates log file but does not write to it
2. Issue with log4j log not writing to file

---

UPDATE for log4j2:

---

Thanks a lot to rgoers for pointing the issue for log4j2. I am updating.

Root cause analysis from P.O.V of wilkinsona

When a restart is triggered, DevTools runs and then clears all registered shutdown hooks. One such hook is Log4J2's DefaultShutdownCallbackRegistry. Log4jContextFactory maintains a reference to the DefaultShutdownCallbackRegistry and LogManager holds a static reference to Log4jContextFactory. Log4J2's classes are loaded by the app classloader which means that there's a single LogManager, Log4jContextFactory, and DefaultShutdownCallbackRegistry shared across restarts.

When DefaultShutdownCallbackRegistry is run as part of a restart it stops the LoggerContext and sets its own state to STOPPED. As the restart proceeds a new LoggerContext is created and an attempt is made to register a shutdown callback for it with the registry. This fails as the registry's state is still STOPPED.

Solution:

Wilkinsona offered a hack method to solve the issue. That is given below. Try to cope with it.

Clearing out the callbacks in the registry before the Restarter runs the JVM's shutdown hooks is better. It prevents the exception from occurring, and logging continues to work after a restart.

private void prepareLog4J2ForRestart() throws Exception {
    if (ClassUtils.isPresent("org.apache.logging.log4j.LogManager",
            getClass().getClassLoader())) {
        LoggerContextFactory factory = LogManager.getFactory();
        Field field = ReflectionUtils.findField(factory.getClass(),
                "shutdownCallbackRegistry");
        ReflectionUtils.makeAccessible(field);
        ShutdownCallbackRegistry shutdownCallbackRegistry = (ShutdownCallbackRegistry) ReflectionUtils
                .getField(field, factory);
        Field hooksField = ReflectionUtils
                .findField(shutdownCallbackRegistry.getClass(), "hooks");
        ReflectionUtils.makeAccessible(hooksField);
        @SuppressWarnings("unchecked")
        Collection<Cancellable> state = (Collection<Cancellable>) ReflectionUtils
                .getField(hooksField, shutdownCallbackRegistry);
        state.clear();
    }
}

Resource Link:

1. Log4j 2.4 breaks rc1 devtools
2. Call context.close() rather than shutdown hook in DevTools restart

---

UPDATE2:

What kind of listener to add to my JEE application, to get the expected behaviour?

For writing a listener, you can follow the tutorials

1. ServletContextListener Example
2. Writing a Listener Class
3. Servlet Listener Example – ServletContextListener, HttpSessionListener and ServletRequestListener