Transactional POP3 Mailbox access with Spring Integration

[al94781]

We want to use Spring Integration 2.1.1 to read mail off a POP3 mailbox transactionally. This transactionality is so that we can read an email message and persist it to Oracle and remove from the mailbox. In the event of a transaction rollback we want the email to remain in the mailbox (i.e. not be deleted).

Our problem is that, despite being in a transaction (more detail on that in a second) the mailbox is opened, the mail is retrieved, marked for deletion and the connection closed irrespective of the rest of the transaction. This means it is too late to not delete the mail if something fails later on (as the connection is closed and the mailbox gone into UPDATE state which permanently removes the email).

Looking at all of the logs when set at debug, we can see our problem in context (note how POP3 "sayonara's" before the rest of our work in the endpoint begins, and most importantly, before the surrounding transaction commits / rolls back):

 15:32:25.256 INFO  [main][org.springframework.transaction.jta.JtaTransactionManager]     Using JTA UserTransaction: com.atomikos.icatch.jta.UserTransactionImp@3228a1
    15:32:25.256 INFO  [main][org.springframework.transaction.jta.JtaTransactionManager] Using JTA TransactionManager: com.atomikos.icatch.jta.UserTransactionManager@10980e7
 ...
    15:32:25.423 WARN  [task-scheduler-1][com.atomikos.icatch.imp.TransactionServiceImp] Attempt to create a 
...
    15:32:25.429 DEBUG [task-scheduler-1][com.atomikos.icatch.imp.TransactionServiceImp] Creating composite transaction: 10.9.21.7.tm0000100022
    15:32:25.433 INFO  [task-scheduler-1][com.atomikos.icatch.imp.BaseTransactionManager] createCompositeTransaction ( 100000000 ): created new ROOT transaction with id 10.9.21.7.tm0000100022
    DEBUG: JavaMail version 1.4.4
    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,Sun Microsystems, Inc], com.sun.mail.smtp.SMTPTransport=javax.mail.Provider[TRANSPORT,smtp,com.sun.mail.smtp.SMTPTransport,Sun Microsystems, Inc], com.sun.mail.imap.IMAPSSLStore=javax.mail.Provider[STORE,imaps,com.sun.mail.imap.IMAPSSLStore,Sun Microsystems, Inc], com.sun.mail.pop3.POP3SSLStore=javax.mail.Provider[STORE,pop3s,com.sun.mail.pop3.POP3SSLStore,Sun Microsystems, Inc], com.sun.mail.imap.IMAPStore=javax.mail.Provider[STORE,imap,com.sun.mail.imap.IMAPStore,Sun Microsystems, Inc], com.sun.mail.pop3.POP3Store=javax.mail.Provider[STORE,pop3,com.sun.mail.pop3.POP3Store,Sun Microsystems, Inc]}
    DEBUG: Providers Listed By Protocol: {imaps=javax.mail.Provider[STORE,imaps,com.sun.mail.imap.IMAPSSLStore,Sun Microsystems, Inc], imap=javax.mail.Provider[STORE,imap,com.sun.mail.imap.IMAPStore,Sun Microsystems, Inc], smtps=javax.mail.Provider[TRANSPORT,smtps,com.sun.mail.smtp.SMTPSSLTransport,Sun Microsystems, Inc], pop3=javax.mail.Provider[STORE,pop3,com.sun.mail.pop3.POP3Store,Sun Microsystems, Inc], pop3s=javax.mail.Provider[STORE,pop3s,com.sun.mail.pop3.POP3SSLStore,Sun Microsystems, Inc], smtp=javax.mail.Provider[TRANSPORT,smtp,com.sun.mail.smtp.SMTPTransport,Sun Microsystems, Inc]}
    DEBUG: successfully loaded resource: /META-INF/javamail.default.address.map
    DEBUG: getProvider() returning javax.mail.Provider[STORE,pop3,com.sun.mail.pop3.POP3Store,Sun Microsystems, Inc]
    DEBUG POP3: mail.pop3.rsetbeforequit: false
    DEBUG POP3: mail.pop3.disabletop: false
    DEBUG POP3: mail.pop3.forgettopheaders: false
    DEBUG POP3: mail.pop3.cachewriteto: false
    DEBUG POP3: mail.pop3.filecache.enable: false
    DEBUG POP3: mail.pop3.keepmessagecontent: false
    DEBUG POP3: mail.pop3.starttls.enable: false
    DEBUG POP3: mail.pop3.starttls.required: false
    15:32:25.446 DEBUG [task-scheduler-1][org.springframework.integration.mail.Pop3MailReceiver] connecting to store [pop3://devmail9:*****@100.100.100.100/inbox]
    DEBUG POP3: mail.pop3.apop.enable: false
    DEBUG POP3: mail.pop3.disablecapa: false
    DEBUG POP3: connecting to host "100.100.100.100", port 110, isSSL false
    S: +OK POP3 xxxxx.xxxx.xxxx.xxx.xxx.uk v4.39 server ready
    C: CAPA
    S: -ERR Unknown command in AUTHORIZATION state
    C: USER myuser
    S: +OK User name accepted, password please
    C: PASS myuser
    S: +OK Mailbox open, 3 messages
    15:32:25.564 DEBUG [task-scheduler-1][org.springframework.integration.mail.Pop3MailReceiver] opening folder [pop3://myuser:*****@100.100.100.100/inbox]
    C: STAT
    S: +OK 3 5956
    15:32:25.569 INFO  [task-scheduler-1][org.springframework.integration.mail.Pop3MailReceiver] attempting to receive mail from folder [inbox]
    C: NOOP
    S: +OK No-op to you too!
    15:32:25.591 DEBUG [task-scheduler-1][org.springframework.integration.mail.Pop3MailReceiver] found 1 new messages
    C: TOP 1 0
    S: +OK Top of message follows
    Received: from xxxxx.xxxx.xxxx.xxx.xxx.uk ([100.100.100.100]) by     xxxxx.xxxx.xxxx.xxx.xxx.uk (AIX5.2/8.11.6p2/8.11.0) with ESMTP id q57EUrG1544330 for C:    LIST 1

    ....

    S: +OK 1 1996
    15:32:25.604 DEBUG [task-scheduler-1][org.springframework.integration.mail.Pop3MailReceiver] Recieved 1 messages
    15:32:26.097 DEBUG [task-scheduler-1][org.springframework.integration.mail.Pop3MailReceiver] USER flags are not supported by this mail server. Flagging message with system flag
    DEBUG POP3: streaming msg 1
    C: RETR 1
    S: +OK 1996 octets
    Received: from xxxxx.xxxx.xxxx.xxx.xxx.uk ([100.100.100.100]) by GLA610.crown.copfs.gsi.gov.uk (AIX5.2/8.11.6p2/8.11.0) with ESMTP id q57EUrG1544330 for <myuser@xxxxx.xxxx.xxxx.xxx.xxx.uk>; Thu, 7 Jun 2012 15:30:53 +0100

    ....

    DEBUG POP3: streaming msg 1
    C: RETR 1
    S: +OK 1996 octets
    Received: from xxxxx.xxxx.xxxx.xxx.xxx.uk ([100.100.100.100]) by xxxxx.xxxx.xxxx.xxx.xxx.uk (AIX5.2/8.11.6p2/8.11.0) with ESMTP id q57EUrG1544330 for <myuser@xxxxx.xxxx.xxxx.xxx.xxx.uk>; Thu, 7 Jun 2012 15:30:53 +0100
    
    ....
    
    .
    C: NOOP
    S: +OK No-op to you too!
    C: DELE 1
    S: +OK Message deleted
    C: QUIT
    S: +OK Sayonara
    15:32:26.672 DEBUG [task-scheduler-1][org.springframework.integration.mail.MailReceivingMessageSource] received mail message [javax.mail.internet.MimeMessage@ef4504]
    15:32:26.696 DEBUG [task-scheduler-1][com.atomikos.icatch.imp.BaseTransactionManager] getCompositeTransaction()  returning instance with id 10.9.21.7.tm0000100022
    15:32:26.697 DEBUG [task-scheduler-1][com.atomikos.icatch.imp.BaseTransactionManager] getCompositeTransaction()  returning instance with id 10.9.21.7.tm0000100022
    15:32:26.697 DEBUG [task-scheduler-1][org.springframework.transaction.jta.JtaTransactionManager] Participating in existing transaction
    15:32:26.716 INFO  [task-scheduler-1][xx.xxx.xxx.xxx.channel.email.InboundEmailMessageEndpoint] In InboundEmailMessageEndpoint.  processing MailMessage (Subject): 7777777777777777777
    15:32:26.735 DEBUG [task-scheduler-1][com.atomikos.icatch.imp.BaseTransactionManager] getCompositeTransaction()  returning instance with id 10.9.21.7.tm0000100022
    15:32:26.735 DEBUG [task-scheduler-1][com.atomikos.icatch.imp.BaseTransactionManager] getCompositeTransaction()  returning instance with id 10.9.21.7.tm0000100022
    15:32:26.735 DEBUG [task-scheduler-1][org.springframework.transaction.jta.JtaTransactionManager] Initiating transaction commit
    15:32:26.735 DEBUG [task-scheduler-1][com.atomikos.icatch.imp.BaseTransactionManager] getCompositeTransaction()  returning instance with id 10.9.21.7.tm0000100022
    15:32:26.735 DEBUG [task-scheduler-1][com.atomikos.icatch.imp.BaseTransactionManager] getCompositeTransaction()  returning instance with id 10.9.21.7.tm0000100022
    15:32:26.735 DEBUG [task-scheduler-1][com.atomikos.icatch.imp.BaseTransactionManager] getCompositeTransaction()  returning instance with id 10.9.21.7.tm0000100022
    15:32:26.735 DEBUG [task-scheduler-1][com.atomikos.icatch.imp.BaseTransactionManager] getCompositeTransaction()  returning instance with id 10.9.21.7.tm0000100022
    15:32:26.736 INFO  [task-scheduler-1][com.atomikos.icatch.imp.CompositeTransactionImp] commit() done (by application) of transaction 10.9.21.7.tm0000100022
    15:32:26.736 DEBUG [task-scheduler-1][com.atomikos.icatch.imp.CoordinatorImp] Coordinator 10.9.21.7.tm0000100022 entering state: COMMITTING
    15:32:26.740 DEBUG [task-scheduler-1][com.atomikos.icatch.imp.CoordinatorImp] Coordinator 10.9.21.7.tm0000100022 entering state: TERMINATED
    15:32:26.741 DEBUG [task-scheduler-1][com.atomikos.icatch.imp.CoordinatorImp] Coordinator 10.9.21.7.tm0000100022 : stopping timer...
    15:32:26.741 DEBUG [task-scheduler-1][com.atomikos.icatch.imp.CoordinatorImp] Coordinator 10.9.21.7.tm0000100022 : disposing statehandler TERMINATED...
    15:32:26.741 DEBUG [task-scheduler-1][com.atomikos.icatch.imp.CoordinatorImp] Coordinator 10.9.21.7.tm0000100022 : disposed.

Thanks in advance for your help.

[oleg.zhurakousky]

You are correct. Once the Message leaves the adapter its been marked as read by the email server especially with POP3 which is very limited. What adds to the prob;em is that Mail is not a transactional system and does not expose a transaction manager like JMS for example where a simple exception would force a rollback.
I would suggest to raise a JIRA feature request and we'll see what we can do https://jira.springsource.org/browse/INT

[al94781]

Hi Oleg,

Thanks VERY much for the swift response. We were coming to the same conclusion ourselves. We'll log the feature request. Do you think the turnaround on this might be quick?

In the meantime, we caon work on things ourselves. Could you give us some pointers on how to create our own transactional inbound-channel-adapter for this which keeps the pop3 session open until a commit / rollback is sent?

Kind regards,

Andrew

You are correct. Once the Message leaves the adapter its been marked as read by the email server especially with POP3 which is very limited. What adds to the prob;em is that Mail is not a transactional system and does not expose a transaction manager like JMS for example where a simple exception would force a rollback.
I would suggest to raise a JIRA feature request and we'll see what we can do https://jira.springsource.org/browse/INT

[oleg.zhurakousky]

I say rais a JIRA and we'll prioritize it so the turnaround should be pretty quick. Can't give you any dates since not sure yet how we are going to approach it (hence no pointers), but I am sure we'll come up with something.

[al94781]

Cheers Oleg,

I've logged this at https://jira.springsource.org/browse/INT-2606

Let me know if I need to provide more information. we'll also continue to work on this too and will contribute back if we come up with anything worthy of sharing...

Cheers, Andrew

I say rais a JIRA and we'll prioritize it so the turnaround should be pretty quick. Can't give you any dates since not sure yet how we are going to approach it (hence no pointers), but I am sure we'll come up with something.

[al94781]

Hi Oleg,

We've finally managed to get round to trying this out. From reading your committed code it seems that all we need to get this going is to update our Spring Integration version. Are we right in thinking that the rest should "just work" without any more changes?

We'd also like to turn on trace logging too to see that this "commits" the delete to the mailbox at the right time in the case of a successful TX and also a rollback. I had a quick try at this but failed to get the trace statements in the code to write for me. We're using SL4J on top of Log4J and enabling trace level logging a follows:

<logger name="org.springframework.integration">
<level value="trace" />
</logger>

This produces no trace logging at all from the classes in this package. I hope you can help.

TIA

Cheers, Andrew

Cheers Oleg,

I've logged this at https://jira.springsource.org/browse/INT-2606

Let me know if I need to provide more information. we'll also continue to work on this too and will contribute back if we come up with anything worthy of sharing...

Cheers, Andrew