[FLUME-2186] Log4jAppender throws a NPE when Flume is turned off - ASF JIRA

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:

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

- Sort By Name
- Sort By Date
- Ascending
- Descending

FLUME-2186-0.patch
12/Dec/13 09:12
1 kB
Ashish Paliwal
FLUME-2186-1.patch
12/Dec/13 09:51
2 kB
Ashish Paliwal
FLUME-2186-2.patch
13/Dec/13 06:06
3 kB
Ashish Paliwal
FLUME-2186-3.patch
13/Dec/13 06:20
3 kB
Ashish Paliwal
FLUME-2186-4.patch
14/Dec/13 06:59
4 kB
Ashish Paliwal

Issue Links

links to

Review Request

Log4jAppender throws a NPE when Flume is turned off

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates