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

[Gary Russell]

As long as your poller is transactional - I just re-tested with the sample app and it worked fine...

08:15:07.805 DEBUG [task-scheduler-3][org.springframework.integration.mail.MailReceivingMessageSource] received mail message [javax.mail.internet.MimeMessage@5edf2d38]
08:15:07.817 DEBUG [task-scheduler-3][org.springframework.integration.endpoint.SourcePollingChannelAdapter] Poll resulted in Message: [Payload=javax.mail.internet.MimeMessage@5edf2d38][Headers={timestamp=1342527307816, id=daa5d27a-f7f1-4a7b-b071-fa5e7cc11450}]
08:15:07.817 DEBUG [task-scheduler-3][org.springframework.integration.channel.DirectChannel] preSend on channel 'recieveChannel', message: [Payload=javax.mail.internet.MimeMessage@5edf2d38][Headers={timestamp=1342527307816, id=daa5d27a-f7f1-4a7b-b071-fa5e7cc11450}]
08:15:07.817 INFO  [task-scheduler-3][org.springframework.integration.samples.mail.imapidle.GmailInboundPop3AdapterTestApp] Message: [Payload=javax.mail.internet.MimeMessage@5edf2d38][Headers={timestamp=1342527307816, id=daa5d27a-f7f1-4a7b-b071-fa5e7cc11450}]
08:15:07.817 DEBUG [task-scheduler-3][org.springframework.integration.channel.DirectChannel] postSend (sent=true) on channel 'recieveChannel', message: [Payload=javax.mail.internet.MimeMessage@5edf2d38][Headers={timestamp=1342527307816, id=daa5d27a-f7f1-4a7b-b071-fa5e7cc11450}]

08:15:07.818 TRACE [task-scheduler-3][org.springframework.transaction.interceptor.TransactionInterceptor] Completing transaction for [org.springframework.integration.endpoint.AbstractPollingEndpoint$1.call]
08:15:07.818 TRACE [task-scheduler-3][org.springframework.jdbc.datasource.DataSourceTransactionManager] Triggering beforeCommit synchronization
08:15:07.818 TRACE [task-scheduler-3][org.springframework.jdbc.datasource.DataSourceTransactionManager] Triggering beforeCompletion synchronization
08:15:07.818 TRACE [task-scheduler-3][org.springframework.transaction.support.TransactionSynchronizationManager] Removed value [org.springframework.integration.mail.MailReceiver$MailReceiverContext@7e717d91] for key [org.springframework.integration.mail.MailReceivingMessageSource@34fe315d] from thread [task-scheduler-3]
08:15:07.818 DEBUG [task-scheduler-3][org.springframework.jdbc.datasource.DataSourceTransactionManager] Initiating transaction commit
08:15:07.818 DEBUG [task-scheduler-3][org.springframework.jdbc.datasource.DataSourceTransactionManager] Committing JDBC transaction on Connection [conn3: url=jdbc:h2:mem:dataSource user=SA]
08:15:07.818 TRACE [task-scheduler-3][org.springframework.jdbc.datasource.DataSourceTransactionManager] Triggering afterCommit synchronization
08:15:07.818 TRACE [task-scheduler-3][org.springframework.integration.endpoint.SourcePollingChannelAdapter] 'Committing' pseudo-transactional resource
...

C: DELE 1
S: +OK Message deleted
C: QUIT
S: +OK Apache James POP3 Server signing off.
08:15:07.911 TRACE [task-scheduler-3][org.springframework.jdbc.datasource.DataSourceTransactionManager] Triggering afterCompletion synchronization
08:15:07.911 TRACE [task-scheduler-3][org.springframework.transaction.support.TransactionSynchronizationManager] Clearing transaction synchronization
08:15:07.912 TRACE [task-scheduler-3][org.springframework.transaction.support.TransactionSynchronizationManager] Removed value [org.springframework.jdbc.datasource.ConnectionHolder@3d8f1be9] for key [org.springframework.jdbc.datasource.SimpleDriverDataSource@64df83e5] from thread [task-scheduler-3]
08:15:07.912 DEBUG [task-scheduler-3][org.springframework.jdbc.datasource.DataSourceTransactionManager] Releasing JDBC Connection [conn3: url=jdbc:h2:mem:dataSource user=SA] after transaction
08:15:07.912 DEBUG [task-scheduler-3][org.springframework.jdbc.datasource.DataSourceUtils] Returning JDBC Connection to DataSource

This is using 2.2.0.BUILD-SNAPSHOT.

[al94781]

Cheers guys,

We finally got time in our dev. schedule to try this out. Worked a treat with v.2.2.0.M4 and the following config:

    <!-- Additional properties for the incoming email poller -->
    <util:properties id="javaMailProperties">
        <prop key="mail.pop3.socketFactory.fallback">false</prop>
        <prop key="mail.debug">true</prop>
        <prop key="mail.pop3.rsetbeforequit">false</prop>
    </util:properties>

    <!-- This inbound channel adaptor interfaces to the sendmail POP3 queue for the COPLINK mailbopx -->
    <int-mail:inbound-channel-adapter id="pop3PollingChannelAdaptor"
                                      store-uri="pop3://medev1:medev1@XX.XX.XX.XX/inbox"
                                      channel="receiveIncomingEmailChannel"
                                      should-delete-messages="true"
                                      auto-startup="false"
                                      java-mail-properties="javaMailProperties">
        <!-- Will poll every 10 seconds -->
        <int:poller fixed-rate="1000" max-messages-per-poll="1">

            <int:transactional transaction-manager="txManager"
                               isolation="DEFAULT"
                               propagation="REQUIRED"
                               read-only="false"
                               timeout="10000" />
        </int:poller>
    </int-mail:inbound-channel-adapter>

[MachineCode]

Hi There.

I'm trying to use this facility but the polling gets exceptions after a few polls and seemingly stops contacting the mail server. This happens even with no emails in the pop3 inbox. I am using SI 2.2.0 RC1 and the mail server is Microsoft Exchange Server 2003 POP3 server version 6.5.7638.1.

Initially the debug output appears on the Weblogic console for each poll:

DEBUG POP3: connecting to host "10.1nn.nn.nn", port 110, isSSL false
S: +OK Microsoft Exchange Server 2003 POP3 server version 6.5.7638.1 (xxxx.xxxx.xxxx.xxxx.xxxx) ready.
C: USER ***username-not-shown***
S: +OK
C: PASS ***password-not-shown***
S: +OK User successfully logged on.
C: STAT
S: +OK 0 0
C: NOOP
S: +OK
C: QUIT
S: +OK Microsoft Exchange Server 2003 POP3 server version 6.5.7638.1 signing off.

... but after a few polls it stops outputting debug info. I've traced the code in Eclipse and it is 'polling' but hits an exception, which is too deep to really debug properly. This is the exception grabbed from Eclipse:

ex	InvocationTargetException  (id=16380)	
	backtrace	 (id=16382)	
	cause	null	
	detailMessage	null	
	noBackTrace	0	
	stackTrace	null	
	target	IllegalStateException  (id=16383)	
		backtrace	 (id=16384)	
		cause	IllegalStateException  (id=16383)	
		detailMessage	"Already value [org.springframework.integration.transaction.IntegrationResourceHolder@3cab8b3] for key [org.springframework.integration.mail.MailReceivingMessageSource@2de3fa0] bound to thread [task-scheduler-2]" (id=16386)	
		noBackTrace	0	
		stackTrace	null

Also this is the associated stack trace:

Thread [task-scheduler-5] (Suspended)	
	AopUtils.invokeJoinpointUsingReflection(Object, Method, Object[]) line: 314
	ReflectiveMethodInvocation.invokeJoinpoint() line: 183	
	ReflectiveMethodInvocation.proceed() line: 150	
	TransactionInterceptor.invoke(MethodInvocation) line: 110	
	ReflectiveMethodInvocation.proceed() line: 172	
	JdkDynamicAopProxy.invoke(Object, Method, Object[]) line: 202	
	$Proxy75.call() line: not available [local variables unavailable]	
	AbstractPollingEndpoint$Poller$1.run() line: 207	
	ErrorHandlingTaskExecutor$1.run() line: 52	
	SyncTaskExecutor.execute(Runnable) line: 48	
	ErrorHandlingTaskExecutor.execute(Runnable) line: 49	
	AbstractPollingEndpoint$Poller.run() line: 202	
	ReschedulingRunnable(DelegatingErrorHandlingRunnable).run() line: 51	
	ReschedulingRunnable.run() line: 81	
	Executors$RunnableAdapter<T>.call() line: 441	
	FutureTask$Sync.innerRun() line: 303	
	ScheduledThreadPoolExecutor$ScheduledFutureTask<V>(FutureTask<V>).run() line: 138	
	ScheduledThreadPoolExecutor$ScheduledFutureTask<V>.access$301(ScheduledThreadPoolExecutor$ScheduledFutureTask) line: 98	
	ScheduledThreadPoolExecutor$ScheduledFutureTask<V>.run() line: 206	
	ThreadPoolExecutor$Worker.runTask(Runnable) line: 886	
	ThreadPoolExecutor$Worker.run() line: 908	
	Thread.run() line: 662

Getting the debug session to resume, results in the poller code being entered again - ultimately hitting the same exception.

I've tried various combinations of fixed-delay (mainly 20 seconds) and transaction timeout (from 10000 seconds to 5 seconds) but still the same problem. It seems to work fine without the int:transactional section.

Any ideas? We really need transactional processing of pop3 emails.

[Gary Russell]

We just fixed this; RC2 will be out shortly (planned for today); it is fixed in 2.2.0.BUILD-SNAPSHOT.