Using Logback 0.9.24 and SLF4J 1.6.1. I'm trying to resolve a hang problem with the ch.qos.logback.classic.net.SMTPAppender in an integration test and using SubethaSMTP as the email server. We have many tests working with SubethaSMTP that send emails, but not with Logback, so I know it works for the non-Logback configuration. I've also seen SMTPAppender work in a different situation to the production email server. So I think I have a config error somewhere with Logback setup to SubethaSMTP, but not sure what, or there is an issue in the LB & SS interaction. This is the SMTPAppender config: <appender name="EMAIL" class="ch.qos.logback.classic.net.SMTPAppender"> <layout class="ch.qos.logback.classic.html.HTMLLayout"> <pattern>%date%contextName%thread%-5level%-55logger{55}%mdc%marker%msg</pattern> <throwableRenderer class="ch.qos.logback.classic.html.DefaultThrowableRenderer" /> </layout> <SMTPHost>${mail.host.name}</SMTPHost> <SMTPPort>${mail.port.number}</SMTPPort> <From>${batch.email.address.from}</From> <To>${batch.email.address.to.cmrdevelopers}</To> <Subject>${batch.email.subject.prefix}Log Email: %msg</Subject> <evaluator class="ch.qos.logback.classic.boolex.OnMarkerEvaluator"> <marker>EMAIL_DEVS</marker> </evaluator> </appender> It hangs on call to SocketInputStream.socketRead0(), which is a native method. Anyone seen/solved this before? The timeout value is 0 on the socket read (means wait forever), so it is waiting for a response to read. While I'm trying to resolve this, one thing I'd like to do is set the timeout value so at least it doesn't hang. I'm not sure how to do that with SMTPAppender - anyone know how? The SMTPAppender/SMTPAppenderBase class does not have a timeout property, but SMTPAppenderBase does pull system properties. I'm hoping there is a config file-based approach to do this though... The following is a call stack captured in the Eclipse debugger; the next line-step would go into socketRead0() and hang. org.eclipse.jdt.internal.junit.runner.RemoteTestRunner at localhost:3598 Thread [main] (Suspended) SocketInputStream.read(byte[], int, int) line: 129 TraceInputStream.read(byte[], int, int) line: 97 BufferedInputStream.fill() line: 218 BufferedInputStream.read() line: 237 LineInputStream.readLine() line: 75 SMTPTransport.readServerResponse() line: 1440 SMTPTransport.openServer(String, int) line: 1260 SMTPTransport.protocolConnect(String, int, String, String) line: 370 SMTPTransport(Service).connect(String, int, String, String) line: 275 SMTPTransport(Service).connect(String, String, String) line: 156 SMTPTransport(Service).connect() line: 105 Transport.send0(Message, Address[]) line: 168 Transport.send(Message) line: 98 SMTPAppender(SMTPAppenderBase<E>).sendBuffer(E) line: 292 SMTPAppender(SMTPAppenderBase<E>).append(E) line: 159 SMTPAppender(AppenderBase<E>).doAppend(E) line: 85 AppenderAttachableImpl<E>.appendLoopOnAppenders(E) line: 64 Logger.appendLoopOnAppenders(ILoggingEvent) line: 283 Logger.callAppenders(ILoggingEvent) line: 270 Logger.buildLoggingEventAndAppend(String, Marker, Level, String, Object[], Throwable) line: 471 Logger.filterAndLog_0_Or3Plus(String, Marker, Level, String, Object[], Throwable) line: 425 Logger.error(Marker, String) line: 592 LoggerEmailTest.testEmailSend() line: 99 NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method] NativeMethodAccessorImpl.invoke(Object, Object[]) line: 39 DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 25 Method.invoke(Object, Object...) line: 597 FrameworkMethod$1.runReflectiveCall() line: 44 FrameworkMethod$1(ReflectiveCallable).run() line: 15 FrameworkMethod.invokeExplosively(Object, Object...) line: 41 InvokeMethod.evaluate() line: 20 RunBefores.evaluate() line: 28 RunBeforeTestMethodCallbacks.evaluate() line: 74 RunAfters.evaluate() line: 31 RunAfterTestMethodCallbacks.evaluate() line: 82 SpringRepeat.evaluate() line: 72 SpringJUnit4ClassRunner.runChild(FrameworkMethod, RunNotifier) line: 240 SpringJUnit4ClassRunner(BlockJUnit4ClassRunner).runChild(Object, RunNotifier) line: 50 ParentRunner$3.run() line: 193 ParentRunner$1.schedule(Runnable) line: 52 SpringJUnit4ClassRunner(ParentRunner<T>).runChildren(RunNotifier) line: 191 ParentRunner<T>.access$000(ParentRunner, RunNotifier) line: 42 ParentRunner$2.evaluate() line: 184 RunBeforeTestClassCallbacks.evaluate() line: 61 RunAfterTestClassCallbacks.evaluate() line: 70 SpringJUnit4ClassRunner(ParentRunner<T>).run(RunNotifier) line: 236 SpringJUnit4ClassRunner.run(RunNotifier) line: 180 JUnit4TestClassReference(JUnit4TestReference).run(TestExecution) line: 46 TestExecution.run(ITestReference[]) line: 38 RemoteTestRunner.runTests(String[], String, TestExecution) line: 467 RemoteTestRunner.runTests(TestExecution) line: 683 RemoteTestRunner.run() line: 390 RemoteTestRunner.main(String[]) line: 197 Thread [ReaderThread] (Running) Thread [org.subethamail.smtp.server.SMTPServer] (Running) Thread [org.subethamail.smtp.server.Session-/127.0.0.1:3601] (Running)
The line numbers in the stack trace you sent indicate an earlier version of logback, probably version 0.9.20 or 0.9.21. In the past we also ran into problems while testing SMTPAppender with SubethaSMTP. If my memory serves me correctly, it was due to a race condition. Maybe the server is shutdown before SMTPAppender has a chance to receive the response of the server. On 23/07/2010 4:54 PM, Jeff Jensen wrote:
Using Logback 0.9.24 and SLF4J 1.6.1.
I'm trying to resolve a hang problem with the ch.qos.logback.classic.net.SMTPAppender in an integration test and using SubethaSMTP as the email server. We have many tests working with SubethaSMTP that send emails, but not with Logback, so I know it works for the non-Logback configuration. I've also seen SMTPAppender work in a different situation to the production email server. So I think I have a config error somewhere with Logback setup to SubethaSMTP, but not sure what, or there is an issue in the LB & SS interaction.
This is the SMTPAppender config:
<appender name="EMAIL" class="ch.qos.logback.classic.net.SMTPAppender"> <layout class="ch.qos.logback.classic.html.HTMLLayout"> <pattern>%date%contextName%thread%-5level%-55logger{55}%mdc%marker%msg</pattern>
<throwableRenderer class="ch.qos.logback.classic.html.DefaultThrowableRenderer" /> </layout> <SMTPHost>${mail.host.name}</SMTPHost> <SMTPPort>${mail.port.number}</SMTPPort> <From>${batch.email.address.from}</From> <To>${batch.email.address.to.cmrdevelopers}</To> <Subject>${batch.email.subject.prefix}Log Email: %msg</Subject> <evaluator class="ch.qos.logback.classic.boolex.OnMarkerEvaluator"> <marker>EMAIL_DEVS</marker> </evaluator> </appender>
It hangs on call to SocketInputStream.socketRead0(), which is a native method. Anyone seen/solved this before?
The timeout value is 0 on the socket read (means wait forever), so it is waiting for a response to read.
While I'm trying to resolve this, one thing I'd like to do is set the timeout value so at least it doesn't hang. I'm not sure how to do that with SMTPAppender - anyone know how? The SMTPAppender/SMTPAppenderBase class does not have a timeout property, but SMTPAppenderBase does pull system properties. I'm hoping there is a config file-based approach to do this though...
The following is a call stack captured in the Eclipse debugger; the next line-step would go into socketRead0() and hang.
org.eclipse.jdt.internal.junit.runner.RemoteTestRunner at localhost:3598 Thread [main] (Suspended) SocketInputStream.read(byte[], int, int) line: 129 TraceInputStream.read(byte[], int, int) line: 97 BufferedInputStream.fill() line: 218 BufferedInputStream.read() line: 237 LineInputStream.readLine() line: 75 SMTPTransport.readServerResponse() line: 1440 SMTPTransport.openServer(String, int) line: 1260 SMTPTransport.protocolConnect(String, int, String, String) line: 370 SMTPTransport(Service).connect(String, int, String, String) line: 275 SMTPTransport(Service).connect(String, String, String) line: 156 SMTPTransport(Service).connect() line: 105 Transport.send0(Message, Address[]) line: 168 Transport.send(Message) line: 98 SMTPAppender(SMTPAppenderBase<E>).sendBuffer(E) line: 292 SMTPAppender(SMTPAppenderBase<E>).append(E) line: 159 SMTPAppender(AppenderBase<E>).doAppend(E) line: 85 AppenderAttachableImpl<E>.appendLoopOnAppenders(E) line: 64 Logger.appendLoopOnAppenders(ILoggingEvent) line: 283 Logger.callAppenders(ILoggingEvent) line: 270 Logger.buildLoggingEventAndAppend(String, Marker, Level, String, Object[], Throwable) line: 471 Logger.filterAndLog_0_Or3Plus(String, Marker, Level, String, Object[], Throwable) line: 425 Logger.error(Marker, String) line: 592 LoggerEmailTest.testEmailSend() line: 99 NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method] NativeMethodAccessorImpl.invoke(Object, Object[]) line: 39 DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 25 Method.invoke(Object, Object...) line: 597 FrameworkMethod$1.runReflectiveCall() line: 44 FrameworkMethod$1(ReflectiveCallable).run() line: 15 FrameworkMethod.invokeExplosively(Object, Object...) line: 41 InvokeMethod.evaluate() line: 20 RunBefores.evaluate() line: 28 RunBeforeTestMethodCallbacks.evaluate() line: 74 RunAfters.evaluate() line: 31 RunAfterTestMethodCallbacks.evaluate() line: 82 SpringRepeat.evaluate() line: 72 SpringJUnit4ClassRunner.runChild(FrameworkMethod, RunNotifier) line: 240
SpringJUnit4ClassRunner(BlockJUnit4ClassRunner).runChild(Object, RunNotifier) line: 50 ParentRunner$3.run() line: 193 ParentRunner$1.schedule(Runnable) line: 52
SpringJUnit4ClassRunner(ParentRunner<T>).runChildren(RunNotifier) line: 191 ParentRunner<T>.access$000(ParentRunner, RunNotifier) line: 42 ParentRunner$2.evaluate() line: 184 RunBeforeTestClassCallbacks.evaluate() line: 61 RunAfterTestClassCallbacks.evaluate() line: 70 SpringJUnit4ClassRunner(ParentRunner<T>).run(RunNotifier) line: 236 SpringJUnit4ClassRunner.run(RunNotifier) line: 180
JUnit4TestClassReference(JUnit4TestReference).run(TestExecution) line: 46 TestExecution.run(ITestReference[]) line: 38 RemoteTestRunner.runTests(String[], String, TestExecution) line: 467 RemoteTestRunner.runTests(TestExecution) line: 683 RemoteTestRunner.run() line: 390 RemoteTestRunner.main(String[]) line: 197 Thread [ReaderThread] (Running) Thread [org.subethamail.smtp.server.SMTPServer] (Running) Thread [org.subethamail.smtp.server.Session-/127.0.0.1:3601] (Running)
On 23/07/2010 5:46 PM, Jeff Jensen wrote:
Hi Ceki, thanks for the reply. Welcome.
Yes, I upgraded to 0.9.24 while investigating this problem. I must have captured the stack before that.
OK.
I wondered about a race condition too. To try mitigate that at SubethaSMTP start/shutdown, I added Thread.sleep(10000) calls after start and before shutdown. There was no change; is 10 seconds long enough to wait to see if a shutdown server is the problem?
Yes, 10 seconds is more than enough.
Any suggestion for setting the timeout value via Logback?
As I mentioned in my previous mail, we also use SubethaSMTP for testing purposes. See SMTPAppender_SubethaSMTPTest [1]. Could you copy and paste SMTPAppender_SubethaSMTPTest into your environment and see if it runs properly? If it runs OK, I suggest comparing the code in SMTPAppender_SubethaSMTPTest with your test code. [1] http://logback.qos.ch/xref-test/ch/qos/logback/classic/net/SMTPAppender_Sube... -- Ceki
Tying up loose ends... so many problems later! I started resolving the needed compile deps to run SMTPAppender_SubethaSMTPTest, but never finished. I found that having a DEBUG logger on org.subethamail causes the test to hang, as simple as: <logger name="org.subethamail" level="DEBUG" /> My guess is the tiny bit of extra processing of its messages must cause a race condition to miss reading the response (?). Any chance of adding the timeout attribute to SMTP appender? I still think it is a good idea, and would like to set it. http://jira.qos.ch/browse/LBCLASSIC-220 -----Original Message----- From: logback-user-bounces@qos.ch [mailto:logback-user-bounces@qos.ch] On Behalf Of Ceki Gülcü Sent: Friday, July 23, 2010 11:17 AM To: logback users list Subject: Re: [logback-user] Hang with SMTPAppender On 23/07/2010 5:46 PM, Jeff Jensen wrote:
Hi Ceki, thanks for the reply. Welcome.
Yes, I upgraded to 0.9.24 while investigating this problem. I must have captured the stack before that.
OK.
I wondered about a race condition too. To try mitigate that at SubethaSMTP start/shutdown, I added Thread.sleep(10000) calls after start and before shutdown. There was no change; is 10 seconds long enough to wait to see if a shutdown server is the problem?
Yes, 10 seconds is more than enough.
Any suggestion for setting the timeout value via Logback?
As I mentioned in my previous mail, we also use SubethaSMTP for testing purposes. See SMTPAppender_SubethaSMTPTest [1]. Could you copy and paste SMTPAppender_SubethaSMTPTest into your environment and see if it runs properly? If it runs OK, I suggest comparing the code in SMTPAppender_SubethaSMTPTest with your test code. [1] http://logback.qos.ch/xref-test/ch/qos/logback/classic/net/SMTPAppender_Sube thaSMTPTest.html -- Ceki _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user
participants (2)
-
Ceki Gülcü -
Jeff Jensen