[jboss-jira] [JBoss JIRA] (JBAS-9455) StackOverflowError from SMTPAppender error loop

StackOverflowError from SMTPAppender error loop ----------------------------------------------- Key: JBAS-9455 URL: https://issues.jboss.org/browse/JBAS-9455 Project: Application Server 3 4 5 and 6 Issue Type: Bug Security Level: Public(Everyone can see) Components: Logging Affects Versions: 6.0.0.Final Environment: Centos 5.6, Sun JVM 1.6 update 14 Reporter: Antti Kuusela What happened: JBoss AS 6.0.0.Final crashed with java.lang.StackOverflowError. Before the crash the following line is repeated dozens of times: ERROR [STDERR] (http-0.0.0.0-8443-15) log4j:ERROR Error occured while sending e-mail notification. This has happened for me once before, with the same server. The smtp server runs on the same computer and is exclusively used by the JBoss AS. The application uses MySQL 5.1.53, connector version 5.1.13 and com.mysql.jdbc.jdbc2.optional.MysqlXADataSource. See below for stack trace. What I think happened: I have JBoss AS 6.0.0.Final set up to send error messages via email to developers using SMTPAppender. This caused the server to crash with java.lang.StackOverflowError due to the SMTPAppender getting stuck in a loop. For some reason sending email failed, and the SMTPAppender tried sending the resulting error message via email. This caused the above error message, which again triggered SMTPAppender to forward it via email. SMTPAppender should detect said loop, and moreso the error message shouldn't be printed to STDERR. If it were printed directly via the logger, I could work around this by setting log level to FATAL for the specific class. The culprit for that is most likely in javamail, though. I sadly don't have a lot that could help figuring out why email sending fails. This issue is not repeated when I just simply shut down the smtp service. Right before the spam to STDERR started, there was a transaction rollback (included below, see above for MySQL version info). It isn't the most critical issue here, though. Stacktraces: ... 2011-12-06 03:39:45,453 ERROR [STDERR] (http-0.0.0.0-8443-15) log4j:ERROR Error occured while sending e-mail notification. 2011-12-06 03:39:45,467 ERROR [STDERR] (http-0.0.0.0-8443-15) log4j:ERROR Error occured while sending e-mail notification. 2011-12-06 03:39:45,481 ERROR [STDERR] (http-0.0.0.0-8443-15) log4j:ERROR Error occured while sending e-mail notification. 2011-12-06 03:39:45,495 ERROR [STDERR] (http-0.0.0.0-8443-15) log4j:ERROR Error occured while sending e-mail notification. 2011-12-06 03:39:45,505 ERROR [org.apache.coyote.http11.Http11Protocol] (http-0.0.0.0-8443-15) Error reading request, ignored: java.lang.StackOverflowError at sun.nio.cs.UTF_8$Encoder.encodeLoop(UTF_8.java:447) [:1.6.0_14] at java.nio.charset.CharsetEncoder.encode(CharsetEncoder.java:544) [:1.6.0_14] at java.lang.StringCoding$StringEncoder.encode(StringCoding.java:240) [:1.6.0_14] at java.lang.StringCoding.encode(StringCoding.java:272) [:1.6.0_14] at java.lang.String.getBytes(String.java:946) [:1.6.0_14] at java.net.Inet4AddressImpl.lookupAllHostAddr(Native Method) [:1.6.0_14] at java.net.InetAddress$1.lookupAllHostAddr(InetAddress.java:849) [:1.6.0_14] at java.net.InetAddress.getAddressFromNameService(InetAddress.java:1200) [:1.6.0_14] at java.net.InetAddress.getLocalHost(InetAddress.java:1350) [:1.6.0_14] at javax.mail.internet.InternetAddress.getLocalAddress(InternetAddress.java:523) [:1.4.2] at javax.mail.internet.UniqueValue.getUniqueMessageIDValue(UniqueValue.java:95) [:1.4.2] at javax.mail.internet.MimeMessage.updateMessageID(MimeMessage.java:2050) [:1.4.2] at javax.mail.internet.MimeMessage.updateHeaders(MimeMessage.java:2073) [:1.4.2] at javax.mail.internet.MimeMessage.saveChanges(MimeMessage.java:2039) [:1.4.2] at javax.mail.Transport.send(Transport.java:119) [:1.4.2] at org.apache.log4j.net.SMTPAppender.sendBuffer(SMTPAppender.java:416) [:] at org.apache.log4j.net.SMTPAppender.append(SMTPAppender.java:256) [:] at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251) [:] at org.jboss.logmanager.log4j.handlers.Log4jAppenderHandler.doPublish(Log4jAppenderHandler.java:111) [:] at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:64) [jboss-logmanager.jar:1.2.0.CR10-SNAPSHOT] at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:283) [jboss-logmanager.jar:1.2.0.CR10-SNAPSHOT] at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:291) [jboss-logmanager.jar:1.2.0.CR10-SNAPSHOT] at org.jboss.logmanager.Logger.logRaw(Logger.java:649) [jboss-logmanager.jar:1.2.0.CR10-SNAPSHOT] at org.jboss.logmanager.Logger.log(Logger.java:434) [jboss-logmanager.jar:1.2.0.CR10-SNAPSHOT] at org.jboss.stdio.AbstractLoggingWriter.write(AbstractLoggingWriter.java:71) [:6.0.0.Final] at org.jboss.stdio.WriterOutputStream.finish(WriterOutputStream.java:133) [:6.0.0.Final] at org.jboss.stdio.WriterOutputStream.write(WriterOutputStream.java:114) [:6.0.0.Final] at java.io.PrintStream.write(PrintStream.java:430) [:1.6.0_14] at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) [:1.6.0_14] at sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:263) [:1.6.0_14] at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:106) [:1.6.0_14] at java.io.OutputStreamWriter.write(OutputStreamWriter.java:190) [:1.6.0_14] at java.io.BufferedWriter.flushBuffer(BufferedWriter.java:111) [:1.6.0_14] at java.io.BufferedWriter.write(BufferedWriter.java:212) [:1.6.0_14] at java.io.Writer.write(Writer.java:140) [:1.6.0_14] at java.io.PrintStream.write(PrintStream.java:475) [:1.6.0_14] at java.io.PrintStream.print(PrintStream.java:619) [:1.6.0_14] at java.io.PrintStream.println(PrintStream.java:756) [:1.6.0_14] at org.jboss.stdio.StdioContext$DelegatingPrintStream.println(StdioContext.java:297) [:6.0.0.Final] at org.apache.log4j.helpers.LogLog.error(LogLog.java:143) [:] at org.apache.log4j.net.SMTPAppender.sendBuffer(SMTPAppender.java:418) [:] at org.apache.log4j.net.SMTPAppender.append(SMTPAppender.java:256) [:] at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251) [:] at org.jboss.logmanager.log4j.handlers.Log4jAppenderHandler.doPublish(Log4jAppenderHandler.java:111) [:] at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:64) [jboss-logmanager.jar:1.2.0.CR10-SNAPSHOT] at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:283) [jboss-logmanager.jar:1.2.0.CR10-SNAPSHOT] at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:291) [jboss-logmanager.jar:1.2.0.CR10-SNAPSHOT] at org.jboss.logmanager.Logger.logRaw(Logger.java:649) [jboss-logmanager.jar:1.2.0.CR10-SNAPSHOT] at org.jboss.logmanager.Logger.log(Logger.java:434) [jboss-logmanager.jar:1.2.0.CR10-SNAPSHOT] at org.jboss.stdio.AbstractLoggingWriter.write(AbstractLoggingWriter.java:71) [:6.0.0.Final] at org.jboss.stdio.WriterOutputStream.finish(WriterOutputStream.java:133) [:6.0.0.Final] at org.jboss.stdio.WriterOutputStream.write(WriterOutputStream.java:114) [:6.0.0.Final] at java.io.PrintStream.write(PrintStream.java:430) [:1.6.0_14] at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) [:1.6.0_14] at sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:263) [:1.6.0_14] at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:106) [:1.6.0_14] at java.io.OutputStreamWriter.write(OutputStreamWriter.java:190) [:1.6.0_14] at java.io.BufferedWriter.flushBuffer(BufferedWriter.java:111) [:1.6.0_14] at java.io.BufferedWriter.write(BufferedWriter.java:212) [:1.6.0_14] at java.io.Writer.write(Writer.java:140) [:1.6.0_14] at java.io.PrintStream.write(PrintStream.java:475) [:1.6.0_14] at java.io.PrintStream.print(PrintStream.java:619) [:1.6.0_14] at java.io.PrintStream.println(PrintStream.java:756) [:1.6.0_14] at org.jboss.stdio.StdioContext$DelegatingPrintStream.println(StdioContext.java:297) [:6.0.0.Final] at org.apache.log4j.helpers.LogLog.error(LogLog.java:143) [:] at org.apache.log4j.net.SMTPAppender.sendBuffer(SMTPAppender.java:418) [:] at org.apache.log4j.net.SMTPAppender.append(SMTPAppender.java:256) [:] at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251) [:] at org.jboss.logmanager.log4j.handlers.Log4jAppenderHandler.doPublish(Log4jAppenderHandler.java:111) [:] at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:64) [jboss-logmanager.jar:1.2.0.CR10-SNAPSHOT] at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:283) [jboss-logmanager.jar:1.2.0.CR10-SNAPSHOT] at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:291) [jboss-logmanager.jar:1.2.0.CR10-SNAPSHOT] at org.jboss.logmanager.Logger.logRaw(Logger.java:649) [jboss-logmanager.jar:1.2.0.CR10-SNAPSHOT] at org.jboss.logmanager.Logger.log(Logger.java:434) [jboss-logmanager.jar:1.2.0.CR10-SNAPSHOT] ... The stacktrace continues similarly, repeating the same calls... The following appears immediate before the spam to STDERR: 2011-12-06 03:39:25,286 WARN [com.arjuna.ats.arjuna] (http-0.0.0.0-8443-15) ARJUNA-12077 Abort called on already aborted ato mic action 0:ffffd970f1c0:126a:4ed5e753:e5766 2011-12-06 03:39:25,286 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 34) ARJUNA-12113 TransactionReaper::doCancel lations worker Thread[Transaction Reaper Worker 34,5,jboss] missed interrupt when cancelling TX 0:ffffd970f1c0:126a:4ed5e753: e5766 -- exiting as zombie (zombie count decremented to 0) 2011-12-06 03:39:25,286 ERROR [org.jboss.webservices.integration.invocation.InvocationHandlerEJB3] (http-0.0.0.0-8443-15) Met hod invocation failed with exception: Transaction rolled back: javax.ejb.EJBTransactionRolledbackException: Transaction rolle d back at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.handleEndTransactionException(CMTTxInterceptor.java:115) [:0.0.1] at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:87) [:0.0.1] at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:255) [:0.0.1] at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.required(CMTTxInterceptor.java:349) [:0.0.1] at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.invoke(CMTTxInterceptor.java:209) [:0.0.1] at org.jboss.ejb3.tx2.aop.CMTTxInterceptorWrapper.invoke(CMTTxInterceptorWrapper.java:52) [:0.0.1] at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.1.GA] at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:76) [:1.0.0.GA] at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.1.GA] at org.jboss.ejb3.security.RunAsSecurityInterceptorv2.invoke(RunAsSecurityInterceptorv2.java:94) [:1.7.17] at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.1.GA] at org.jboss.ejb3.security.RoleBasedAuthorizationInterceptorv2.invoke(RoleBasedAuthorizationInterceptorv2.java:201) [ :1.7.17] at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.1.GA] at org.jboss.ejb3.security.Ejb3AuthenticationInterceptorv2.invoke(Ejb3AuthenticationInterceptorv2.java:182) [:1.7.17] at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.1.GA] at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:41) [:1.7.17] at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.1.GA] at org.jboss.ejb3.BlockContainerShutdownInterceptor.invoke(BlockContainerShutdownInterceptor.java:67) [:1.7.17] at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.1.GA] at org.jboss.ejb3.core.context.CurrentInvocationContextInterceptor.invoke(CurrentInvocationContextInterceptor.java:47 ) [:1.7.17] at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.1.GA] at org.jboss.aspects.currentinvocation.CurrentInvocationInterceptor.invoke(CurrentInvocationInterceptor.java:67) [:1.0.1] at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.1.GA] at org.jboss.ejb3.interceptor.EJB3TCCLInterceptor.invoke(EJB3TCCLInterceptor.java:86) [:1.7.17] at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) [jboss-aop.jar:2.2.1.GA] at org.jboss.ejb3.stateless.StatelessContainer.localInvoke(StatelessContainer.java:272) [:1.7.17] at org.jboss.ejb3.stateless.StatelessContainer.invokeEndpoint(StatelessContainer.java:617) [:1.7.17] at org.jboss.webservices.integration.invocation.InvocationHandlerEJB3.invoke(InvocationHandlerEJB3.java:137) [:6.0.0.Final] at org.jboss.ws.core.server.ServiceEndpointInvoker.invoke(ServiceEndpointInvoker.java:241) [:3.4.1.GA] at org.jboss.wsf.stack.jbws.RequestHandlerImpl.processRequest(RequestHandlerImpl.java:527) [:3.4.1.GA] at org.jboss.wsf.stack.jbws.RequestHandlerImpl.handleRequest(RequestHandlerImpl.java:316) [:3.4.1.GA] at org.jboss.wsf.stack.jbws.RequestHandlerImpl.doPost(RequestHandlerImpl.java:222) [:3.4.1.GA] at org.jboss.wsf.stack.jbws.RequestHandlerImpl.handleHttpRequest(RequestHandlerImpl.java:147) [:3.4.1.GA] at org.jboss.wsf.common.servlet.AbstractEndpointServlet.service(AbstractEndpointServlet.java:87) [:1.4.1.GA] at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [:1.0.0.Final] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:324) [:6.0.0.Final] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:242) [:6.0.0.Final] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [:6.0.0.Final] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) [:6.0.0.Final] at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:181) [:6.0.0.Final] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:593) [:6.0.0.Final] at org.jboss.modcluster.catalina.CatalinaContext$RequestListenerValve.event(CatalinaContext.java:285) [:1.1.0.Final] at org.jboss.modcluster.catalina.CatalinaContext$RequestListenerValve.invoke(CatalinaContext.java:261) [:1.1.0.Final] at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:88) [:6.0.0.Final] at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:100) [:6.0.0.Final] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) [:6.0.0.Final] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [:6.0.0.Final] at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158) [:6.0.0.Final] at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:567) [:6.0.0.Final] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [:6.0.0.Final] at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.invoke(ActiveRequestResponseCacheValve.java:53) [:6.0.0.Final] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:362) [:6.0.0.Final] at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [:6.0.0.Final] at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:654) [:6.0.0.Final] at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:951) [:6.0.0.Final] at java.lang.Thread.run(Thread.java:619) [:1.6.0_14] Caused by: javax.transaction.RollbackException: ARJUNA-16063 The transaction is not active! at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1148) [:6.0.0.Final] at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:119) [:6.0.0.Final] at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75) [:6.0.0.Final] at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:82) [:0.0.1] ... 54 more