[
https://issues.apache.org/jira/browse/LOG4J2-391?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13904729#comment-13904729
]
Steve Sulatycki commented on LOG4J2-391:
----------------------------------------
Though this has been closed, this issue still persists in beta9. We have
multiple servers/services that have had this error, which effectively stops the
Flume logging.
Version: beta9
Config: Running async loggers, with the following parameters:
-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
-DAsyncLogger.RingBufferSize=512
-DAsyncLogger.WaitStrategy=Block
OSes:
1. SunOS 5.10 Generic_141445-09 i86pc i386 i86pc
2. Linux 2.6.32-220.el6.x86_64 #1 SMP Tue Dec 6 19:48:22 GMT 2011 x86_64 x86_64
x86_64 GNU/Linux
Error seen in logs:
2014-02-04 16:00:19,945 ERROR Error reading database
com.sleepycat.je.LockTimeoutException: (JE 5.0.73) Lock expired. Locker
31404296 -1_Thread-3_ThreadLocker: waited for lock on
database=FlumePersistent[agent01:44444,agent02:44444] /logs/flume
LockAddr:793535 LSN=0x5f/0x7004b8 type=READ grant=WAIT_NEW timeoutMillis=5000
startTime=1391529614658 endTime=1391529619941
Owners: [<LockInfo locker="28110478 856908_DaemonPool-1-thread-36_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.run(FlumePersistentManager.java:460)
2014-02-04 16:00:21,591 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:166)
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.config.LoggerConfig.callAppenders(LoggerConfig.java:426)
at
org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:407)
at
org.apache.logging.log4j.core.Logger$PrivateConfig.logEvent(Logger.java:273)
at
org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:240)
at
org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:97)
at
org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:43)
at
org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:28)
at
com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:133)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:619)
I would suggest that the retry and timeout parameters be made configurable so
that they may be tuned for specific needs.
> 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
> Fix For: 2.0-beta9
>
> Attachments: log4j2-391_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 was sent by Atlassian JIRA
(v6.1.5#6160)
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-dev-h...@logging.apache.org
