logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Shaddy Baddah (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (LOG4J2-459) Race condition on Web app configuration prevents ${web:initParam. lookup
Date Fri, 06 Dec 2013 04:07:36 GMT

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

Shaddy Baddah commented on LOG4J2-459:

Unfortunately not. By that stage, the "horse has bolted". That is, log4j has actually tried
to configure the appender and failed. Including all the other failures of loggers that reference
the failed appender. Here is an example of what I see falling through the stack to complete
the call to getContext():

2013-12-06 14:51:50,361 ERROR FileManager (${web:initParam.myappdir}/myapp.log) java.io.FileNotFoundException:
${web:initParam.myappdir}/myapp.log (The filename, directory name, or volume label syntax
is incorrect)
2013-12-06 14:51:50,364 ERROR Unable to invoke method createAppender in class org.apache.logging.log4j.core.appender.FileAppender
for element File java.lang.reflect.InvocationTargetException

And it stands to reason. The following ctx.start(config) does nothing. As the code for LoggerContext.start
does this check:

        if (configLock.tryLock()) {
            try {
                if ((status == Status.INITIALIZED || status == Status.STOPPED) &&
config.isShutdownHookEnabled() ) {
                    status = Status.STARTED;

The earlier call to start has set the status to STARTED.

I'm quite convinced that this is a "chicken-egg" scenario (if race condition is exclusive
to multi-threaded scenarios).

> Race condition on Web app configuration prevents ${web:initParam. lookup
> ------------------------------------------------------------------------
>                 Key: LOG4J2-459
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-459
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Core
>    Affects Versions: 2.0-beta9
>            Reporter: Shaddy Baddah
>            Priority: Minor
> I am happy for someone to challenge me on this assertion, but I cannot see how ${web:initParam.*}
notation in XML configuration could ever work in 2.0-beta9 at least. Well at least for bootstrapped
> I have a Web application that includes an XML configfile in the WAR at:
> WEB-INF/classes/log4j2.xml
> The file looks something like this:
> ?xml version="1.0" encoding="UTF-8"?>
> <Configuration status="WARN">
> <Appenders>
> <File name="file" fileName="${web:initParam.myapp.logdir}/myapp.log" append="true">
> 	<PatternLayout pattern="%d [%t] %-5p %c - %m%n"/>
> </File>
> </Appenders>
> <Loggers>
> <Root level="warn">
> <AppenderRef ref="file"/>
>  </Root>
> </Loggers>
> </Configuration>
> For the uninitiated, a recap on how ${web:initParam.myapp.logdir} is resolved, to the
best of my understanding.
> The ${web: prefix will indicate to log4j2 that it should use the WebLookup class to resolve
what comes after it; initParam.myapp.logdir.
> WebLookup will then check if that key is prefixed with initParam. (as well as another
attr type prefix), and seeing that it is, will use the remainder as the real key name: myapp.logdir.
> It then calls getInitParameter() with that key on the ServletContext for the parent web
application. That should pluck a value that could, for example, be configured in the web.xml
like this:
>      <context-param>
>     <param-name>myapp.logdir</param-name>
>     <param-value>c:/myapp_logs</param-value>
>     </context-param>
> However, this is where there is a race condition. To get the ServletContext , the WebLookup.lookup()
method will call its own getServletContext() method. This in term attempt to get the ServletContext
from the LogManager singleton, which stores it as an untyped (java.lang.Object) externalContext
> For a Web App, this externalContext is not being set ahead of the bootstrapping parse
of the XML config file.The problem can be seen in the sequencing of instructions in the Configurator.initialize()
>     public static LoggerContext initialize(final String name, final ClassLoader loader,
final URI configLocation,
>                                            final Object externalContext) {
>         try {
>             final org.apache.logging.log4j.spi.LoggerContext context = LogManager.getContext(loader,
false, configLocation);
>             if (context instanceof LoggerContext) {
>                 final LoggerContext ctx = (LoggerContext) context;
>                 ContextAnchor.THREAD_CONTEXT.set(ctx);
>                 if (externalContext != null) {
>                     ctx.setExternalContext(externalContext);
>                 }
> This line:
>             final org.apache.logging.log4j.spi.LoggerContext context = LogManager.getContext(loader,
false, configLocation);
> kicks-off the boostrapped parse of the XML config, that in turn utilizes WebLookup.lookup().
> You can see however that ctx.setExternalContext(externalContext) is called after.
> Simple reasoning suggests that this initialization could be moved ahead. However this
code applies to non-web apps too, and being not familiar with the design and intentions, I'd
be very appreciative of someone looking into a fix for this.
> Thanks.

This message was sent by Atlassian JIRA

To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org

View raw message