You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by "Kamal Bahadur (JIRA)" <ji...@apache.org> on 2013/09/05 21:55:51 UTC
[jira] [Updated] (LOG4J2-391) Flume appender crashes when lock
timeout occurs
[ https://issues.apache.org/jira/browse/LOG4J2-391?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Kamal Bahadur updated LOG4J2-391:
---------------------------------
Attachment: patch.txt
Attached is a patch to fix this bug. Basically, I have added a logic to sleep for 500 milliseconds and retry if lock related exception occurs. It will retry 100 times before setting the errors to true. This should prevent the FlumePersistentManager to shutdown.
> Flume appender crashes when lock timeout occurs
> -----------------------------------------------
>
> Key: LOG4J2-391
> URL: https://issues.apache.org/jira/browse/LOG4J2-391
> Project: Log4j 2
> Issue Type: Bug
> Components: Appenders
> Affects Versions: 2.0-beta9
> Environment: Rhel 5
> Reporter: Kamal Bahadur
> Attachments: patch.txt
>
>
> 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)
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org