Uploaded image for project: 'Flume'
  1. Flume
  2. FLUME-2186

Log4jAppender throws a NPE when Flume is turned off

Attach filesAttach ScreenshotAdd voteVotersWatch issueWatchersCreate sub-taskLinkCloneUpdate Comment AuthorReplace String in CommentUpdate Comment VisibilityDelete Comments
    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Patch Available
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 1.4.0
    • Fix Version/s: None
    • Component/s: Client SDK
    • Labels:
      None
    • Environment:

      Java 1.6.0_26
      Flume 1.4.0

      Description

      When Log4jAppender loses its connection to Flume, it will meet a NPE.

      My test Flume agent:

      a1.sources = r1
      a1.sinks = k1
      a1.channels = c1

      a1.sources.r1.type = avro
      a1.sources.r1.bind = 0.0.0.0
      a1.sources.r1.port = 4141

      a1.sinks.k1.type = null

      a1.channels.c1.type = memory

      a1.sources.r1.channels = c1
      a1.sinks.k1.channel = c1

      My Log4J property file for the Flume appender:

      log4j.appender.FLUME = org.apache.flume.clients.log4jappender.Log4jAppender
      log4j.appender.FLUME.Hostname = localhost
      log4j.appender.FLUME.Port = 4141
      log4j.appender.FLUME.UnsafeMode = true

      For the issue, I made a simple JUnit:

      public class FlumeLog4jAppenderTest {
        private static final org.apache.log4j.Logger LOGGER = org.apache.log4j.Logger.getLogger(FlumeLog4jAppenderTest.class);
      
        @Test
        public void theMillionLog() {
          int MAX = 1000000;
          for (int i = 0; i < MAX; i++) {
            LOGGER.info(String.format("This is a dummy log, %1$d/%2$d", i, MAX));
          }
        }
      
      }
      

      Scenario:
      1) Run Flume
      2) Run the Java app
      3) Turn Flume off

      The Java app will log:

      ...
      [INFO] 13:22:18,246 com.test.FlumeLog4jAppenderTest.theMillionLog(FlumeLog4jAppenderTest.java:15) This is a dummy log, 301/1000000
      [INFO] 13:22:18,251 com.test.FlumeLog4jAppenderTest.theMillionLog(FlumeLog4jAppenderTest.java:15) This is a dummy log, 302/1000000
      [INFO] 13:22:18,254 com.test.FlumeLog4jAppenderTest.theMillionLog(FlumeLog4jAppenderTest.java:15) This is a dummy log, 303/1000000
      [INFO] 13:22:18,257 com.test.FlumeLog4jAppenderTest.theMillionLog(FlumeLog4jAppenderTest.java:15) This is a dummy log, 304/1000000
      [INFO] 13:22:18,261 com.test.FlumeLog4jAppenderTest.theMillionLog(FlumeLog4jAppenderTest.java:15) This is a dummy log, 305/1000000
      [INFO] 13:22:18,265 com.test.FlumeLog4jAppenderTest.theMillionLog(FlumeLog4jAppenderTest.java:15) This is a dummy log, 306/1000000
      [INFO] 13:22:18,269 com.test.FlumeLog4jAppenderTest.theMillionLog(FlumeLog4jAppenderTest.java:15) This is a dummy log, 307/1000000
      [INFO] 13:22:18,274 com.test.FlumeLog4jAppenderTest.theMillionLog(FlumeLog4jAppenderTest.java:15) This is a dummy log, 308/1000000
      [INFO] 13:22:18,281 com.test.FlumeLog4jAppenderTest.theMillionLog(FlumeLog4jAppenderTest.java:15) This is a dummy log, 309/1000000
      [INFO] 13:22:18,286 com.test.FlumeLog4jAppenderTest.theMillionLog(FlumeLog4jAppenderTest.java:15) This is a dummy log, 310/1000000
      log4j:ERROR Flume append() failed.
      [INFO] 13:22:18,291 com.test.FlumeLog4jAppenderTest.theMillionLog(FlumeLog4jAppenderTest.java:15) This is a dummy log, 311/1000000
      log4j:ERROR RPC client creation failed! NettyAvroRpcClient { host: localhost, port: 4141 }: RPC connection error
      

      ... and will stop.

      Here is the stacktrace (JUnit runned in Eclipse):

      FlumeLog4jAppenderTest
      com.test.FlumeLog4jAppenderTest
      theMillionLog(com.test.FlumeLog4jAppenderTest)
      java.lang.NullPointerException
      	at org.apache.flume.clients.log4jappender.Log4jAppender.append(Log4jAppender.java:163)
      	at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
      	at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
      	at org.apache.log4j.Category.callAppenders(Category.java:206)
      	at org.apache.log4j.Category.forcedLog(Category.java:391)
      	at org.apache.log4j.Category.info(Category.java:666)
      	at com.test.FlumeLog4jAppenderTest.theMillionLog(FlumeLog4jAppenderTest.java:15)
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      	at java.lang.reflect.Method.invoke(Method.java:597)
      	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
      	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
      	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
      	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
      	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
      	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
      	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
      	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
      	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
      	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
      	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
      	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
      	at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
      	at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:50)
      	at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
      	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)
      	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)
      	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)
      	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)
      
      

      Explanation:

      (This logging error is done here: https://git-wip-us.apache.org/repos/asf?p=flume.git;a=blob;f=flume-ng-clients/flume-ng-log4jappender/src/main/java/org/apache/flume/clients/log4jappender/Log4jAppender.java;h=b07b189701d30e1789a8543b020b53aca1acee34;hb=756924e96ace470289472a3bdb4d87e273ca74ef#l313)
      Note: reconnect() is just calling close() (close rpcClient then set rpcClient to null) and activateOptions() (reconfigure the rpcClient)

      • BUT, since rpcClient has been set to null by the close() method, and activateOptions() failed, rpcClient remains null. Then rpcClient.append(event) will throw a NPE.

        Attachments

        1. FLUME-2186-0.patch
          1 kB
          Ashish Paliwal
        2. FLUME-2186-1.patch
          2 kB
          Ashish Paliwal
        3. FLUME-2186-2.patch
          3 kB
          Ashish Paliwal
        4. FLUME-2186-3.patch
          3 kB
          Ashish Paliwal
        5. FLUME-2186-4.patch
          4 kB
          Ashish Paliwal

          Activity

            People

            • Assignee:
              paliwalashish Ashish Paliwal
              Reporter:
              christophel X-Tough

              Dates

              • Created:
                Updated:

                Issue deployment