[LOG4J2-391] Flume appender crashes when lock timeout occurs

• Type: Bug
• Status: Closed
• Priority: Blocker
• Resolution: Fixed
• Affects Version/s: 2.0-beta9
• Fix Version/s: 2.1
• Component/s: Appenders

Environment

Rhel 5

• Assignee: Unassigned
• Reporter: Kamal Bahadur
• Created: 04/Sep/13 16:18
• Updated: 10/Sep/14 23:40
• Resolved: 10/Sep/14 05:18

Description

Flume appender seems to crash when it can't acquire the lock on the embeded Berkeley DB before the timeout period. The flume appender should retry when this happens. Here is the stack trace:

2013-08-20 22:40:36,315 -0700 level=INFO class=STDOUT 2013-08-20 22:40:36,314 ERROR Error reading database com.sleepycat.je.LockTimeoutException: (JE 5.0.73) Lock expired. Locker 988835149 -1_Thread-12_ThreadLocker: waited for lock on database=FlumePersistent[pprdgblas30i.ie.intuit.net:8800,pprdgblas30c.ie.intuit.net:8800,pprdgblas30b.ie.intuit.net:8800] /usr/local/whp-jboss-ws-5/server/default/flumeData LockAddr:2123888757 LSN=0x93/0x2d3184 type=READ grant=WAIT_NEW timeoutMillis=5000 startTime=1377063631308 endTime=1377063636310
Owners: [<LockInfo locker="1275407544 1268918_DaemonPool-1-thread-2902_Txn" type="WRITE"/>]
Waiters: []

at com.sleepycat.je.txn.LockManager.newLockTimeoutException(LockManager.java:664)
at com.sleepycat.je.txn.LockManager.makeTimeoutMsgInternal(LockManager.java:623)
at com.sleepycat.je.txn.SyncedLockManager.makeTimeoutMsg(SyncedLockManager.java:97)
at com.sleepycat.je.txn.LockManager.lockInternal(LockManager.java:390)
at com.sleepycat.je.txn.LockManager.lock(LockManager.java:276)
at com.sleepycat.je.txn.BasicLocker.lockInternal(BasicLocker.java:118)
at com.sleepycat.je.txn.Locker.lock(Locker.java:443)
at com.sleepycat.je.dbi.CursorImpl.lockLN(CursorImpl.java:2621)
at com.sleepycat.je.dbi.CursorImpl.lockLN(CursorImpl.java:2422)
at com.sleepycat.je.dbi.CursorImpl.fetchCurrent(CursorImpl.java:2253)
at com.sleepycat.je.dbi.CursorImpl.getCurrentAlreadyLatched(CursorImpl.java:1466)
at com.sleepycat.je.dbi.CursorImpl.getNext(CursorImpl.java:1593)
at com.sleepycat.je.Cursor.retrieveNextAllowPhantoms(Cursor.java:2924)
at com.sleepycat.je.Cursor.retrieveNextNoDups(Cursor.java:2801)
at com.sleepycat.je.Cursor.retrieveNext(Cursor.java:2775)
at com.sleepycat.je.Cursor.getNext(Cursor.java:1128)
at org.apache.logging.log4j.flume.appender.FlumePersistentManager$WriterThread.sendBatch(FlumePersistentManager.java:568)
at org.apache.logging.log4j.flume.appender.FlumePersistentManager$WriterThread.run(FlumePersistentManager.java:473)
2013-08-20 22:40:56,947 -0700 level=INFO class=STDOUT 2ba4851d-0a24-11e3-9b42-005056b5071b 2013-08-20 22:40:56,946 ERROR An exception occurred processing Appender flume org.apache.logging.log4j.LoggingException: Unable to record event
at org.apache.logging.log4j.flume.appender.FlumePersistentManager.send(FlumePersistentManager.java:172)
at org.apache.logging.log4j.flume.appender.FlumeAppender.append(FlumeAppender.java:102)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:102)
at org.apache.logging.log4j.core.appender.rewrite.RewriteAppender.append(RewriteAppender.java:92)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:102)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:426)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:407)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:368)
at org.apache.logging.log4j.core.Logger.log(Logger.java:110)
at org.apache.logging.log4j.spi.AbstractLoggerWrapper.log(AbstractLoggerWrapper.java:55)
at org.apache.logging.log4j.EventLogger.logEvent(EventLogger.java:56)
at com.intuit.ifs.globallogging.dto.LogEventFactory$AuditProxy.invoke(LogEventFactory.java:242)
at $Proxy161.logEvent(Unknown Source)
at com.intuit.ifs.globallogging.fakeapp.LoggingController.startLogging(LoggingController.java:157)
at sun.reflect.GeneratedMethodAccessor179.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.invokeHandlerMethod(HandlerMethodInvoker.java:176)
at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.invokeHandlerMethod(AnnotationMethodHandlerAdapter.java:436)
at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.handle(AnnotationMethodHandlerAdapter.java:424)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:923)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:852)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:882)
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:778)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:617)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:183)
at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:95)
at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
at org.apache.catalina.authenticator.SingleSignOn.invoke(SingleSignOn.java:383)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.internalProcess(ActiveRequestResponseCacheValve.java:74)
at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.invoke(ActiveRequestResponseCacheValve.java:47)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:829)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:599)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:451)
at java.lang.Thread.run(Thread.java:662)
2013-08-20 22:40:57,559 -0700 level=INFO class=STDOUT 2be29f90-0a24-11e3-9b42-005056b5071b 2013-08-20 22:40:57,557 ERROR An exception occurred processing Appender flume org.apache.logging.log4j.LoggingException: Unable to record event
at org.apache.logging.log4j.flume.appender.FlumePersistentManager.send(FlumePersistentManager.java:172)
at org.apache.logging.log4j.flume.appender.FlumeAppender.append(FlumeAppender.java:102)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:102)
at org.apache.logging.log4j.core.appender.rewrite.RewriteAppender.append(RewriteAppender.java:92)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:102)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:426)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:407)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:368)
at org.apache.logging.log4j.core.Logger.log(Logger.java:110)
at org.apache.logging.log4j.spi.AbstractLoggerWrapper.log(AbstractLoggerWrapper.java:55)
at org.apache.logging.log4j.EventLogger.logEvent(EventLogger.java:56)
at com.intuit.ifs.globallogging.dto.LogEventFactory$AuditProxy.invoke(LogEventFactory.java:242)
at $Proxy199.logEvent(Unknown Source)
at com.intuit.ifs.globallogging.fakeapp.LoggingController.startLogging(LoggingController.java:157)
at sun.reflect.GeneratedMethodAccessor179.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.invokeHandlerMethod(HandlerMethodInvoker.java:176)
at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.invokeHandlerMethod(AnnotationMethodHandlerAdapter.java:436)
at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.handle(AnnotationMethodHandlerAdapter.java:424)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:923)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:852)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:882)
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:778)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:617)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:183)
at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:95)
at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
at org.apache.catalina.authenticator.SingleSignOn.invoke(SingleSignOn.java:383)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.internalProcess(ActiveRequestResponseCacheValve.java:74)
at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.invoke(ActiveRequestResponseCacheValve.java:47)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:829)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:599)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:451)
at java.lang.Thread.run(Thread.java:662)
2013-08-20 22:40:58,641 -0700 level=INFO class=STDOUT 3060d4b8-0a24-11e3-9b42-005056b5071b 2013-08-20 22:40:58,639 ERROR An exception occurred processing Appender flume org.apache.logging.log4j.LoggingException: Unable to record event
at org.apache.logging.log4j.flume.appender.FlumePersistentManager.send(FlumePersistentManager.java:172)
at org.apache.logging.log4j.flume.appender.FlumeAppender.append(FlumeAppender.java:102)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:102)
at org.apache.logging.log4j.core.appender.rewrite.RewriteAppender.append(RewriteAppender.java:92)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:102)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:426)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:407)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:368)
at org.apache.logging.log4j.core.Logger.log(Logger.java:110)
at org.apache.logging.log4j.spi.AbstractLoggerWrapper.log(AbstractLoggerWrapper.java:55)
at org.apache.logging.log4j.EventLogger.logEvent(EventLogger.java:56)
at com.intuit.ifs.globallogging.dto.LogEventFactory$AuditProxy.invoke(LogEventFactory.java:242)
at $Proxy162.logEvent(Unknown Source)
at com.intuit.ifs.globallogging.fakeapp.LoggingController.startLogging(LoggingController.java:157)
at sun.reflect.GeneratedMethodAccessor179.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.invokeHandlerMethod(HandlerMethodInvoker.java:176)
at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.invokeHandlerMethod(AnnotationMethodHandlerAdapter.java:436)
at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.handle(AnnotationMethodHandlerAdapter.java:424)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:923)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:852)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:882)
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:778)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:617)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:183)
at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:95)
at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
at org.apache.catalina.authenticator.SingleSignOn.invoke(SingleSignOn.java:383)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.internalProcess(ActiveRequestResponseCacheValve.java:74)
at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.invoke(ActiveRequestResponseCacheValve.java:47)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:829)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:599)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:451)
at java.lang.Thread.run(Thread.java:662)