Thanks for the reply. I opened a JIRA:
https://issues.apache.org/jira/browse/MAILBOX-216
On Mar 9, 2015, at 0:43, Eric Charles <e...@apache.org> wrote:
> Can you open a JIRA and copy there that information. We had some
> deadlock we solved some time ago, but it seems there is still something
> to work out.
>
> On 03/03/2015 05:27 AM, Kohei Nozaki wrote:
>> Hello, I'm running James3 in trunk with Apache Derby Embedded. today I found
>> some weird log in wrapper.log. does it mean something went wrong? or can I
>> safely ignore it?
>>
>> INFO | jvm 1 | 2015/03/03 03:29:55 | Caused by:
>> org.apache.openjpa.lib.jdbc.ReportingSQLException: A lock could not be
>> obtained due to a deadlock, cycle of locks and waiters is:
>> INFO | jvm 1 | 2015/03/03 03:29:55 | Lock : ROW, JAMES_MAIL, (735,6)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | Waiting XID : {123722435, U} ,
>> APP, DELETE FROM APP.JAMES_MAIL WHERE EXISTS (SELECT 1 FROM APP.JAMES_MAIL
>> t0 WHERE (t0.MAILBOX_ID = ? AND t0.MAIL_UID = ? AND t0.MAIL_IS_DELETED = ?)
>> AND (t0.MAILBOX_ID = APP.JAMES_MAIL.MAILBOX_ID AND t0.MAIL_UID =
>> APP.JAMES_MAIL.MAIL_UID))
>> INFO | jvm 1 | 2015/03/03 03:29:55 | Granted XID : {123722454, X}
>> INFO | jvm 1 | 2015/03/03 03:29:55 | Lock : TABLE, JAMES_MAIL_PROPERTY,
>> Tablelock
>> INFO | jvm 1 | 2015/03/03 03:29:55 | Waiting XID : {123722454, IX} ,
>> APP, INSERT INTO APP.JAMES_MAIL_PROPERTY (PROPERTY_ID, PROPERTY_LINE_NUMBER,
>> PROPERTY_LOCAL_NAME, PROPERTY_NAME_SPACE, PROPERTY_VALUE, MAILBOX_ID,
>> MAIL_UID) VALUES (?, ?, ?, ?, ?, ?, ?)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | Granted XID : {123722435, X}
>> INFO | jvm 1 | 2015/03/03 03:29:55 | . The selected victim is XID :
>> 123722435. {prepstmnt 239961255 DELETE FROM APP.JAMES_MAIL WHERE EXISTS
>> (SELECT 1 FROM APP.JAMES_MAIL t0 WHERE (t0.MAILBOX_ID = ? AND t0.MAIL_UID =
>> ? AND t0.MAIL_IS_DELETED = ?) AND (t0.MAILBOX_ID = APP.JAMES_MAIL.MAILBOX_ID
>> AND t0.MAIL_UID = APP.JAMES_MAIL.MAIL_UID))} [code=30000, state=40001]
>>
>> I acquired the source tree in February 4 of this year.
>>
>> $ pwd
>> /Users/kyle/src/james-server
>> $ svn info | grep "Revision:"
>> Revision: 1657019
>>
>> Related libraries:
>>
>> -rw------- 1 james james 118172 Feb 4 15:59
>> apache-james-mailbox-api-0.6-20150204.040032-612.jar
>> -rw------- 1 james james 38208 Feb 4 16:05
>> apache-james-mailbox-cassandra-0.6-20150204.040425-162.jar
>> -rw------- 1 james james 58663 Feb 4 16:05
>> apache-james-mailbox-jcr-0.6-20150204.040507-581.jar
>> -rw------- 1 james james 78735 Feb 4 16:05
>> apache-james-mailbox-jpa-0.6-20150204.040524-579.jar
>> -rw------- 1 james james 33190 Feb 4 16:05
>> apache-james-mailbox-lucene-0.6-20150204.040533-581.jar
>> -rw------- 1 james james 75204 Feb 4 15:59
>> apache-james-mailbox-maildir-0.6-20150204.040556-576.jar
>> -rw------- 1 james james 23255 Feb 4 15:59
>> apache-james-mailbox-memory-0.6-20150204.040602-577.jar
>> -rw------- 1 james james 18574 Feb 4 16:05
>> apache-james-mailbox-spring-0.6-20150204.040621-568.jar
>> -rw------- 1 james james 188973 Feb 4 15:59
>> apache-james-mailbox-store-0.6-20150204.040045-608.jar
>> -rw------- 1 james james 25298 Feb 4 15:59
>> apache-james-mailbox-tool-0.6-20150204.040612-571.jar
>>
>> Full stacktrace: (My domain name is replaced by example.org).
>>
>> INFO | jvm 1 | 2015/03/03 03:29:55 | INFO 03:29:54,514 |
>> james.imapserver | ID=1358640821 Expunge failed for mailbox
>> #private:k...@example.org:INBOX
>> INFO | jvm 1 | 2015/03/03 03:29:55 |
>> org.apache.james.mailbox.exception.MailboxException: Search of MessageRange
>> TYPE: ONE UID: 751:751 failed in mailbox Mailbox ( mailboxId = 1 name =
>> INBOX uidValidity = 1950409796 )
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.mailbox.jpa.mail.JPAMessageMapper.expungeMarkedForDeletionInMailbox(JPAMessageMapper.java:262)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.mailbox.store.StoreMessageManager$7.run(StoreMessageManager.java:678)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.mailbox.store.StoreMessageManager$7.run(StoreMessageManager.java:675)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.mailbox.store.transaction.TransactionalMapper.execute(TransactionalMapper.java:37)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.mailbox.store.StoreMessageManager.deleteMarkedInMailbox(StoreMessageManager.java:675)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.mailbox.store.StoreMessageManager.expunge(StoreMessageManager.java:233)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.ExpungeProcessor.expunge(ExpungeProcessor.java:107)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.ExpungeProcessor.doProcess(ExpungeProcessor.java:75)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.ExpungeProcessor.doProcess(ExpungeProcessor.java:47)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.AbstractMailboxProcessor.doProcess(AbstractMailboxProcessor.java:100)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.AbstractMailboxProcessor.process(AbstractMailboxProcessor.java:89)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.AbstractMailboxProcessor.doProcess(AbstractMailboxProcessor.java:83)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.AbstractMailboxProcessor.doProcess(AbstractMailboxProcessor.java:66)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:52)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imap.processor.base.AbstractChainedProcessor.process(AbstractChainedProcessor.java:54)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.imapserver.netty.ImapChannelUpstreamHandler.messageReceived(ImapChannelUpstreamHandler.java:187)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:75)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:558)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:777)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:327)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.jboss.netty.handler.codec.frame.FrameDecoder.callDecode(FrameDecoder.java:305)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.jboss.netty.handler.codec.frame.FrameDecoder.messageReceived(FrameDecoder.java:207)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:75)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:558)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:777)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.jboss.netty.handler.execution.ChannelUpstreamEventRunnable.run(ChannelUpstreamEventRunnable.java:44)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.jboss.netty.handler.execution.OrderedMemoryAwareThreadPoolExecutor$ChildExecutor.run(OrderedMemoryAwareThreadPoolExecutor.java:312)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> java.lang.Thread.run(Thread.java:745)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | Caused by:
>> <openjpa-2.2.1-r422266:1396819 nonfatal store error>
>> org.apache.openjpa.persistence.OptimisticLockException: Unable to obtain an
>> object lock on "DELETE FROM APP.JAMES_MAIL WHERE EXISTS (SELECT 1 FROM
>> APP.JAMES_MAIL t0 WHERE (t0.MAILBOX_ID = ? AND t0.MAIL_UID = ? AND
>> t0.MAIL_IS_DELETED = ?) AND (t0.MAILBOX_ID = APP.JAMES_MAIL.MAILBOX_ID AND
>> t0.MAIL_UID = APP.JAMES_MAIL.MAIL_UID)) [java.lang.String]".
>> INFO | jvm 1 | 2015/03/03 03:29:55 | FailedObject: DELETE FROM
>> APP.JAMES_MAIL WHERE EXISTS (SELECT 1 FROM APP.JAMES_MAIL t0 WHERE
>> (t0.MAILBOX_ID = ? AND t0.MAIL_UID = ? AND t0.MAIL_IS_DELETED = ?) AND
>> (t0.MAILBOX_ID = APP.JAMES_MAIL.MAILBOX_ID AND t0.MAIL_UID =
>> APP.JAMES_MAIL.MAIL_UID)) [java.lang.String]
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.jdbc.sql.DBDictionary.narrow(DBDictionary.java:4940)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.jdbc.sql.DBDictionary.newStoreException(DBDictionary.java:4918)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.jdbc.sql.SQLExceptions.getStore(SQLExceptions.java:136)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.jdbc.sql.SQLExceptions.getStore(SQLExceptions.java:78)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.jdbc.kernel.JDBCStoreQuery.executeBulkOperation(JDBCStoreQuery.java:579)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.jdbc.kernel.JDBCStoreQuery.executeDelete(JDBCStoreQuery.java:491)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.kernel.ExpressionStoreQuery$DataStoreExecutor.executeDelete(ExpressionStoreQuery.java:789)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.kernel.QueryImpl.delete(QueryImpl.java:1025)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.kernel.QueryImpl.execute(QueryImpl.java:865)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.kernel.QueryImpl.deleteAll(QueryImpl.java:892)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.kernel.DelegatingQuery.deleteAll(DelegatingQuery.java:574)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.persistence.QueryImpl.executeUpdate(QueryImpl.java:374)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.mailbox.jpa.mail.JPAMessageMapper.deleteDeletedMessagesInMailboxWithUID(JPAMessageMapper.java:378)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.james.mailbox.jpa.mail.JPAMessageMapper.expungeMarkedForDeletionInMailbox(JPAMessageMapper.java:240)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | ... 52 more
>> INFO | jvm 1 | 2015/03/03 03:29:55 | Caused by:
>> org.apache.openjpa.lib.jdbc.ReportingSQLException: A lock could not be
>> obtained due to a deadlock, cycle of locks and waiters is:
>> INFO | jvm 1 | 2015/03/03 03:29:55 | Lock : ROW, JAMES_MAIL, (735,6)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | Waiting XID : {123722435, U} ,
>> APP, DELETE FROM APP.JAMES_MAIL WHERE EXISTS (SELECT 1 FROM APP.JAMES_MAIL
>> t0 WHERE (t0.MAILBOX_ID = ? AND t0.MAIL_UID = ? AND t0.MAIL_IS_DELETED = ?)
>> AND (t0.MAILBOX_ID = APP.JAMES_MAIL.MAILBOX_ID AND t0.MAIL_UID =
>> APP.JAMES_MAIL.MAIL_UID))
>> INFO | jvm 1 | 2015/03/03 03:29:55 | Granted XID : {123722454, X}
>> INFO | jvm 1 | 2015/03/03 03:29:55 | Lock : TABLE, JAMES_MAIL_PROPERTY,
>> Tablelock
>> INFO | jvm 1 | 2015/03/03 03:29:55 | Waiting XID : {123722454, IX} ,
>> APP, INSERT INTO APP.JAMES_MAIL_PROPERTY (PROPERTY_ID, PROPERTY_LINE_NUMBER,
>> PROPERTY_LOCAL_NAME, PROPERTY_NAME_SPACE, PROPERTY_VALUE, MAILBOX_ID,
>> MAIL_UID) VALUES (?, ?, ?, ?, ?, ?, ?)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | Granted XID : {123722435, X}
>> INFO | jvm 1 | 2015/03/03 03:29:55 | . The selected victim is XID :
>> 123722435. {prepstmnt 239961255 DELETE FROM APP.JAMES_MAIL WHERE EXISTS
>> (SELECT 1 FROM APP.JAMES_MAIL t0 WHERE (t0.MAILBOX_ID = ? AND t0.MAIL_UID =
>> ? AND t0.MAIL_IS_DELETED = ?) AND (t0.MAILBOX_ID = APP.JAMES_MAIL.MAILBOX_ID
>> AND t0.MAIL_UID = APP.JAMES_MAIL.MAIL_UID))} [code=30000, state=40001]
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator.wrap(LoggingConnectionDecorator.java:219)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator.wrap(LoggingConnectionDecorator.java:195)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator.access$1000(LoggingConnectionDecorator.java:59)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator$LoggingConnection$LoggingPreparedStatement.executeUpdate(LoggingConnectionDecorator.java:1134)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.lib.jdbc.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:272)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.jdbc.kernel.JDBCStoreManager$CancelPreparedStatement.executeUpdate(JDBCStoreManager.java:1765)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.jdbc.kernel.JDBCStoreQuery.executeUpdate(JDBCStoreQuery.java:746)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | at
>> org.apache.openjpa.jdbc.kernel.JDBCStoreQuery.executeBulkOperation(JDBCStoreQuery.java:577)
>> INFO | jvm 1 | 2015/03/03 03:29:55 | ... 61 more
>> INFO | jvm 1 | 2015/03/03 03:54:59 | WARN 03:54:59,387 |
>> james.imapserver | ID=32652598 Error while processing imap request:
>> java.io.IOException - Connection timed out
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: server-user-unsubscr...@james.apache.org
>> For additional commands, e-mail: server-user-h...@james.apache.org
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: server-user-unsubscr...@james.apache.org
> For additional commands, e-mail: server-user-h...@james.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscr...@james.apache.org
For additional commands, e-mail: server-user-h...@james.apache.org
