[jira] [Commented] (LOG4J2-2624) ${web:rootDir} not working in weblogic 12c

["Tim Perry (Jira)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/LOG4J2-2624?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17269663#comment-17269663 ] 

Tim Perry commented on LOG4J2-2624:
-----------------------------------

I have the same issue Kamil Hanak describes. To fix it, I think the WebFragment logic registers the filter to shut down log4j needs to be separated out from the logic that initializes log4j. Using the ServletContainerInitializer to start log4j makes sure logging is initialized really early and that is good. But it would be nice to make registration of the filter to shut down log4j optional so that this could be handled in web.xml.

To help make things concrete, assume the following ServletContextListener is registered in a war's web.xml after any log4j configuration.

public class DisplayNameLoggingServletContextListener implements ServletContextListener {
    private Logger logger = LoggerFactory.getLogger(getClass());

    public void contextInitialized(ServletContextEvent sce) {
        final String servletContextName = sce.getServletContext().getServletContextName();
        logger.info("Loading " + servletContextName + " " + new Date());
    }

    public void contextDestroyed(ServletContextEvent sce) {
        final String servletContextName = sce.getServletContext().getServletContextName();
        logger.info("Unloading " + servletContextName + " " + new Date());
    }
}

What I have figured out is that if I use log4j-web's default registration then the logging is initialized when the web fragment jar is first processed when ServletContainerInitializer.onStartup(...) is called. This is great because it is before almost any class in the war file being loaded can request a logger so the WebLookup works correctly. However, because the log4j shutdown logic is added as a filter in the web fragment, logging is shut down before servlets, ServletContextListeners, etc. are shutdown and so log messages get lost during shutdown. In particular, the "Unloading <servletContextName> 2021-01-21 13:22" message is lost.


However, if I switch the servlet 2.5 method of configuring log4j, then a logger can easily be requested before log4j has initialized. In the above example, when DisplayNameLoggingServletContextListener is instantiated it is before log4j is initialized and WebLookup doesn't return the expected results. In our environment, we name the log files off the "display-name" element in the web.xml, but it breaks whenever someone creates a logger too soon.

To fix this, I propose breaking apart the logic in Log4jServletContainerInitializer so that it can be configured to not register the filter to shutdown log4j and instead put the Log4jWebLifeCycle initializer into the servlet context. To avoid breaking existing deployments, this is controlled by a new parameter IS_LOG4J_AUTO_SHUTDOWN_DISABLED.

final Log4jWebLifeCycle initializer = WebLoggerContextUtils.getWebLifeCycle(servletContext);
initializer.start();
initializer.setLoggerContext(); // the application is just now starting to start up


if (!"true".equalsIgnoreCase(servletContext.getInitParameter(
        Log4jWebSupport.IS_LOG4J_AUTO_SHUTDOWN_DISABLED))) {
    servletContext.addListener(new Log4jServletDestroyedListener());
} else {
    servletContext.setAttribute(Log4jWebSupport.LOG4J_INITIALIZER, initializer);
}

Then, we need a way to shut down log4j:
public class Log4jServletDestroyedListener implements ServletContextListener {

    private static final int DEFAULT_STOP_TIMEOUT = 30;
    private static final TimeUnit DEFAULT_STOP_TIMEOUT_TIMEUNIT = TimeUnit.SECONDS;

    private static final String KEY_STOP_TIMEOUT = "log4j.stop.timeout";
    private static final String KEY_STOP_TIMEOUT_TIMEUNIT = "log4j.stop.timeout.timeunit";

    private static final Logger LOGGER = StatusLogger.getLogger();

    private ServletContext servletContext;
    private Log4jWebLifeCycle initializer;

    public void contextInitialized(final ServletContextEvent event) {
        LOGGER.debug("Log4jServletContextListener ensuring that Log4j started up properly.");
        servletContext = event.getServletContext();
        this.initializer = (Log4jWebLifeCycle) 
                servletContext.getAttribute(Log4jWebSupport.LOG4J_INITIALIZER);
        if (initializer == null) {
            LOGGER.warn("Context did not contain required Log4jWebLifeCycle in attribute '" 
                    + Log4jWebSupport.LOG4J_INITIALIZER + "'. Please only use "
                    + "Log4jServletDestroyedListener with " 
                    + Log4jWebSupport.IS_LOG4J_AUTO_SHUTDOWN_DISABLED + " set to true");
        }
    }

    public void contextDestroyed(final ServletContextEvent event) {
        if (this.servletContext == null || this.initializer == null) {
            LOGGER.warn("Context destroyed before it was initialized.");
            return;
        }
        LOGGER.debug("Log4jServletDestroyedListener ensuring that Log4j shuts down properly.");

        this.initializer.clearLoggerContext(); // the application is finished
        // shutting down now
        if (initializer instanceof LifeCycle2) {
            final String stopTimeoutStr = servletContext.getInitParameter(KEY_STOP_TIMEOUT);
            final long stopTimeout = Strings.isEmpty(stopTimeoutStr) ? DEFAULT_STOP_TIMEOUT
                    : Long.parseLong(stopTimeoutStr);
            final String timeoutTimeUnitStr = servletContext.getInitParameter(KEY_STOP_TIMEOUT_TIMEUNIT);
            final TimeUnit timeoutTimeUnit = Strings.isEmpty(timeoutTimeUnitStr) ? DEFAULT_STOP_TIMEOUT_TIMEUNIT
                    : TimeUnit.valueOf(timeoutTimeUnitStr.toUpperCase(Locale.ROOT));
            ((LifeCycle2) this.initializer).stop(stopTimeout, timeoutTimeUnit);
        } else {
            this.initializer.stop();
        }
    }
}


Then to use these changes the following is needed in web.xml:
	<context-param>
        <param-name>isLog4jAutoShutdownDisabled</param-name>
        <param-value>true</param-value>
    </context-param>

	<listener>
		<listener-class>org.apache.logging.log4j.web.Log4jServletDestroyedListener</listener-class>
	</listener>


I'd like some feedback from the log4j team: Is this an acceptable fix? If so, would you like a pull request?

> ${web:rootDir} not working in weblogic 12c
> ------------------------------------------
>
>                 Key: LOG4J2-2624
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-2624
>             Project: Log4j 2
>          Issue Type: Bug
>    Affects Versions: 2.11.0
>            Reporter: gaurav
>            Priority: Blocker
>
> The web lookup - ${web:rootDir} seems to cause problems on weblogic 12c deployment.
> I suspect that the _*web-lookup plugin is not initialized*_ when weblogic requests the logger at the start of deployment and is unable to create the file.
> What I've done - 
> *1. Added slf4j in weblogic preferred packages of weblogic.xml.*
>     <wls:package-name>org.slf4j.*</wls:package-name>
> *2. log4j-web dependency is present in classpath.*
> *3.web.xml contains following:-* 
> <context-param>
>     <param-name>isLog4jAutoInitializationDisabled</param-name>
>     <param-value>true</param-value>
> </context-param>
> <listener>
>     <listener-class>org.apache.logging.log4j.web.Log4jServletContextListener</listener-class>
> </listener>
> <filter>
>     <filter-name>log4jServletFilter</filter-name>
>     <filter-class>org.apache.logging.log4j.web.Log4jServletFilter</filter-class>
> </filter>
> <filter-mapping>
>     <filter-name>log4jServletFilter</filter-name>
>     <url-pattern>/*</url-pattern>
>     <dispatcher>REQUEST</dispatcher>
>     <dispatcher>FORWARD</dispatcher>
>     <dispatcher>INCLUDE</dispatcher>
>     <dispatcher>ERROR</dispatcher>
> </filter-mapping>
> *Note - Log4jServletContextListener is placed before all listeners.
> -Have attached stacktrace for your reference.
> [^stacktrace.txt]
> Please assist.



--
This message was sent by Atlassian Jira
(v8.3.4#803005)