Occasional deadlocking problems while connecting to IMAP server

[Henrik Martin]

Hi. I have a piece of code that runs in a Tomcat server and polls a
remote IMAP server over SSL about once every 15th seconds. The job is
scheduled using Quartz, and I have configured Quartz to not start a
new job until the previous one has finished. I.e., it's not a
multi-threaded environment. For the most part, this works very nicely,
but about once every 8-12 hours, it hangs trying to connect to the
IMAP server (my conclusion from looking at the JVM stacktrace). When
this happens, there's NO evidence whatsoever of a TCP connection
between the client and the server judging from running netstat on the
machine where the IMAP server runs! Both the client (JavaMail in
Tomcat) and the IMAP server (Cyrus 2.2.13-24.2) are running on pretty
snappy OpenSUSE Linux AMD machines (2 dual cores) with lots of RAM
and disk. Please note that the very same IMAP server handles all the
mailboxes for the company (all via SSL), and we've had no problems
with it. Also note that the timeout that is set to 180000 milliseconds
doesn't seem to help here. When the problem occurs, this will block
forever.

Here's the code snippet:

      // This line was added after googling for JavaMail and SSL
      Security.addProvider(new com.sun.net.ssl.internal.ssl.Provider());
      Properties props = System.getProperties();
      props.setProperty("mail.imap.socketFactory.class",
                        "javax.net.ssl.SSLSocketFactory");
      props.setProperty("mail.imap.socketFactory.fallback", "false");
      props.setProperty("mail.imap.starttls.enable", "true");
      props.setProperty("mail.imap.port", IMAPS_PORT);
      props.setProperty("mail.imap.socketFactory.port", IMAPS_PORT);
      props.setProperty("mail.imap.sasl.enable", "true");
      props.setProperty("mail.imap.timeout", "180000");
      props.setProperty("mail.imap.connectiontimeout", "180000");
      Session session = Session.getInstance(props);
      // session.setDebug(debug);
      store = session.getStore("imaps");
      store.connect(mailServer, mailUser, password);

The code blocks in the call to store.connect(). A JVM stack trace
follows below. Any help to fix or circumvent this problem is highly
appreciated. Thanks,

Henrik

"scheduler_Worker-3" prio=10 tid=0x00002aabf0101000 nid=0x772e runnable [0x000000004163d000..0x000000004163ec80]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:129)
        at com.sun.net.ssl.internal.ssl.InputRecord.readFully(InputRecord.java:293)
        at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:331)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:789)
        - locked <0x00002aab0db69840> (a java.lang.Object)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1096)
        - locked <0x00002aab0db697e8> (a java.lang.Object)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:744)
        at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75)
        - locked <0x00002aab0db6a630> (a com.sun.net.ssl.internal.ssl.AppInputStream)
        at com.sun.mail.util.TraceInputStream.read(TraceInputStream.java:110)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:237)
        - locked <0x00002aab0db6a8e0> (a java.io.BufferedInputStream)
        at com.sun.mail.iap.ResponseInputStream.readResponse(ResponseInputStream.java:97)
        at com.sun.mail.iap.Response.<init>(Response.java:96)
        at com.sun.mail.imap.protocol.IMAPResponse.<init>(IMAPResponse.java:61)
        at com.sun.mail.imap.protocol.IMAPResponse.readResponse(IMAPResponse.java:135)
        at com.sun.mail.imap.protocol.IMAPProtocol.readResponse(IMAPProtocol.java:261)
        at com.sun.mail.iap.Protocol.<init>(Protocol.java:114)
        at com.sun.mail.imap.protocol.IMAPProtocol.<init>(IMAPProtocol.java:104)
        at com.sun.mail.imap.IMAPStore.protocolConnect(IMAPStore.java:538)
        - locked <0x00002aab0db6b1c8> (a com.sun.mail.imap.IMAPSSLStore)
        at javax.mail.Service.connect(Service.java:288)
        - locked <0x00002aab0db6b1c8> (a com.sun.mail.imap.IMAPSSLStore)
        at javax.mail.Service.connect(Service.java:169)
        at com.pws.imagebot.ImageAttachmentExtractor.retrieveMessage(ImageAttachmentExtractor.java:169)
        at com.pws.scheduling.EmailImageExtractorJob.executeInternal(EmailImageExtractorJob.java:146)
        at org.springframework.scheduling.quartz.QuartzJobBean.execute(QuartzJobBean.java:86)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:203)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:520)

===========================================================================
To unsubscribe, send email to listserv@... and include in the body
of the message "signoff JAVAMAIL-INTEREST".  For general help, send email to
listserv@... and include in the body of the message "help".

[Bill Shannon]

What does netstat on the client machine say?

Have you tried turning on protocol tracing in JavaMail or using
tcpdump to see what's happening when it fails?

It looks like a bug in the OS or the JDK where the code isn't recognizing
that the connection is really closed.

As a workaround you could try creating your own watchdog thread that
kills the main thread if it's not making progress.


Foo Bar wrote:

> Hi. I have a piece of code that runs in a Tomcat server and polls a
> remote IMAP server over SSL about once every 15th seconds. The job is
> scheduled using Quartz, and I have configured Quartz to not start a
> new job until the previous one has finished. I.e., it's not a
> multi-threaded environment. For the most part, this works very nicely,
> but about once every 8-12 hours, it hangs trying to connect to the
> IMAP server (my conclusion from looking at the JVM stacktrace). When
> this happens, there's NO evidence whatsoever of a TCP connection
> between the client and the server judging from running netstat on the
> machine where the IMAP server runs! Both the client (JavaMail in
> Tomcat) and the IMAP server (Cyrus 2.2.13-24.2) are running on pretty
> snappy OpenSUSE Linux AMD machines (2 dual cores) with lots of RAM
> and disk. Please note that the very same IMAP server handles all the
> mailboxes for the company (all via SSL), and we've had no problems
> with it. Also note that the timeout that is set to 180000 milliseconds
> doesn't seem to help here. When the problem occurs, this will block
> forever.
>
> Here's the code snippet:
>
>       // This line was added after googling for JavaMail and SSL
>       Security.addProvider(new com.sun.net.ssl.internal.ssl.Provider());
>       Properties props = System.getProperties();
>       props.setProperty("mail.imap.socketFactory.class",
>                         "javax.net.ssl.SSLSocketFactory");
>       props.setProperty("mail.imap.socketFactory.fallback", "false");
>       props.setProperty("mail.imap.starttls.enable", "true");
>       props.setProperty("mail.imap.port", IMAPS_PORT);
>       props.setProperty("mail.imap.socketFactory.port", IMAPS_PORT);
>       props.setProperty("mail.imap.sasl.enable", "true");
>       props.setProperty("mail.imap.timeout", "180000");
>       props.setProperty("mail.imap.connectiontimeout", "180000");
>       Session session = Session.getInstance(props);
>       // session.setDebug(debug);
>       store = session.getStore("imaps");
>       store.connect(mailServer, mailUser, password);
>
> The code blocks in the call to store.connect(). A JVM stack trace
> follows below. Any help to fix or circumvent this problem is highly
> appreciated. Thanks,
>
> Henrik
>
> "scheduler_Worker-3" prio=10 tid=0x00002aabf0101000 nid=0x772e runnable [0x000000004163d000..0x000000004163ec80]
>    java.lang.Thread.State: RUNNABLE
>         at java.net.SocketInputStream.socketRead0(Native Method)
>         at java.net.SocketInputStream.read(SocketInputStream.java:129)
>         at com.sun.net.ssl.internal.ssl.InputRecord.readFully(InputRecord.java:293)
>         at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:331)
>         at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:789)
>         - locked <0x00002aab0db69840> (a java.lang.Object)
>         at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1096)
>         - locked <0x00002aab0db697e8> (a java.lang.Object)
>         at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:744)
>         at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75)
>         - locked <0x00002aab0db6a630> (a com.sun.net.ssl.internal.ssl.AppInputStream)
>         at com.sun.mail.util.TraceInputStream.read(TraceInputStream.java:110)
>         at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
>         at java.io.BufferedInputStream.read(BufferedInputStream.java:237)
>         - locked <0x00002aab0db6a8e0> (a java.io.BufferedInputStream)
>         at com.sun.mail.iap.ResponseInputStream.readResponse(ResponseInputStream.java:97)
>         at com.sun.mail.iap.Response.<init>(Response.java:96)
>         at com.sun.mail.imap.protocol.IMAPResponse.<init>(IMAPResponse.java:61)
>         at com.sun.mail.imap.protocol.IMAPResponse.readResponse(IMAPResponse.java:135)
>         at com.sun.mail.imap.protocol.IMAPProtocol.readResponse(IMAPProtocol.java:261)
>         at com.sun.mail.iap.Protocol.<init>(Protocol.java:114)
>         at com.sun.mail.imap.protocol.IMAPProtocol.<init>(IMAPProtocol.java:104)
>         at com.sun.mail.imap.IMAPStore.protocolConnect(IMAPStore.java:538)
>         - locked <0x00002aab0db6b1c8> (a com.sun.mail.imap.IMAPSSLStore)
>         at javax.mail.Service.connect(Service.java:288)
>         - locked <0x00002aab0db6b1c8> (a com.sun.mail.imap.IMAPSSLStore)
>         at javax.mail.Service.connect(Service.java:169)
>         at com.pws.imagebot.ImageAttachmentExtractor.retrieveMessage(ImageAttachmentExtractor.java:169)
>         at com.pws.scheduling.EmailImageExtractorJob.executeInternal(EmailImageExtractorJob.java:146)
>         at org.springframework.scheduling.quartz.QuartzJobBean.execute(QuartzJobBean.java:86)
>         at org.quartz.core.JobRunShell.run(JobRunShell.java:203)
>         at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:520)
>
> ===========================================================================
> To unsubscribe, send email to listserv@... and include in the body
> of the message "signoff JAVAMAIL-INTEREST".  For general help, send email to
> listserv@... and include in the body of the message "help".

===========================================================================
To unsubscribe, send email to listserv@... and include in the body
of the message "signoff JAVAMAIL-INTEREST".  For general help, send email to
listserv@... and include in the body of the message "help".

[Henrik Martin]

Thanks. I just had a chance to study this closer while it
happened. When the problem first occurs, netstat shows that the
connection is ESTABLISHED on both ends.  After a while, it seems like
the IMAP server times out (seems to take about 10 minutes). Now when I
run netstat, it shows absolutely nothing on the mail server side (not
even a lingering TIME_WAIT), but the client side shows that the
connections is ESTABLISHED. This seems to confirm your suspicions
about an OS/JVM bug.

How do I turn on protocol tracing only? For a while I used the
setDebug() method in the Session object, but since the emails that I'm
downloading from the IMAP server are big with image attachments, it
filled my tomcat log files with so much data that it became
unbearable. If there's a way of turning on protocol debugging only
that would be great.

What's the best way to go about writing a watchdog? Is there a
listener method that I can use that will be called at the beginning of
the connection to kick off the watchdog thread? Assuming I detect that
the connection is blocked, is it safe to just kill the client thread,
or do I risk leaving the IMAP server in some weird state?

I forgot to mention that I'm using JDK 1.6.0_03-b05 (64 bit version)
and the JavaMail version is 1.4.1. Thanks,

/Henrik

On Friday 02 May 2008 01:48, Bill Shannon wrote:

> What does netstat on the client machine say?
>
> Have you tried turning on protocol tracing in JavaMail or using
> tcpdump to see what's happening when it fails?
>
> It looks like a bug in the OS or the JDK where the code isn't recognizing
> that the connection is really closed.
>
> As a workaround you could try creating your own watchdog thread that
> kills the main thread if it's not making progress.
>
>
> Foo Bar wrote:
> > Hi. I have a piece of code that runs in a Tomcat server and polls a
> > remote IMAP server over SSL about once every 15th seconds. The job is
> > scheduled using Quartz, and I have configured Quartz to not start a
> > new job until the previous one has finished. I.e., it's not a
> > multi-threaded environment. For the most part, this works very nicely,
> > but about once every 8-12 hours, it hangs trying to connect to the
> > IMAP server (my conclusion from looking at the JVM stacktrace). When
> > this happens, there's NO evidence whatsoever of a TCP connection
> > between the client and the server judging from running netstat on the
> > machine where the IMAP server runs! Both the client (JavaMail in
> > Tomcat) and the IMAP server (Cyrus 2.2.13-24.2) are running on pretty
> > snappy OpenSUSE Linux AMD machines (2 dual cores) with lots of RAM
> > and disk. Please note that the very same IMAP server handles all the
> > mailboxes for the company (all via SSL), and we've had no problems
> > with it. Also note that the timeout that is set to 180000 milliseconds
> > doesn't seem to help here. When the problem occurs, this will block
> > forever.
> >
> > Here's the code snippet:
> >
> >       // This line was added after googling for JavaMail and SSL
> >       Security.addProvider(new com.sun.net.ssl.internal.ssl.Provider());
> >       Properties props = System.getProperties();
> >       props.setProperty("mail.imap.socketFactory.class",
> >                         "javax.net.ssl.SSLSocketFactory");
> >       props.setProperty("mail.imap.socketFactory.fallback", "false");
> >       props.setProperty("mail.imap.starttls.enable", "true");
> >       props.setProperty("mail.imap.port", IMAPS_PORT);
> >       props.setProperty("mail.imap.socketFactory.port", IMAPS_PORT);
> >       props.setProperty("mail.imap.sasl.enable", "true");
> >       props.setProperty("mail.imap.timeout", "180000");
> >       props.setProperty("mail.imap.connectiontimeout", "180000");
> >       Session session = Session.getInstance(props);
> >       // session.setDebug(debug);
> >       store = session.getStore("imaps");
> >       store.connect(mailServer, mailUser, password);
> >
> > The code blocks in the call to store.connect(). A JVM stack trace
> > follows below. Any help to fix or circumvent this problem is highly
> > appreciated. Thanks,
> >
> > Henrik
> >
> > "scheduler_Worker-3" prio=10 tid=0x00002aabf0101000 nid=0x772e runnable [0x000000004163d000..0x000000004163ec80]
> >    java.lang.Thread.State: RUNNABLE
> >         at java.net.SocketInputStream.socketRead0(Native Method)
> >         at java.net.SocketInputStream.read(SocketInputStream.java:129)
> >         at com.sun.net.ssl.internal.ssl.InputRecord.readFully(InputRecord.java:293)
> >         at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:331)
> >         at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:789)
> >         - locked <0x00002aab0db69840> (a java.lang.Object)
> >         at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1096)
> >         - locked <0x00002aab0db697e8> (a java.lang.Object)
> >         at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:744)
> >         at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75)
> >         - locked <0x00002aab0db6a630> (a com.sun.net.ssl.internal.ssl.AppInputStream)
> >         at com.sun.mail.util.TraceInputStream.read(TraceInputStream.java:110)
> >         at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
> >         at java.io.BufferedInputStream.read(BufferedInputStream.java:237)
> >         - locked <0x00002aab0db6a8e0> (a java.io.BufferedInputStream)
> >         at com.sun.mail.iap.ResponseInputStream.readResponse(ResponseInputStream.java:97)
> >         at com.sun.mail.iap.Response.<init>(Response.java:96)
> >         at com.sun.mail.imap.protocol.IMAPResponse.<init>(IMAPResponse.java:61)
> >         at com.sun.mail.imap.protocol.IMAPResponse.readResponse(IMAPResponse.java:135)
> >         at com.sun.mail.imap.protocol.IMAPProtocol.readResponse(IMAPProtocol.java:261)
> >         at com.sun.mail.iap.Protocol.<init>(Protocol.java:114)
> >         at com.sun.mail.imap.protocol.IMAPProtocol.<init>(IMAPProtocol.java:104)
> >         at com.sun.mail.imap.IMAPStore.protocolConnect(IMAPStore.java:538)
> >         - locked <0x00002aab0db6b1c8> (a com.sun.mail.imap.IMAPSSLStore)
> >         at javax.mail.Service.connect(Service.java:288)
> >         - locked <0x00002aab0db6b1c8> (a com.sun.mail.imap.IMAPSSLStore)
> >         at javax.mail.Service.connect(Service.java:169)
> >         at com.pws.imagebot.ImageAttachmentExtractor.retrieveMessage(ImageAttachmentExtractor.java:169)
> >         at com.pws.scheduling.EmailImageExtractorJob.executeInternal(EmailImageExtractorJob.java:146)
> >         at org.springframework.scheduling.quartz.QuartzJobBean.execute(QuartzJobBean.java:86)
> >         at org.quartz.core.JobRunShell.run(JobRunShell.java:203)
> >         at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:520)
> >
> > ===========================================================================
> > To unsubscribe, send email to listserv@... and include in the body
> > of the message "signoff JAVAMAIL-INTEREST".  For general help, send email to
> > listserv@... and include in the body of the message "help".
>
>
>

===========================================================================
To unsubscribe, send email to listserv@... and include in the body
of the message "signoff JAVAMAIL-INTEREST".  For general help, send email to
listserv@... and include in the body of the message "help".