Log4j 2
  1. Log4j 2
  2. LOG4J2-293

classloader URI scheme broken or insufficient when using Log4jContextListener

    Details

      Description

      I'm trying to migrate to Log4j2, and things looked promising when I spotted Log4jContextListener.

      However, there are too many holes.

      Firstly, I tried using classpath: as a scheme, and nothing blew up, so I assumed I'd got it right.

      Then I looked at the code (which shouldn't be how we find out) and eventually discovered some code relating to a 'classloader' scheme.

      Still silent failure. It seems that the classpath is not being searched, perhaps just the WAR classloader, not the JARs in WEB-INF/lib.

      Next I tried omitting the / (i.e. using classloader:log4j2.xml) and got a NullPointerException.

      Can you please document what schemes are supported and what you expect them to do, and not fail silently when a configuration file is specified, but nothing happens.

      1. LOG4J2-293.patch
        3 kB
        Abhinav Shah
      2. TestConfigurator.java
        15 kB
        Abhinav Shah
      3. ConfigurationFactory.java
        19 kB
        Abhinav Shah

        Issue Links

          Activity

          Hide
          Nick Williams added a comment -

          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.

          Show
          Nick Williams added a comment - 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 .
          Hide
          Neale Upstone added a comment -

          Hi Nick, I'll give beta8 a go and then update.

          Show
          Neale Upstone added a comment - Hi Nick, I'll give beta8 a go and then update.
          Hide
          Nick Williams added a comment -

          Neale,

          How is this working for you in beta8? Can you update us?

          Thanks.

          Show
          Nick Williams added a comment - Neale, How is this working for you in beta8? Can you update us? Thanks.
          Hide
          Neale Upstone added a comment - - 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

          Show
          Neale Upstone added a comment - - 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
          Hide
          Neale Upstone added a comment - - 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.

          Show
          Neale Upstone added a comment - - 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.
          Hide
          Nick Williams added a comment -
          1. Just to double-check, you're using Beta8, right?
          2. What exact version of Tomcat are you using?
          3. Attach your web.xml file, please.
          4. 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.
          5. You have read this documentation, correct?
          Show
          Nick Williams added a comment - 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?
          Hide
          Neale Upstone added a comment -

          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.

          Show
          Neale Upstone added a comment - 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.
          Hide
          Abhinav Shah added a comment - - edited

          I found a work around to this problem.

          You would need spring-core-3.2.0 jar for this solution to work.

          import java.io.FileNotFoundException;
          import java.net.URL;
          
          import javax.servlet.ServletContext;
          import javax.servlet.ServletContextEvent;
          import javax.servlet.ServletContextListener;
          
          import org.apache.logging.log4j.core.web.Log4jServletContextListener;
          import org.springframework.util.ResourceUtils;
          import org.springframework.util.SystemPropertyUtils;
          import org.springframework.web.util.WebUtils;
          
          public class MyLog4jServletContextListener implements ServletContextListener {
          	private ServletContext servletContext;
          	private Log4jServletContextListener log4jServletContextListener;
          
          	@Override
          	public void contextInitialized(ServletContextEvent sce) {
          		this.servletContext = sce.getServletContext();
          		String location = servletContext.getInitParameter("log4jConfig");
          
          		// Perform actual log4j initialization; else rely on log4j's default
          		// initialization.
          		try {
          			// Resolve system property placeholders before potentially
          			// resolving a real path.
          			location = SystemPropertyUtils.resolvePlaceholders(location);
          
          			// Leave a URL (e.g. "classpath:" or "file:") as-is.
          			if (!ResourceUtils.isUrl(location)) {
          				// Consider a plain file path as relative to the web
          				// application root directory.
          				location = WebUtils.getRealPath(servletContext, location);
          			}
          
          			URL url = ResourceUtils.getURL(location);
          			if (url == null) {
          				throw new FileNotFoundException(location
          						+ " cannot be resolved to absolute file path "
          						+ "because it does not reside in the file system");
          			}
          			sce.getServletContext().setInitParameter("log4jConfiguration",
          					url.toString());
          		} catch (FileNotFoundException ex) {
          			throw new IllegalArgumentException(
          					"Invalid 'log4jConfigLocation' parameter: "
          							+ ex.getMessage());
          		}
          		log4jServletContextListener = new Log4jServletContextListener();
          		log4jServletContextListener.contextInitialized(sce);
          	}
          
          	@Override
          	public void contextDestroyed(ServletContextEvent sce) {
          		log4jServletContextListener.contextDestroyed(sce);
          	}
          

          web.xml

          <?xml version="1.0" encoding="UTF-8"?>
          <web-app xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
          	xmlns="http://java.sun.com/xml/ns/javaee"
          	xsi:schemaLocation="http://java.sun.com/xml/ns/javaee http://java.sun.com/xml/ns/javaee/web-app_3_0.xsd"
          	id="WebApp_ID" version="3.0" metadata-complete="true">
          	<absolute-ordering />
          	<display-name>pec-service</display-name>
          	<context-param>
          		<param-name>log4jConfig</param-name>
          		<param-value>classpath:log4j/${com.labcorp.app.env}.log4j.xml</param-value>
          	</context-param>
          	 
          	<listener>
          		<listener-class>com.eag.util.web.MyLog4jServletContextListener</listener-class>
          	</listener>	
          	 
          	<filter>
          		<filter-name>log4jServletFilter</filter-name>
          		<filter-class>org.apache.logging.log4j.core.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>
          	
          	
          </web-app>
          
          Show
          Abhinav Shah added a comment - - edited I found a work around to this problem. You would need spring-core-3.2.0 jar for this solution to work. import java.io.FileNotFoundException; import java.net.URL; import javax.servlet.ServletContext; import javax.servlet.ServletContextEvent; import javax.servlet.ServletContextListener; import org.apache.logging.log4j.core.web.Log4jServletContextListener; import org.springframework.util.ResourceUtils; import org.springframework.util.SystemPropertyUtils; import org.springframework.web.util.WebUtils; public class MyLog4jServletContextListener implements ServletContextListener { private ServletContext servletContext; private Log4jServletContextListener log4jServletContextListener; @Override public void contextInitialized(ServletContextEvent sce) { this .servletContext = sce.getServletContext(); String location = servletContext.getInitParameter( "log4jConfig" ); // Perform actual log4j initialization; else rely on log4j's default // initialization. try { // Resolve system property placeholders before potentially // resolving a real path. location = SystemPropertyUtils.resolvePlaceholders(location); // Leave a URL (e.g. "classpath:" or "file:" ) as-is. if (!ResourceUtils.isUrl(location)) { // Consider a plain file path as relative to the web // application root directory. location = WebUtils.getRealPath(servletContext, location); } URL url = ResourceUtils.getURL(location); if (url == null ) { throw new FileNotFoundException(location + " cannot be resolved to absolute file path " + "because it does not reside in the file system" ); } sce.getServletContext().setInitParameter( "log4jConfiguration" , url.toString()); } catch (FileNotFoundException ex) { throw new IllegalArgumentException( "Invalid 'log4jConfigLocation' parameter: " + ex.getMessage()); } log4jServletContextListener = new Log4jServletContextListener(); log4jServletContextListener.contextInitialized(sce); } @Override public void contextDestroyed(ServletContextEvent sce) { log4jServletContextListener.contextDestroyed(sce); } web.xml <?xml version= "1.0" encoding= "UTF-8" ?> <web-app xmlns:xsi = "http://www.w3.org/2001/XMLSchema-instance" xmlns= "http://java.sun.com/xml/ns/javaee" xsi:schemaLocation= "http://java.sun.com/xml/ns/javaee http://java.sun.com/xml/ns/javaee/web-app_3_0.xsd" id= "WebApp_ID" version= "3.0" metadata-complete= "true" > <absolute-ordering /> <display-name> pec-service </display-name> <context-param> <param-name> log4jConfig </param-name> <param-value> classpath:log4j/${com.labcorp.app.env}.log4j.xml </param-value> </context-param> <listener> <listener-class> com.eag.util.web.MyLog4jServletContextListener </listener-class> </listener> <filter> <filter-name> log4jServletFilter </filter-name> <filter-class> org.apache.logging.log4j.core.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> </web-app>
          Hide
          Ralph Goers added a comment -

          I think your earlier suggestion to reconfigure if the LoggerContext has a null configLocation is the correct one.

          Show
          Ralph Goers added a comment - I think your earlier suggestion to reconfigure if the LoggerContext has a null configLocation is the correct one.
          Hide
          Abhinav Shah added a comment -

          I fixed this issue. Since I am not a contributor to log4j2, I am going to attach the source files here.

          Show
          Abhinav Shah added a comment - I fixed this issue. Since I am not a contributor to log4j2, I am going to attach the source files here.
          Hide
          Abhinav Shah added a comment -

          prefix to pick the config. file from classpath is classpath:

          Show
          Abhinav Shah added a comment - prefix to pick the config. file from classpath is classpath:
          Hide
          Nick Williams added a comment - - 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.

          Show
          Nick Williams added a comment - - 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.
          Hide
          Abhinav Shah added a comment -

          Attaching svn patch.

          Show
          Abhinav Shah added a comment - Attaching svn patch.
          Hide
          Nick Williams added a comment - - 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).

          Show
          Nick Williams added a comment - - 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).
          Hide
          Abhinav Shah added a comment -

          Nick. I just removed all the code formatting. Attaching new patch.

          Show
          Abhinav Shah added a comment - Nick. I just removed all the code formatting. Attaching new patch.
          Hide
          Nick Williams added a comment -

          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?

          Show
          Nick Williams added a comment - 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?
          Hide
          Neale Upstone added a comment -

          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.

          Show
          Neale Upstone added a comment - 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.
          Hide
          Nick Williams added a comment -

          As instructed in the mailing list conversation you linked to, can you enable logging the effective web.xml? Then, attach both your actual web.xml and the effective web.xml? Thanks.

          Show
          Nick Williams added a comment - As instructed in the mailing list conversation you linked to, can you enable logging the effective web.xml ? Then, attach both your actual web.xml and the effective web.xml ? Thanks.
          Hide
          Ralph Goers added a comment - - 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.

          Show
          Ralph Goers added a comment - - 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.
          Hide
          Neale Upstone added a comment -

          Thanks. Will verify when I get a chance this week. Prob not going to be until Wed or Thurs

          Show
          Neale Upstone added a comment - Thanks. Will verify when I get a chance this week. Prob not going to be until Wed or Thurs
          Hide
          Neale Upstone added a comment - - 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)
          
          Show
          Neale Upstone added a comment - - 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)
          Hide
          Nick Williams added a comment - - 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:

          1. 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.
          2. 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.
          3. 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.
          Show
          Nick Williams added a comment - - 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.
          Hide
          Neale Upstone added a comment -

          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

          Show
          Neale Upstone added a comment - 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
          Hide
          Ralph Goers added a comment -

          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.

          Show
          Ralph Goers added a comment - 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.

            People

            • Assignee:
              Nick Williams
              Reporter:
              Neale Upstone
            • Votes:
              1 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development