Activity

Can you provide a bit more information about the problem you're seeing? I'm unable to see a problem. Can you provide some example configurations, list directory/file layouts, show your deployment descriptor (web.xml), etc?

Note that the entire web initialization system got a major overhaul for 2.0-beta8, which comes out next week. See LOG4J2-270.

Nick Williams
added a comment - 08/Jul/13 00:32 Can you provide a bit more information about the problem you're seeing? I'm unable to see a problem. Can you provide some example configurations, list directory/file layouts, show your deployment descriptor (web.xml), etc?
Note that the entire web initialization system got a major overhaul for 2.0-beta8, which comes out next week. See LOG4J2-270 .

Just updated my Log4j2 branch to beta8 and config is apparently behaving but silently is giving defaults. I think something is happening before the initializer gets in on the act, so the context never gets initialized from the URI.

I can't get much further as until beta9, as what seems to be LOG4J2-304 breaks our build

Neale Upstone
added a comment - 02/Aug/13 10:00 - edited Hi Nick,
Just updated my Log4j2 branch to beta8 and config is apparently behaving but silently is giving defaults. I think something is happening before the initializer gets in on the act, so the context never gets initialized from the URI.
I can't get much further as until beta9, as what seems to be LOG4J2-304 breaks our build
Thanks. Neale

The other listener calls SLF4J Log4jLoggerFactory.getLogger(), which in turn calls Log4jContextFactory.getContext()

This causes a LoggerContext to be created with configLocation set to null (ClassLoaderContextSelector:line 204). This is placed in CONTEXT_MAP.

After the above, the Log4jServletContextListener fires.

locateContext() is called again, this time with the URI set. At line 214 (if(ctx != null) return ctx;), you now have ctx.configLocation==null, but the passed in configLocation is classloader:/path/to/log4j2.xml

Should the key used for CONTEXT_MAP perhaps contain configLocation too?

I think at the very least, a useful warning could be emitted when the configLocation mis-match is discovered. I would have thought the expected behaviour would be that a reconfiguration would take place at this point, so Log4j2 would tolerate the late config. I've always thought that this is what's been happening with 1.2.x.

Neale Upstone
added a comment - 02/Aug/13 11:07 - edited I've got further on this. I think that some helpful checking could be done. What seems to be happening is:
web.xml has other listeners. log4j2 is the first listed, but the other fires first (This seems a Tomcat 7 issue: http://tomcat.10.x6.nabble.com/Autowired-spring-bean-not-working-in-tomcat-7-0-35-with-jax-ws-td4993897.html )
The other listener calls SLF4J Log4jLoggerFactory.getLogger(), which in turn calls Log4jContextFactory.getContext()
This causes a LoggerContext to be created with configLocation set to null (ClassLoaderContextSelector:line 204). This is placed in CONTEXT_MAP.
After the above, the Log4jServletContextListener fires.
locateContext() is called again, this time with the URI set. At line 214 ( if(ctx != null) return ctx; ), you now have ctx.configLocation==null, but the passed in configLocation is classloader:/path/to/log4j2.xml
Should the key used for CONTEXT_MAP perhaps contain configLocation too?
I think at the very least, a useful warning could be emitted when the configLocation mis-match is discovered. I would have thought the expected behaviour would be that a reconfiguration would take place at this point, so Log4j2 would tolerate the late config. I've always thought that this is what's been happening with 1.2.x.

Go through all of the JARs in your application's /WEB-INF/lib directory and find any and all JARs (other than log4j) that contain a /META-INF/web-fragment.xml file. Post the names of those JARs and the contents of their corresponding web-fragment.xml files.

Nick Williams
added a comment - 03/Aug/13 16:06
Just to double-check, you're using Beta8, right?
What exact version of Tomcat are you using?
Attach your web.xml file, please.
Go through all of the JARs in your application's /WEB-INF/lib directory and find any and all JARs (other than log4j) that contain a /META-INF/web-fragment.xml file. Post the names of those JARs and the contents of their corresponding web-fragment.xml files.
You have read this documentation , correct?

Apols that I omitted to clarify that the linked Tomcat issue is a Servlet 2.5 issue, i.e. that I'm using 2.5 so fragments are not relevant.

I'm now confused. For some reason classloader: seemed to be the scheme when I last looked and this seems to pick up the correct handler stepping through the code, but your docs (which seem to be different from the ones I remember) say classpath:.

Could you please read my bullets and confirm the expected behaviour when getLogger() has already been called by another Listener? This silent skipping of config is not helpful.

I'll check whether 1.2 exhibited that behaviour as you'll really need to jump one way or the other on it: reconfigure or fail, not silently proceed with defaults, as is happening at the moment.

Neale Upstone
added a comment - 05/Aug/13 17:22 Beta 8, as I said:
> Just updated my Log4j2 branch to beta8
Apols that I omitted to clarify that the linked Tomcat issue is a Servlet 2.5 issue, i.e. that I'm using 2.5 so fragments are not relevant.
I'm now confused. For some reason classloader: seemed to be the scheme when I last looked and this seems to pick up the correct handler stepping through the code, but your docs (which seem to be different from the ones I remember) say classpath: .
Could you please read my bullets and confirm the expected behaviour when getLogger() has already been called by another Listener ? This silent skipping of config is not helpful.
I'll check whether 1.2 exhibited that behaviour as you'll really need to jump one way or the other on it: reconfigure or fail, not silently proceed with defaults, as is happening at the moment.

Thanks for looking into and, possibly (I haven't reviewed it yet), fixing this issue. Such proposed patches should be attached as SVN diffs, not whole source files. That way, it makes it easier for us to tell exactly what changed and review the proposed patch.

Please use a command like:

$ svn diff > LOG4J2-293.patch

(from the trunk directory) to generate a patch that can be properly vetted, and attach that patch to this issue.

Nick Williams
added a comment - 31/Aug/13 00:22 - edited Thanks for looking into and, possibly (I haven't reviewed it yet), fixing this issue. Such proposed patches should be attached as SVN diffs, not whole source files. That way, it makes it easier for us to tell exactly what changed and review the proposed patch.
Please use a command like:
$ svn diff > LOG4J2-293.patch
(from the trunk directory) to generate a patch that can be properly vetted, and attach that patch to this issue.
Thanks.

Your IDE has reformatted the JavaDoc and Java code in the file. This makes it very difficult to separate out the changes you made from the reformatting. Please correct this. Patches should not reformat code that doesn't change. You will likely need to disable this auto-reformatting in your IDE, or change the settings to reflect the Log4j coding standards (for example, 120-character lines, not 80-character lines as it appears your IDE is enforcing).

Nick Williams
added a comment - 31/Aug/13 01:08 - edited Your IDE has reformatted the JavaDoc and Java code in the file. This makes it very difficult to separate out the changes you made from the reformatting. Please correct this. Patches should not reformat code that doesn't change. You will likely need to disable this auto-reformatting in your IDE, or change the settings to reflect the Log4j coding standards (for example, 120-character lines, not 80-character lines as it appears your IDE is enforcing).

Nick Williams
added a comment - 31/Aug/13 21:59 Thanks for the patch. I tweaked it slightly to still maintain support for the classloader: scheme and also to improve test code coverage. Can you checkout, build, verify, and close, please?

Neale Upstone
added a comment - 31/Aug/13 23:19 It looks like this patch fixes only the NPE, but not the reconfiguration issue, as Ralph had alluded to.
That still remains a gotcha as Log4j2 should not silently ignore configuration as it does.

Ralph Goers
added a comment - 02/Sep/13 05:22 - edited As of revision 1519337 ClassLoaderContextSelector will now reconfigure if it previously had no configuration location and is subsequently provided one. Please verify and close.

classpath:/properties/log4j2.xml still fails silently (this should at least output something saying that nothing was found, or preferably illegal config and bomb out)

classpath:properties/log4j2.xml works (once I've excluded an old Xerces 2.6 from my build).

when running, there is lots of "WARN locateContext called with URI null. Existing LoggerContext has URI classpath:properties/dev/log4j2.xml". I think being called with null is to be expected, as that's what lots of filters etc are doing via things like commons logging or SLF4J APIs.

The silent failure is still a bug. I should not need to use a debugger, and it certainly should be covered in the documentation (and isn't. An example for classpath: is needed).
I'd even suggest that the JavaDoc for Log4jServletContextListener could say what params it expects and what the valid values are.

If you want to help those who somehow have Xerces 2.6.1 or equiv on their classpath, then the following could be caught and dealt with (e.g. continue, but warn that they have old XML parser around):

Neale Upstone
added a comment - 03/Sep/13 11:54 - edited Okay. More time spent with a debugger to find:
classpath:/properties/log4j2.xml still fails silently (this should at least output something saying that nothing was found, or preferably illegal config and bomb out)
classpath:properties/log4j2.xml works (once I've excluded an old Xerces 2.6 from my build).
when running, there is lots of "WARN locateContext called with URI null. Existing LoggerContext has URI classpath:properties/dev/log4j2.xml". I think being called with null is to be expected, as that's what lots of filters etc are doing via things like commons logging or SLF4J APIs.
The silent failure is still a bug. I should not need to use a debugger, and it certainly should be covered in the documentation (and isn't. An example for classpath: is needed).
I'd even suggest that the JavaDoc for Log4jServletContextListener could say what params it expects and what the valid values are.
If you want to help those who somehow have Xerces 2.6.1 or equiv on their classpath, then the following could be caught and dealt with (e.g. continue, but warn that they have old XML parser around):
java.lang.AbstractMethodError: javax.xml.parsers.DocumentBuilderFactory.setFeature(Ljava/lang/ String ;Z)V
at org.apache.logging.log4j.core.config.XMLConfiguration.enableXInclude(XMLConfiguration.java:106)

Point taken that there are improvements to be made on JavaDoc. However, there are three separate issues here, and they all need to be handled differently:

Log4j is not gracefully handling logging starting before Log4j's filter. We're trying to fix that. This additional info you've provided is helpful to get that straightened out. I definitely understand that silent failures are frustrating.

Something is starting logging before Log4j's filter. While Log4j should handle this gracefully, this is still a big problem because you could be missing important logging events. I need more information to troubleshoot this. As mentioned above and above, I need A) your web.xml, B) your effective web.xml as generated by Tomcat (the thread you linked to has instructions for logging this info), and C) a list of any JARs in your webapp containing files /META-INF/web-fragment.xml OR META-INF/services/javax.servlet.ServletContainerInitializer.

You are now getting an AbstractMethodError. I understand your frustration with it, but Log4j cannot be responsible for detecting, catching, and reporting all the many different errors that can happen because users have the wrong versions of other-party libraries on their classpath. The error, as you pointed out, means that you had an old Xerces on your classpath. Fixing that fixes the problem. There's nothing that needs to be done in Log4j here.

Nick Williams
added a comment - 03/Sep/13 12:45 - edited Point taken that there are improvements to be made on JavaDoc. However, there are three separate issues here, and they all need to be handled differently:
Log4j is not gracefully handling logging starting before Log4j's filter. We're trying to fix that. This additional info you've provided is helpful to get that straightened out. I definitely understand that silent failures are frustrating.
Something is starting logging before Log4j's filter. While Log4j should handle this gracefully, this is still a big problem because you could be missing important logging events. I need more information to troubleshoot this. As mentioned above and above, I need A) your web.xml, B) your effective web.xml as generated by Tomcat (the thread you linked to has instructions for logging this info), and C) a list of any JARs in your webapp containing files /META-INF/web-fragment.xml OR META-INF/services/javax.servlet.ServletContainerInitializer.
You are now getting an AbstractMethodError. I understand your frustration with it, but Log4j cannot be responsible for detecting, catching, and reporting all the many different errors that can happen because users have the wrong versions of other-party libraries on their classpath. The error, as you pointed out, means that you had an old Xerces on your classpath. Fixing that fixes the problem. There's nothing that needs to be done in Log4j here.

I understand about XML, although I'd people expect a level of 'drop-in-replacement'. My suggestion fits with what Liquibase does, which is just to warn that it will not be able to process includes, and carries on. Naturally, now I've fixed the issue, I can see all sorts of DRYness I can get out of using them

Neale Upstone
added a comment - 03/Sep/13 13:47 Thanks Nick. Will see what I can do when I next get time.
I understand about XML, although I'd people expect a level of 'drop-in-replacement'. My suggestion fits with what Liquibase does, which is just to warn that it will not be able to process includes, and carries on. Naturally, now I've fixed the issue, I can see all sorts of DRYness I can get out of using them

Ralph Goers
added a comment - 03/Sep/13 17:32 I disagree with item 3. I think we should check for the exception and log a warning that XInclude support is unavailable. But that should be a separate Jira issue.