James Server
  1. James Server
  2. JAMES-900

Possible race-condition in MimeMessageCopyOnWriteProxy

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.3.1, 2.3.2, 3.0-M1
    • Fix Version/s: 3.0-M2
    • Labels:
      None
    • Environment:
      Windows XP, Sun JDK 1.6.0_12, MySQL 5.0 backend

      Description

      The exception below occurs 1-2 times a day on a server handling between a few hundred and a few thousands of messages per day.

      I took a short look at the code, and it looks like there's a MimeMessageCopyOnWriteProxy wrapping a null message. A few possible causes:

      • MessageReferenceTracker.getWrapped() should be synchronized, as the field is neither final nor volatile and so it's possible that a thread other than the one which creates it will see a null wrapped message.
      • the refCount field is not properly synchronized nor volatile so methods which set/replace its value (private constructor, getWrappedMessageForWriting) may cause some threads to see the new instance and some the old one. this can result in buggy reference counting, which can result in the wrapped message being set to null (when reference count is decreased too much) and then being accessed.
      • a MailImpl is being constructed (or copy-constructed) somewhere with a null message (which is passed on to the proxy class).
      • something completely different.

      The stacktrace from spoolmanager log:

      25/04/09 02:00:58 ERROR spoolmanager.transport: Exception calling LocalDelivery: Exception spooling message: Exception caught while storing mail Container:
      javax.mail.MessagingException: Exception spooling message: Exception caught while storing mail Container: ;
      nested exception is:
      javax.mail.MessagingException: Exception caught while storing mail Container: ;
      nested exception is:
      java.lang.NullPointerException
      at org.apache.james.James.sendMail(James.java:501)
      at org.apache.james.James.sendMail(James.java:454)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
      at java.lang.reflect.Method.invoke(Unknown Source)
      at org.apache.avalon.phoenix.components.application.BlockInvocationHandler.invoke(BlockInvocationHandler.java:134)
      at $Proxy9.sendMail(Unknown Source)
      at org.apache.james.transport.mailets.ToMultiRepository.service(ToMultiRepository.java:183)
      at org.apache.james.transport.mailets.LocalDelivery.service(LocalDelivery.java:66)
      at org.apache.james.transport.LinearProcessor.service(LinearProcessor.java:424)
      at org.apache.james.transport.JamesSpoolManager.process(JamesSpoolManager.java:405)
      at org.apache.james.transport.JamesSpoolManager.run(JamesSpoolManager.java:309)
      at java.lang.Thread.run(Unknown Source)
      Caused by: javax.mail.MessagingException: Exception caught while storing mail Container: ;
      nested exception is:
      java.lang.NullPointerException
      at org.apache.james.mailrepository.JDBCMailRepository.store(JDBCMailRepository.java:764)
      at org.apache.james.mailrepository.JDBCSpoolRepository.store(JDBCSpoolRepository.java:240)
      at org.apache.james.mailrepository.MailStoreSpoolRepository.store(MailStoreSpoolRepository.java:126)
      at sun.reflect.GeneratedMethodAccessor10.invoke(Unknown Source)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
      at java.lang.reflect.Method.invoke(Unknown Source)
      at org.apache.avalon.phoenix.components.application.BlockInvocationHandler.invoke(BlockInvocationHandler.java:134)
      at $Proxy5.store(Unknown Source)
      at org.apache.james.James.sendMail(James.java:493)
      ... 13 more
      Caused by: java.lang.NullPointerException
      at org.apache.james.core.MimeMessageUtil.calculateMessageSize(MimeMessageUtil.java:277)
      at org.apache.james.core.MimeMessageUtil.getMessageSize(MimeMessageUtil.java:261)
      at org.apache.james.core.MimeMessageCopyOnWriteProxy.getMessageSize(MimeMessageCopyOnWriteProxy.java:745)
      at org.apache.james.core.MimeMessageUtil.getMessageSize(MimeMessageUtil.java:257)
      at org.apache.james.core.MailImpl.getMessageSize(MailImpl.java:372)
      at org.apache.james.mailrepository.MessageInputStream.<init>(MessageInputStream.java:53)
      at org.apache.james.mailrepository.JDBCMailRepository.store(JDBCMailRepository.java:718)
      ... 21 more
      javax.mail.MessagingException: Exception caught while storing mail Container: ;
      nested exception is:
      java.lang.NullPointerException
      at org.apache.james.mailrepository.JDBCMailRepository.store(JDBCMailRepository.java:764)
      at org.apache.james.mailrepository.JDBCSpoolRepository.store(JDBCSpoolRepository.java:240)
      at org.apache.james.mailrepository.MailStoreSpoolRepository.store(MailStoreSpoolRepository.java:126)
      at sun.reflect.GeneratedMethodAccessor10.invoke(Unknown Source)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
      at java.lang.reflect.Method.invoke(Unknown Source)
      at org.apache.avalon.phoenix.components.application.BlockInvocationHandler.invoke(BlockInvocationHandler.java:134)
      at $Proxy5.store(Unknown Source)
      at org.apache.james.James.sendMail(James.java:493)
      at org.apache.james.James.sendMail(James.java:454)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
      at java.lang.reflect.Method.invoke(Unknown Source)
      at org.apache.avalon.phoenix.components.application.BlockInvocationHandler.invoke(BlockInvocationHandler.java:134)
      at $Proxy9.sendMail(Unknown Source)
      at org.apache.james.transport.mailets.ToMultiRepository.service(ToMultiRepository.java:183)
      at org.apache.james.transport.mailets.LocalDelivery.service(LocalDelivery.java:66)
      at org.apache.james.transport.LinearProcessor.service(LinearProcessor.java:424)
      at org.apache.james.transport.JamesSpoolManager.process(JamesSpoolManager.java:405)
      at org.apache.james.transport.JamesSpoolManager.run(JamesSpoolManager.java:309)
      at java.lang.Thread.run(Unknown Source)
      Caused by: java.lang.NullPointerException
      at org.apache.james.core.MimeMessageUtil.calculateMessageSize(MimeMessageUtil.java:277)
      at org.apache.james.core.MimeMessageUtil.getMessageSize(MimeMessageUtil.java:261)
      at org.apache.james.core.MimeMessageCopyOnWriteProxy.getMessageSize(MimeMessageCopyOnWriteProxy.java:745)
      at org.apache.james.core.MimeMessageUtil.getMessageSize(MimeMessageUtil.java:257)
      at org.apache.james.core.MailImpl.getMessageSize(MailImpl.java:372)
      at org.apache.james.mailrepository.MessageInputStream.<init>(MessageInputStream.java:53)
      at org.apache.james.mailrepository.JDBCMailRepository.store(JDBCMailRepository.java:718)
      ... 21 more
      java.lang.NullPointerException
      at org.apache.james.core.MimeMessageUtil.calculateMessageSize(MimeMessageUtil.java:277)
      at org.apache.james.core.MimeMessageUtil.getMessageSize(MimeMessageUtil.java:261)
      at org.apache.james.core.MimeMessageCopyOnWriteProxy.getMessageSize(MimeMessageCopyOnWriteProxy.java:745)
      at org.apache.james.core.MimeMessageUtil.getMessageSize(MimeMessageUtil.java:257)
      at org.apache.james.core.MailImpl.getMessageSize(MailImpl.java:372)
      at org.apache.james.mailrepository.MessageInputStream.<init>(MessageInputStream.java:53)
      at org.apache.james.mailrepository.JDBCMailRepository.store(JDBCMailRepository.java:718)
      at org.apache.james.mailrepository.JDBCSpoolRepository.store(JDBCSpoolRepository.java:240)
      at org.apache.james.mailrepository.MailStoreSpoolRepository.store(MailStoreSpoolRepository.java:126)
      at sun.reflect.GeneratedMethodAccessor10.invoke(Unknown Source)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
      at java.lang.reflect.Method.invoke(Unknown Source)
      at org.apache.avalon.phoenix.components.application.BlockInvocationHandler.invoke(BlockInvocationHandler.java:134)
      at $Proxy5.store(Unknown Source)
      at org.apache.james.James.sendMail(James.java:493)
      at org.apache.james.James.sendMail(James.java:454)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
      at java.lang.reflect.Method.invoke(Unknown Source)
      at org.apache.avalon.phoenix.components.application.BlockInvocationHandler.invoke(BlockInvocationHandler.java:134)
      at $Proxy9.sendMail(Unknown Source)
      at org.apache.james.transport.mailets.ToMultiRepository.service(ToMultiRepository.java:183)
      at org.apache.james.transport.mailets.LocalDelivery.service(LocalDelivery.java:66)
      at org.apache.james.transport.LinearProcessor.service(LinearProcessor.java:424)
      at org.apache.james.transport.JamesSpoolManager.process(JamesSpoolManager.java:405)
      at org.apache.james.transport.JamesSpoolManager.run(JamesSpoolManager.java:309)
      at java.lang.Thread.run(Unknown Source)

        Activity

        Hide
        Norman Maurer added a comment -

        fixed

        Show
        Norman Maurer added a comment - fixed
        Hide
        Norman Maurer added a comment -

        MimeMessageCopyOnWriteProxy lacks synchronized keyword on a few methods

        Show
        Norman Maurer added a comment - MimeMessageCopyOnWriteProxy lacks synchronized keyword on a few methods
        Hide
        Norman Maurer added a comment -

        I agree with Stefano, anyway I think adding the synchronized make sense.

        @Stefano: WDYT as Author of the class

        Show
        Norman Maurer added a comment - I agree with Stefano, anyway I think adding the synchronized make sense. @Stefano: WDYT as Author of the class
        Hide
        Stefano Bagnara added a comment -

        Never happened to me. Maybe you are using dbfile as spool repositories, and they are not supported to do that (IIRC using dbfile in spool repositories led to NPE).

        Show
        Stefano Bagnara added a comment - Never happened to me. Maybe you are using dbfile as spool repositories, and they are not supported to do that (IIRC using dbfile in spool repositories led to NPE).
        Hide
        Norman Maurer added a comment -

        Assign to 3.0-M2

        Show
        Norman Maurer added a comment - Assign to 3.0-M2
        Hide
        Amichai Rothman added a comment -

        I've made good progress analyzing the logs some more - I've found a correspondence between these errors and errors in the mailet logs (see below). The mail identifier in the last line is the one that appears also in the spoolmanager logs. So I suppose the bug can be rephrased as: a message with a mime format error cannot be stored in the error store.

        Note that I first tried a simple fix for #1 and #2, namely adding the synchronized modifier to the methods MessageReferenceTracker.getWrapped(), getWrappedMessageForWriting() and getWrappedMessage() in the MimeMessageCopyOnWriteProxy class. u might want to make these changes anyway because the code as it is does have potential bugs without them, even if not this specific error.

        02/05/09 04:07:50 INFO James.Mailet: Error while storing mail.
        javax.mail.MessagingException: Exception caught while storing mail Container: ;
        nested exception is:
        javax.mail.MessagingException: IOException while copying message;
        nested exception is:
        com.sun.mail.util.DecodingException: BASE64Decoder: Error in encoded stream: needed 4 valid base64 characters but only got 2 before EOF, the 10 most recent characters were: "\130\190\130\179\130\162\129B\r\n"
        at org.apache.james.mailrepository.JDBCMailRepository.store(JDBCMailRepository.java:764)
        at org.apache.james.transport.mailets.ToMultiRepository.storeMail(ToMultiRepository.java:230)
        at org.apache.james.transport.mailets.ToMultiRepository.service(ToMultiRepository.java:154)
        at org.apache.james.transport.mailets.LocalDelivery.service(LocalDelivery.java:66)
        at org.apache.james.transport.LinearProcessor.service(LinearProcessor.java:424)
        at org.apache.james.transport.JamesSpoolManager.process(JamesSpoolManager.java:405)
        at org.apache.james.transport.JamesSpoolManager.run(JamesSpoolManager.java:309)
        at java.lang.Thread.run(Unknown Source)
        Caused by: javax.mail.MessagingException: IOException while copying message;
        nested exception is:
        com.sun.mail.util.DecodingException: BASE64Decoder: Error in encoded stream: needed 4 valid base64 characters but only got 2 before EOF, the 10 most recent characters were: "\130\190\130\179\130\162\129B\r\n"
        at org.apache.james.core.MimeMessageWrapper.<init>(MimeMessageWrapper.java:149)
        at org.apache.james.core.MimeMessageCopyOnWriteProxy.getWrappedMessageForWriting(MimeMessageCopyOnWriteProxy.java:149)
        at org.apache.james.core.MimeMessageCopyOnWriteProxy.saveChanges(MimeMessageCopyOnWriteProxy.java:687)
        at org.apache.james.core.MimeMessageUtil.writeToInternal(MimeMessageUtil.java:84)
        at org.apache.james.core.MimeMessageUtil.writeTo(MimeMessageUtil.java:70)
        at org.apache.james.core.MimeMessageUtil.writeTo(MimeMessageUtil.java:50)
        at org.apache.james.mailrepository.MessageInputStream.writeStream(MessageInputStream.java:112)
        at org.apache.james.mailrepository.MessageInputStream.<init>(MessageInputStream.java:82)
        at org.apache.james.mailrepository.JDBCMailRepository.store(JDBCMailRepository.java:718)
        ... 7 more
        Caused by: com.sun.mail.util.DecodingException: BASE64Decoder: Error in encoded stream: needed 4 valid base64 characters but only got 2 before EOF, the 10 most recent characters were: "\130\190\130\179\130\162\129B\r\n"
        at com.sun.mail.util.BASE64DecoderStream.decode(BASE64DecoderStream.java:252)
        at com.sun.mail.util.BASE64DecoderStream.read(BASE64DecoderStream.java:140)
        at java.io.FilterInputStream.read(Unknown Source)
        at org.apache.james.core.MimeMessageUtil.copyStream(MimeMessageUtil.java:167)
        at org.apache.james.core.MimeMessageUtil.writeMessageBodyTo(MimeMessageUtil.java:152)
        at org.apache.james.core.MimeMessageUtil.writeToInternal(MimeMessageUtil.java:90)
        at org.apache.james.core.MimeMessageWrapper.writeTo(MimeMessageWrapper.java:281)
        at org.apache.james.core.MimeMessageWrapper.writeTo(MimeMessageWrapper.java:257)
        at org.apache.james.core.MimeMessageWrapper.writeTo(MimeMessageWrapper.java:242)
        at org.apache.james.core.MimeMessageWrapper.<init>(MimeMessageWrapper.java:140)
        ... 15 more
        02/05/09 04:07:50 INFO James.Mailet: ToRepository: Storing mail Mail1241237254190-37952 in db://maildb/deadletter/error

        Show
        Amichai Rothman added a comment - I've made good progress analyzing the logs some more - I've found a correspondence between these errors and errors in the mailet logs (see below). The mail identifier in the last line is the one that appears also in the spoolmanager logs. So I suppose the bug can be rephrased as: a message with a mime format error cannot be stored in the error store. Note that I first tried a simple fix for #1 and #2, namely adding the synchronized modifier to the methods MessageReferenceTracker.getWrapped(), getWrappedMessageForWriting() and getWrappedMessage() in the MimeMessageCopyOnWriteProxy class. u might want to make these changes anyway because the code as it is does have potential bugs without them, even if not this specific error. 02/05/09 04:07:50 INFO James.Mailet: Error while storing mail. javax.mail.MessagingException: Exception caught while storing mail Container: ; nested exception is: javax.mail.MessagingException: IOException while copying message; nested exception is: com.sun.mail.util.DecodingException: BASE64Decoder: Error in encoded stream: needed 4 valid base64 characters but only got 2 before EOF, the 10 most recent characters were: "\130\190\130\179\130\162\129B\r\n" at org.apache.james.mailrepository.JDBCMailRepository.store(JDBCMailRepository.java:764) at org.apache.james.transport.mailets.ToMultiRepository.storeMail(ToMultiRepository.java:230) at org.apache.james.transport.mailets.ToMultiRepository.service(ToMultiRepository.java:154) at org.apache.james.transport.mailets.LocalDelivery.service(LocalDelivery.java:66) at org.apache.james.transport.LinearProcessor.service(LinearProcessor.java:424) at org.apache.james.transport.JamesSpoolManager.process(JamesSpoolManager.java:405) at org.apache.james.transport.JamesSpoolManager.run(JamesSpoolManager.java:309) at java.lang.Thread.run(Unknown Source) Caused by: javax.mail.MessagingException: IOException while copying message; nested exception is: com.sun.mail.util.DecodingException: BASE64Decoder: Error in encoded stream: needed 4 valid base64 characters but only got 2 before EOF, the 10 most recent characters were: "\130\190\130\179\130\162\129B\r\n" at org.apache.james.core.MimeMessageWrapper.<init>(MimeMessageWrapper.java:149) at org.apache.james.core.MimeMessageCopyOnWriteProxy.getWrappedMessageForWriting(MimeMessageCopyOnWriteProxy.java:149) at org.apache.james.core.MimeMessageCopyOnWriteProxy.saveChanges(MimeMessageCopyOnWriteProxy.java:687) at org.apache.james.core.MimeMessageUtil.writeToInternal(MimeMessageUtil.java:84) at org.apache.james.core.MimeMessageUtil.writeTo(MimeMessageUtil.java:70) at org.apache.james.core.MimeMessageUtil.writeTo(MimeMessageUtil.java:50) at org.apache.james.mailrepository.MessageInputStream.writeStream(MessageInputStream.java:112) at org.apache.james.mailrepository.MessageInputStream.<init>(MessageInputStream.java:82) at org.apache.james.mailrepository.JDBCMailRepository.store(JDBCMailRepository.java:718) ... 7 more Caused by: com.sun.mail.util.DecodingException: BASE64Decoder: Error in encoded stream: needed 4 valid base64 characters but only got 2 before EOF, the 10 most recent characters were: "\130\190\130\179\130\162\129B\r\n" at com.sun.mail.util.BASE64DecoderStream.decode(BASE64DecoderStream.java:252) at com.sun.mail.util.BASE64DecoderStream.read(BASE64DecoderStream.java:140) at java.io.FilterInputStream.read(Unknown Source) at org.apache.james.core.MimeMessageUtil.copyStream(MimeMessageUtil.java:167) at org.apache.james.core.MimeMessageUtil.writeMessageBodyTo(MimeMessageUtil.java:152) at org.apache.james.core.MimeMessageUtil.writeToInternal(MimeMessageUtil.java:90) at org.apache.james.core.MimeMessageWrapper.writeTo(MimeMessageWrapper.java:281) at org.apache.james.core.MimeMessageWrapper.writeTo(MimeMessageWrapper.java:257) at org.apache.james.core.MimeMessageWrapper.writeTo(MimeMessageWrapper.java:242) at org.apache.james.core.MimeMessageWrapper.<init>(MimeMessageWrapper.java:140) ... 15 more 02/05/09 04:07:50 INFO James.Mailet: ToRepository: Storing mail Mail1241237254190-37952 in db://maildb/deadletter/error
        Hide
        Stefano Bagnara added a comment -

        Checking your #1 or #2 should be easy. If you understand synchronization you probably can try to fix it, build it, and run it one day and tell us the result.

        My servers handle a lot more mail per day, so maybe it is also related to your configuration. E.g: the reference stuff is mainly used when you have "partial matches" (a mail destinated to multiple recipients and only parts of the recipient are matched by a Matcher). Can you post also your processor configuration?

        Show
        Stefano Bagnara added a comment - Checking your #1 or #2 should be easy. If you understand synchronization you probably can try to fix it, build it, and run it one day and tell us the result. My servers handle a lot more mail per day, so maybe it is also related to your configuration. E.g: the reference stuff is mainly used when you have "partial matches" (a mail destinated to multiple recipients and only parts of the recipient are matched by a Matcher). Can you post also your processor configuration?

          People

          • Assignee:
            Norman Maurer
            Reporter:
            Amichai Rothman
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development