Javamail event listener not getting any events

Question

I coded an IMAP handler and an event listener as I understood it should be done, but I don't see any events firing, despite filling up the inbox with new emails. What could be my problem?

I set up the store to idle until someone closes the mailbox:

public void run() {
    boolean logged = false;
    synchronized (emailListener) {
        while (!isCancelled) {
            try {
                if (isListening) {
                    throw new EtlSystemException(
                            null,
                            "Disallowed attempt to "
                                + "start email listener - listening status already set",
                            null, null);
                } else {
                    isListening = true;
                }
                if (imapProperties == null) {
                    imapProperties = new Properties();
                    imapProperties.put("mail.debug", "true");
                }
                Session session =
                        javax.mail.Session.getInstance(imapProperties);
                session.setDebug(true);
                store = (IMAPStore) session.getStore(imapProtocol);
                store.connect(imapHost, imapUser, imapPassword);
                inbox = (IMAPFolder) store.getFolder("INBOX");
                if (inbox == null) {
                    throw new NonEtlSystemException(null, "No inbox in "
                        + this.imapUser,
                            null, null);
                }
                inbox.open(Folder.READ_WRITE);
                inbox.addMessageCountListener(emailListener);
                // While the listener is registered, we loop over idle().
                // Only stop if the inbox is closed, or thread interrupted
                while (inbox.isOpen()) {
                    log.debug("store idling...");
                    inbox.idle();
                }
                // if any system errors occur processing the emails, stop
                // the thread
                if (!emailListener.getStatusOK()) {
                    break;
                }
            } catch (MessagingException e) {
                lastThrowable = e;
            } catch (Throwable throwable) {
                lastThrowable = throwable;
                break;
            } finally {
                close();
                if (lastThrowable != null) {
                    if (!logged) {
                        EtlAlert alert = new EtlAlert(lastThrowable);
                        log.error(alert.getSysLogText(),
                                alert.getThrowable());
                        auditLogService.addEvent(alert.getEcnCode(),
                                alert.getEcnName(),
                                new Date(),
                                alert.getUserGpn(),
                                alert.getUserName(),
                                alert.getEventType(),
                                alert.getAuditLogText());
                        logged = true;
                    }
                    if (lastThrowable instanceof MessagingException) {
                        try {
                            log.info("Waiting for IMAP server recovery ... "
                                + "checks every " + WAIT_AT_IMAP_ERROR
                                + "ms ");
                            Thread.sleep(WAIT_AT_IMAP_ERROR);
                        } catch (InterruptedException e1) {
                        }
                    }
                }
            }
        }
    }
    log.debug("thread dying now");
}

and this is how I'm testing it:

@Test
public void testImapHandler() {
    try {
        // launch ImapHandler
        ImapHandler imapHandler =
                new ImapHandler(new EmailListener());
        imapHandler.setConfig(host, protocol, imapUser, imapPass);
        // now the listener starts listening in a separate thread
        Thread test = new Thread(imapHandler, "ImapHandler");
        test.start();
        // send a test email to inbox
        int startCount = imapHandler.getProcessedMessageCount();
        sendTestEmail();
        // wait for a bit
        Thread.sleep(60000);
        // stop it
        log.debug("stopping listener on thread [" + test.getName() + "]");
        test.interrupt();
        imapHandler.closeAndTerminate(); // this forces it out of idling
        test.join();
        // test listener count to see if it raised an email event
        int finalCount = imapHandler.getProcessedMessageCount();
        assertNotSame("start with " + startCount + ", ended with "
            + finalCount, startCount, finalCount);
    } catch (final InterruptedException e) {
    }
}

The imapHandler.closeAndTerminate() method closes the inbox and store, which forces store.idle() to stop blocking. The IMAPHandler class is used as a singleton and the store and inbox are kept as memvars, just for this purpose.

This is the debug log from the IMAP session:

DEBUG: JavaMail version 1.5.0-b01
DEBUG: successfully loaded resource: /META-INF/javamail.default.providers
DEBUG: Tables of loaded providers
DEBUG: Providers Listed By Class Name: {com.sun.mail.smtp.SMTPSSLTransport=javax.mail.Provider[TRANSPORT,smtps,com.sun.mail.smtp.SMTPSSLTransport,Oracle], com.sun.mail.smtp.SMTPTransport=javax.mail.Provider[TRANSPORT,smtp,com.sun.mail.smtp.SMTPTransport,Oracle], com.sun.mail.imap.IMAPSSLStore=javax.mail.Provider[STORE,imaps,com.sun.mail.imap.IMAPSSLStore,Oracle], com.sun.mail.pop3.POP3SSLStore=javax.mail.Provider[STORE,pop3s,com.sun.mail.pop3.POP3SSLStore,Oracle], com.sun.mail.imap.IMAPStore=javax.mail.Provider[STORE,imap,com.sun.mail.imap.IMAPStore,Oracle], com.sun.mail.pop3.POP3Store=javax.mail.Provider[STORE,pop3,com.sun.mail.pop3.POP3Store,Oracle]}
DEBUG: Providers Listed By Protocol: {imaps=javax.mail.Provider[STORE,imaps,com.sun.mail.imap.IMAPSSLStore,Oracle], imap=javax.mail.Provider[STORE,imap,com.sun.mail.imap.IMAPStore,Oracle], smtps=javax.mail.Provider[TRANSPORT,smtps,com.sun.mail.smtp.SMTPSSLTransport,Oracle], pop3=javax.mail.Provider[STORE,pop3,com.sun.mail.pop3.POP3Store,Oracle], pop3s=javax.mail.Provider[STORE,pop3s,com.sun.mail.pop3.POP3SSLStore,Oracle], smtp=javax.mail.Provider[TRANSPORT,smtp,com.sun.mail.smtp.SMTPTransport,Oracle]}
DEBUG: successfully loaded resource: /META-INF/javamail.default.address.map
DEBUG: setDebug: JavaMail version 1.5.0-b01
DEBUG: getProvider() returning javax.mail.Provider[STORE,imaps,com.sun.mail.imap.IMAPSSLStore,Oracle]
DEBUG IMAPS: mail.imap.fetchsize: 16384
DEBUG IMAPS: mail.imap.ignorebodystructuresize: false
DEBUG IMAPS: mail.imap.statuscachetimeout: 1000
DEBUG IMAPS: mail.imap.appendbuffersize: -1
DEBUG IMAPS: mail.imap.minidletime: 10
DEBUG IMAPS: disable AUTH=PLAIN
DEBUG IMAPS: disable AUTH=NTLM
DEBUG IMAPS: trying to connect to host "webmail", port 993, isSSL true
* OK The Microsoft Exchange IMAP4 service is ready.
A0 CAPABILITY
* CAPABILITY IMAP4 IMAP4rev1 AUTH=NTLM AUTH=GSSAPI AUTH=PLAIN UIDPLUS CHILDREN IDLE NAMESPACE LITERAL+
A0 OK CAPABILITY completed.
DEBUG IMAPS: AUTH: NTLM
DEBUG IMAPS: AUTH: GSSAPI
DEBUG IMAPS: AUTH: PLAIN
DEBUG IMAPS: protocolConnect login, host=webmail, user=826, password=<non-null>
DEBUG IMAPS: LOGIN command trace suppressed
DEBUG IMAPS: LOGIN command result: A1 OK LOGIN completed.
A2 CAPABILITY
* CAPABILITY IMAP4 IMAP4rev1 AUTH=NTLM AUTH=GSSAPI AUTH=PLAIN UIDPLUS CHILDREN IDLE NAMESPACE LITERAL+
A2 OK CAPABILITY completed.
DEBUG IMAPS: AUTH: NTLM
DEBUG IMAPS: AUTH: GSSAPI
DEBUG IMAPS: AUTH: PLAIN
DEBUG IMAPS: connection available -- size: 1
A3 SELECT INBOX
* 42 EXISTS
* 2 RECENT
* FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)
* OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)] Permanent flags
* OK [UNSEEN 3] Is the first unseen message
* OK [UIDVALIDITY 71441] UIDVALIDITY value
* OK [UIDNEXT 46] The next unique identifier value
A3 OK [READ-WRITE] SELECT completed.
17:54:34.132 [ImapHandler] DEBUG (ImapHandler.java:205) runListener() - store idling...
A4 IDLE
+ IDLE accepted, awaiting DONE command.
* 35 FETCH (FLAGS (\Seen))
17:55:33.320 [main] DEBUG (ImapTest.java:96) testImapHandler() - stopping listener on thread [ImapHandler]
DONE
A4 OK IDLE completed.
DEBUG IMAPS: IMAPProtocol noop
A5 NOOP
A5 OK NOOP completed.
A6 CLOSE
A6 OK CLOSE completed.
DEBUG IMAPS: added an Authenticated connection -- size: 1
DEBUG IMAPS: IMAPProtocol noop
A7 NOOP
A7 OK NOOP completed.
A8 LOGOUT
* BYE Microsoft Exchange Server 2010 IMAP4 server signing off.
A8 OK LOGOUT completed.
DEBUG IMAPS: IMAPStore connection dead
DEBUG IMAPS: IMAPStore cleanup, force false
DEBUG IMAPS: IMAPStore cleanup done
17:55:33.342 [ImapHandler] DEBUG (ImapHandler.java:188) run() - thread dying now

You can see from the log4j log statements in between the IMAP logging that the Store.idle() command was running for a full minute, during which time the test email was sent by the test thread.

Any other relevant info I can think of:

• Exchange 2010

• Tomcat 7

• Javamail 1.5.0-b01

• jdk 1.7.0-55

Answer 1

Well, first of all, that's a very old version of JavaMail. You should upgrade to the current version, just in case it has something to do with your problem.

Also, by including "store.isConnected()" in your while loop, you're forcing JavaMail to create another connection to your server. That's probably not something you need.

What produces the "stopping listener" message? Is that coming from the listener itself? Something is aborting the IDLE command and closing the Folder and Store, but it's not clear from your code what's causing that.

Is this a standalone Java program? Or is it running in an application server?