Log4j 2
  1. Log4j 2
  2. LOG4J2-462

LevelPatternConverter.format may throw NPE

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-beta9
    • Fix Version/s: 2.0-rc1, 2.0
    • Component/s: Core
    • Labels:
      None
    • Environment:

      java version "1.6.0_65"
      Java(TM) SE Runtime Environment (build 1.6.0_65-b14-462-11M4609)
      Java HotSpot(TM) 64-Bit Server VM (build 20.65-b04-462, mixed mode)

      Description

      I found an issue when enabling asynchronous appenders with `-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector` and I also got a workaround to fix it.

      Note that I invoke LogContext.setConfigLocation() then LogContext.reconfigure() in order to apply log4j2.xml programatically.

      1. Stacktrace ... See the bottom of the Description as it is a large portion.
      2. Workaround
      Just to get rid of toString() at line 123 from the following snippet:

      2.0-beta-9.org.apache.logging.log4j.core.pattern.LevelPatternConverter.java
      122 public void format(final LogEvent event, final StringBuilder output) {
      123     output.append(levelMap == null ? event.getLevel().toString() : levelMap.get(event.getLevel()));
      124 }
      

      The workaround is as follows:

      MyWorkaround
      122 public void format(final LogEvent event, final StringBuilder output) {
      123     output.append(levelMap == null ? event.getLevel() : levelMap.get(event.getLevel()));
      124 }
      

      3. Log4j2.xml

      log4j2.xml snip
      		<RollingRandomAccessFile name="MySizeRollingLog"
      			fileName="foo.log"
      			filePattern="foo-%d{MM-dd-yyyy}-%i.log.gz">
      			<PatternLayout
      				pattern="%d{yyyy-MM-dd HH:mm:ss,SSS z} %-5p [%t] (%F:%L) - [server($${sys:something})]-[%X{Something}]-%m%n" />
      			<Policies>
      				<TimeBasedTriggeringPolicy interval="1"
      					modulate="true" />
      				<SizeBasedTriggeringPolicy size="1000KB" />
      			</Policies>
      			<DefaultRolloverStrategy max="3" />
      		</RollingRandomAccessFile>
      

      I'm not sure why event.getLevel() was null but the workaround works for me.


      Full stacktrace:
      2013-12-05 09:36:58,947 ERROR An exception occurred processing Appender MySizeRollingLog java.lang.NullPointerException
      at org.apache.logging.log4j.core.pattern.LevelPatternConverter.format(LevelPatternConverter.java:122)
      at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:36)
      at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:167)
      at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:52)
      at org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:45)
      at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:111)
      at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
      at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:99)
      at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
      at org.apache.logging.log4j.core.async.AsyncLoggerConfig.asyncCallAppenders(AsyncLoggerConfig.java:116)
      at org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigHelper.java:218)
      at org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigHelper.java:203)
      at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:133)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
      at java.lang.Thread.run(Thread.java:695)

        Issue Links

          Activity

          Hide
          Remko Popma added a comment -

          Thanks for reporting this.
          I'm very surprised that event.getLevel() returns null. I think that should never happen. (Team: am I right? Or are there cases where event.getLevel() is legitimately null?)

          Daisuke, can you also post your code where you programmatically configure log4j?

          Show
          Remko Popma added a comment - Thanks for reporting this. I'm very surprised that event.getLevel() returns null . I think that should never happen. (Team: am I right? Or are there cases where event.getLevel() is legitimately null?) Daisuke, can you also post your code where you programmatically configure log4j?
          Hide
          Daisuke Baba added a comment -

          Indeed, what I did seems to be a little bit tricky. Let me explain.
          I'm running my app on the Tomcat7. And I wrote a class to initialize Log4J2 with a specified file within ServletContextListener#contextInitialized().
          In the Log4J2 initialization class, I wrote the code like this:

          // context => a ServletContext object
          String log4j2File = context.getInitParameter("...");
          final URI log4j2FileURI = log4j2File.toURI();
          LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
          ctx.setConfigLocation(log4j2FileURI);
          ctx.reconfigure();
          

          Note that I used reflection in order to manipulate org.apache.logging.log4j.* classes because I'd like to inject the log4j2 dependency dynamically rather than statically for our specific reason.

          I'm also enabling asynchronous logging by providing -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector option to the Tomcat startup shell.

          SLF4J is also included in my app. So I import the following library as well.

          <dependency>
          	<groupId>org.apache.logging.log4j</groupId>
          	<artifactId>log4j-slf4j-impl</artifactId>
          	<version>2.0-beta9</version>
          	<scope>runtime</scope>
          </dependency>
          
          Show
          Daisuke Baba added a comment - Indeed, what I did seems to be a little bit tricky. Let me explain. I'm running my app on the Tomcat7. And I wrote a class to initialize Log4J2 with a specified file within ServletContextListener#contextInitialized(). In the Log4J2 initialization class, I wrote the code like this: // context => a ServletContext object String log4j2File = context.getInitParameter( "..." ); final URI log4j2FileURI = log4j2File.toURI(); LoggerContext ctx = (LoggerContext) LogManager.getContext( false ); ctx.setConfigLocation(log4j2FileURI); ctx.reconfigure(); Note that I used reflection in order to manipulate org.apache.logging.log4j.* classes because I'd like to inject the log4j2 dependency dynamically rather than statically for our specific reason. I'm also enabling asynchronous logging by providing -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector option to the Tomcat startup shell. SLF4J is also included in my app. So I import the following library as well. <dependency> <groupId> org.apache.logging.log4j </groupId> <artifactId> log4j-slf4j-impl </artifactId> <version> 2.0-beta9 </version> <scope> runtime </scope> </dependency>
          Hide
          Remko Popma added a comment -

          Daisuke, both this issue and LOG4J2-465 occur because somehow the LogEvent Level became null.

          I thought this wasn't possible but I missed an obvious way this can happen. The Logger interface has about 14 log methods, 2 printf methods and a throwing that take a Level parameter. Is it possible that your application calls one of these methods with a null Level parameter?

          Team, should we replace null Level parameters with Level.OFF when constructing a LogEvent to prevent NPEs?
          I think that would be preferable to having to check if level == null everywhere downstream...

          Show
          Remko Popma added a comment - Daisuke, both this issue and LOG4J2-465 occur because somehow the LogEvent Level became null . I thought this wasn't possible but I missed an obvious way this can happen. The Logger interface has about 14 log methods, 2 printf methods and a throwing that take a Level parameter. Is it possible that your application calls one of these methods with a null Level parameter? Team, should we replace null Level parameters with Level.OFF when constructing a LogEvent to prevent NPEs? I think that would be preferable to having to check if level == null everywhere downstream...
          Hide
          Gary Gregory added a comment -

          I like the idea of using Level.OFF, it is OO unlike checking for null all over the place.

          Show
          Gary Gregory added a comment - I like the idea of using Level.OFF , it is OO unlike checking for null all over the place.
          Hide
          Ralph Goers added a comment -

          Yes, that make sense to me as well.

          Show
          Ralph Goers added a comment - Yes, that make sense to me as well.
          Hide
          Remko Popma added a comment -

          Log4jLogEvent constructor and RingBufferLogEvent.getLevel now convert null Level to Level.OFF to prevent NPEs.

          Fixed in revision 1555339.
          Please verify and close.

          Show
          Remko Popma added a comment - Log4jLogEvent constructor and RingBufferLogEvent.getLevel now convert null Level to Level.OFF to prevent NPEs. Fixed in revision 1555339. Please verify and close.

            People

            • Assignee:
              Remko Popma
              Reporter:
              Daisuke Baba
            • Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development