Details
-
Bug
-
Status: Patch Available
-
Major
-
Resolution: Unresolved
-
1.4.0
-
None
-
None
-
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 = c1a1.sources.r1.type = avro
a1.sources.r1.bind = 0.0.0.0
a1.sources.r1.port = 4141a1.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:
- Once Flume is turned off, Log4J fails to append: 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#l163
And logs the following error:log4j:ERROR Flume append() failed.
- At the next call of append, it tries to reconnect (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#l131) without success:
log4j:ERROR RPC client creation failed! NettyAvroRpcClient { host: localhost, port: 4141 }: RPC connection error
(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
Attachments
Issue Links
- links to