James Server
  1. James Server
  2. JAMES-282

Partial message may be delivered if client disconnects

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.1.3, 2.2.0
    • Fix Version/s: 2.2.0
    • Component/s: DNSServer, SMTPServer
    • Labels:
      None
    • Environment:
      Windows 2000

      Description

      Some emails keep hanging in my sendmail queue. When they are delivered through James I receive a crippled version (no subject, no body) and an error is sent back to Sendmail that the message could not be delivered. The message keeps hanging in the queue and blocks delivery of all messages that are behind it.
      We can accurately reproduce the problem by filling in an address in the 'From' header that can not be resolved by DNS.

      This problem might by hard to reproduce and I apologise for the lengthy description that follows. I don't know what's going on exactly but I think it would be best to give you plenty of information.

      I will try to give an accurate description of the situation.

      The email I try to send is:

      From: "Tom" <tom@xxxxx.org>
      To: "Hes Siemelink" <hes@izecom.com>
      Subject: TEST unkown From
      Date: Tue, 2 Mar 2004 12:46:05 +0100
      Message-ID: <004601c4004b$f26e7950$0502a8c0@smallsvenyos>
      MIME-Version: 1.0
      Content-Type: text/plain;
      charset="us-ascii"
      Content-Transfer-Encoding: 7bit

      Hi Hes,

      Thanks for the info.

      Tom

      The domain 'xxxxx.org' can not be found in the DNS:

      hes@uffizi hes]$ dig xxxxx.org

      ; <<>> DiG 9.2.1 <<>> xxxxx.org
      ;; global options: printcmd
      ;; connection timed out; no servers could be reached

      If I change the domain in the from address to tom@izecom.com, delivery is fine.

      In a test run, the message is first sent to our Sendmail server. Sendmail attempts to deliver it to the recipient 'stress@secure.izemail.com'. Here is a transcript of what happens then:

      Forcing the attempted delivery of mail with the command /usr/lib/sendmail -v -q -C/etc/sendmail.cf ..

      Running /var/spool/mqueue/i4AD2YUS018252 (sequence 1 of 123)
      <stress@secure.izemail.com>... Connecting to extra3.izecom.com. via esmtp...
      220 izecom-martijn SMTP Server (JAMES SMTP Server 2.2.0RC3) ready Mon, 10 May 2004 15:15:53 +0200 (CEST)
      >>> EHLO zloty.izecom.com
      250 izecom-martijn Hello zloty.izecom.com (192.168.0.1 [192.168.0.1])
      >>> MAIL From:<hes@izecom.com>
      250 Sender <hes@izecom.com> OK
      >>> RCPT To:<stress@secure.izemail.com>
      250 Recipient <stress@secure.izemail.com> OK
      >>> DATA
      354 Ok Send data ending with <CRLF>.<CRLF>
      xxxxx.org: Name server timeout
      >>> .
      <stress@secure.izemail.com>... Deferred

      Running /var/spool/mqueue/i4ACdNUS018002 (sequence 2 of 123)
      stress@secure.izemail.com... Deferred: Connection reset by extra3.izecom.com.

      Running /var/spool/mqueue/i4ACaYUS017978 (sequence 3 of 123)
      stress@secure.izemail.com... Deferred: Connection reset by extra3.izecom.com.

      ... etc ...

      Note that the 123 messages are never delivered.

      In the James logs I can see the delivery of the first message was succesful.

      10/05/04 15:23:44 INFO smtpserver : Successfully spooled mail Mail1084195424201-17 from hes@izecom.com for [stress@secure.izemail.com]
      10/05/04 15:23:44 INFO James.Mailet : RemoteDelivery: Attempting delivery of Mail1084195424201-17 to host 192.168.0.18 at 192.168.0.18 to addresses [stress@exchange.izecom.com]
      10/05/04 15:23:44 INFO James.Mailet : RemoteDelivery: Mail (Mail1084195424201-17) sent successfully to 192.168.0.18 at 192.168.0.18

      The James server in this case functions as a relay. Mail is delivered to an Exchange server (running at 192.168.0.18). The (reconstructed) email that is received is:

      Received: from izecom-martijn ([192.168.0.18]) by izecom-martijn.exchange.izecom.com with Microsoft SMTPSVC(5.0.2195.6713);
      Mon, 10 May 2004 15:23:44 +0200
      Return-Path: <hes@izecom.com>
      Received: from 192.168.0.1 ([192.168.0.1])
      by izecom-martijn (JAMES SMTP Server 2.2.0RC3) with SMTP ID 385
      for <stress@secure.izemail.com>;
      Mon, 10 May 2004 15:23:44 +0200 (CEST)
      Date: Mon, 10 May 2004 15:23:44 +0200 (CEST)
      From: hes@izecom.com
      Bcc:
      Message-ID: <IZECOM-MARTIJNoYAPN0000001d@izecom-martijn.exchange.izecom.com>
      X-OriginalArrivalTime: 10 May 2004 13:23:44.0295 (UTC) FILETIME=[0490F370:01C43692]

      So... other points of interest:

      • There is similar behavior with James 2.1.3. In stead of "Deferred" the SMTP response of james is I/O error.
      • The problem does not occur if I talk to directly to James. It is only in combination with Sendmail.
      • The problem does not occur id I talk to directly to Exchange.
      • Mailets/Matchers in use: ToProcessor, RemoteAddrInNetwork, RemoteAddrNotInNetwork, RecipientIsLocal, HostIsLocal and two custom Mailets: Log and ChangeRecipientDomain

      And one question: why does the value of the From field matter?

      Please help!

      Thanks

      Hes.

        Activity

        Hide
        Hes Siemelink added a comment -

        This might of course also be a Sendmail issue.

        Show
        Hes Siemelink added a comment - This might of course also be a Sendmail issue.
        Hide
        Noel J. Bergman added a comment -

        Please turn on DEBUG for the smtpserver (in environment.xml), and look to see what is happening in the smtpserver log. Also let us know if there are any exceptions.

        There should not be any dependence on the From: header, nor does anything appear wrong in the code.

        Show
        Noel J. Bergman added a comment - Please turn on DEBUG for the smtpserver (in environment.xml), and look to see what is happening in the smtpserver log. Also let us know if there are any exceptions. There should not be any dependence on the From: header, nor does anything appear wrong in the code.
        Hide
        Hes Siemelink added a comment -

        Thanks, will do that. I saw no exceptions in the James log on the INFO level (I assume that exceptions are never logged on the DEBUG level?).

        We're a bit puzzled by this behavior – it might by a Sendmail thing but it seems only to occur in combination with James.

        In the meantime the domain that caused the behavior is up again. I have to figure out how to configure our DNS so a certain domain times out before I can test again.

        Apart from the From header that triggers this, perhaps a graver issue is that a partial message is delivered by James, while Sendmail keeps the original message in its queue because it thinks delivery failed.

        We noticed that James delivers mail when the connection is interrupted in the DATA part of the SMTP protocol. So half-sent messages do arrive. Is this according to spec? We did some quick tests on Exchange, Sendmail and Exim and those servers do not deliver mail in this case.

        Show
        Hes Siemelink added a comment - Thanks, will do that. I saw no exceptions in the James log on the INFO level (I assume that exceptions are never logged on the DEBUG level?). We're a bit puzzled by this behavior – it might by a Sendmail thing but it seems only to occur in combination with James. In the meantime the domain that caused the behavior is up again. I have to figure out how to configure our DNS so a certain domain times out before I can test again. Apart from the From header that triggers this, perhaps a graver issue is that a partial message is delivered by James, while Sendmail keeps the original message in its queue because it thinks delivery failed. We noticed that James delivers mail when the connection is interrupted in the DATA part of the SMTP protocol. So half-sent messages do arrive. Is this according to spec? We did some quick tests on Exchange, Sendmail and Exim and those servers do not deliver mail in this case.
        Hide
        Noel J. Bergman added a comment -

        Please try to avoid using JIRA as a discussion tool. Use the mailing list(s) to discuss potential problems.

        The DEBUG level for the the smtphandler will log all of the protocol requests/responses. It will not log the data, but will log other things. If necessary, additional logging could be added in a private build to isolate where a problem is happening in your reproducible environment.

        > perhaps a graver issue is that a partial message is delivered by
        > James, while Sendmail keeps the original message in its queue
        > because it thinks delivery failed.

        If there is an exception during processing, James should not deliver the message. The fact that it attempts delivery indicates that the code has entered processMail (beyond processMailHeaders) without any prior Exception. What happens next is this:

        • processMail creates a new MailImpl with an InputStream.
        • MailImpl creates a MimeMessageInputStreamSource.
        • MimeMessageInputStreamSource reads the entire InputStream
          into a temporary file.
        • The InputStream returns -1 when the <CRLF>.<CRLF> is found.
        • MimeMessageInputStreamSource throws a MessagingException
          if there is an IOException processing the InputStream.

        If we get to the sendMail call in processMail, James believes that it has properly received an entire message, whose contents would be temporarily located in a .m64 file under $PHOENIX_HOME/temp/.

        Show
        Noel J. Bergman added a comment - Please try to avoid using JIRA as a discussion tool. Use the mailing list(s) to discuss potential problems. The DEBUG level for the the smtphandler will log all of the protocol requests/responses. It will not log the data, but will log other things. If necessary, additional logging could be added in a private build to isolate where a problem is happening in your reproducible environment. > perhaps a graver issue is that a partial message is delivered by > James, while Sendmail keeps the original message in its queue > because it thinks delivery failed. If there is an exception during processing, James should not deliver the message. The fact that it attempts delivery indicates that the code has entered processMail (beyond processMailHeaders) without any prior Exception. What happens next is this: processMail creates a new MailImpl with an InputStream. MailImpl creates a MimeMessageInputStreamSource. MimeMessageInputStreamSource reads the entire InputStream into a temporary file. The InputStream returns -1 when the <CRLF>.<CRLF> is found. MimeMessageInputStreamSource throws a MessagingException if there is an IOException processing the InputStream. If we get to the sendMail call in processMail, James believes that it has properly received an entire message, whose contents would be temporarily located in a .m64 file under $PHOENIX_HOME/temp/.
        Hide
        Hes Siemelink added a comment -

        I'm afraiud the problem is not potential but quite real and reproducible.

        We have nailed down the problem to the following:

        • Open a conenection to James
        • Give the HELO, MAIL FROM, RCPT TO and DATA commands
        • Close the connection after the DATA command. (On Windows, the most effective way to do this is by closing the telnet window)

        James will deliver a stub message.

        Here is a log of a test run. Please try a similar test on a local James installation.

        Client side:

        220 izecom-martijn SMTP Server (JAMES SMTP Server 2.2.0RC3) ready Wed, 19 May 2004 15:36:47 +0200 (CEST)
        helo Hes
        250 izecom-martijn Hello Hes (192.168.0.1 [192.168.0.1])
        mail from: <hes@izecom.com>
        250 Sender <hes@izecom.com> OK
        rcpt to: <hes@secure.izemail.com>
        250 Recipient <hes@secure.izemail.com> OK
        data
        354 Ok Send data ending with <CRLF>.<CRLF>
        [Break the connection here]

        Server side:

        19/05/04 15:09:50 INFO smtpserver : Connection from 192.168.0.1 (192.168.0.1)
        19/05/04 15:09:50 DEBUG smtpserver : Sent: 220 izecom-martijn SMTP Server (JAMES SMTP Server 2.2.0RC3) ready Wed, 19 May 2004 15:09:50 +0200 (CEST)
        19/05/04 15:09:50 DEBUG smtpserver : Calling start()
        19/05/04 15:09:50 DEBUG smtpserver : Command received: helo Hes
        19/05/04 15:09:50 DEBUG smtpserver : Sent: 250 izecom-martijn Hello Hes (192.168.0.1 [192.168.0.1])
        19/05/04 15:09:50 DEBUG smtpserver : Calling reset() for inactive watchdog
        19/05/04 15:09:50 DEBUG smtpserver : Watchdog default Worker #13 has time to sleep 360000
        19/05/04 15:10:04 DEBUG smtpserver : Command received: mail from: <hes@izecom.com>
        19/05/04 15:10:04 DEBUG smtpserver : Sent: 250 Sender <hes@izecom.com> OK
        19/05/04 15:10:04 DEBUG smtpserver : Calling reset() default Worker #13
        19/05/04 15:10:18 DEBUG smtpserver : Command received: rcpt to: <hes@secure.izemail.com>
        19/05/04 15:10:18 DEBUG smtpserver : Sent: 250 Recipient <hes@secure.izemail.com> OK
        19/05/04 15:10:18 DEBUG smtpserver : Calling reset() default Worker #13
        19/05/04 15:10:21 DEBUG smtpserver : Command received: data
        19/05/04 15:10:21 DEBUG smtpserver : Sent: 354 Ok Send data ending with <CRLF>.<CRLF>
        19/05/04 15:10:25 INFO smtpserver : Successfully spooled mail Mail1084972225857-1 from hes@izecom.com for [hes@secure.izemail.com]
        19/05/04 15:10:25 DEBUG smtpserver : Sent: 250 Message received
        19/05/04 15:10:25 DEBUG smtpserver : Calling reset() default Worker #13
        19/05/04 15:10:25 DEBUG smtpserver : Calling stop() default Worker #13
        19/05/04 15:10:25 DEBUG smtpserver : Closing socket.
        19/05/04 15:10:25 DEBUG smtpserver : Calling disposeWatchdog() default Worker #13
        19/05/04 15:10:25 DEBUG smtpserver : Returning SMTPHandler to pool.
        19/05/04 15:10:25 DEBUG smtpserver : Returning a org.apache.james.smtpserver.SMTPHandler to the pool
        19/05/04 15:10:25 DEBUG smtpserver : Watchdog default Worker #13 is exiting run().
        19/05/04 15:10:26 INFO James.Mailet : RemoteDelivery: Attempting delivery of Mail1084972225857-1 to host 192.168.0.18 at 192.168.0.18 to addresses [hes@exchange.izecom.com]

        No exception occurs, so the mail is processed. Since no data is specified, only a stub message is delivered.

        Other mail servers we tested (Exchange. Sendmail, Exim) do not process the message when presented with this data.

        Show
        Hes Siemelink added a comment - I'm afraiud the problem is not potential but quite real and reproducible. We have nailed down the problem to the following: Open a conenection to James Give the HELO, MAIL FROM, RCPT TO and DATA commands Close the connection after the DATA command. (On Windows, the most effective way to do this is by closing the telnet window) James will deliver a stub message. Here is a log of a test run. Please try a similar test on a local James installation. Client side: 220 izecom-martijn SMTP Server (JAMES SMTP Server 2.2.0RC3) ready Wed, 19 May 2004 15:36:47 +0200 (CEST) helo Hes 250 izecom-martijn Hello Hes (192.168.0.1 [192.168.0.1] ) mail from: <hes@izecom.com> 250 Sender <hes@izecom.com> OK rcpt to: <hes@secure.izemail.com> 250 Recipient <hes@secure.izemail.com> OK data 354 Ok Send data ending with <CRLF>.<CRLF> [Break the connection here] Server side: 19/05/04 15:09:50 INFO smtpserver : Connection from 192.168.0.1 (192.168.0.1) 19/05/04 15:09:50 DEBUG smtpserver : Sent: 220 izecom-martijn SMTP Server (JAMES SMTP Server 2.2.0RC3) ready Wed, 19 May 2004 15:09:50 +0200 (CEST) 19/05/04 15:09:50 DEBUG smtpserver : Calling start() 19/05/04 15:09:50 DEBUG smtpserver : Command received: helo Hes 19/05/04 15:09:50 DEBUG smtpserver : Sent: 250 izecom-martijn Hello Hes (192.168.0.1 [192.168.0.1] ) 19/05/04 15:09:50 DEBUG smtpserver : Calling reset() for inactive watchdog 19/05/04 15:09:50 DEBUG smtpserver : Watchdog default Worker #13 has time to sleep 360000 19/05/04 15:10:04 DEBUG smtpserver : Command received: mail from: <hes@izecom.com> 19/05/04 15:10:04 DEBUG smtpserver : Sent: 250 Sender <hes@izecom.com> OK 19/05/04 15:10:04 DEBUG smtpserver : Calling reset() default Worker #13 19/05/04 15:10:18 DEBUG smtpserver : Command received: rcpt to: <hes@secure.izemail.com> 19/05/04 15:10:18 DEBUG smtpserver : Sent: 250 Recipient <hes@secure.izemail.com> OK 19/05/04 15:10:18 DEBUG smtpserver : Calling reset() default Worker #13 19/05/04 15:10:21 DEBUG smtpserver : Command received: data 19/05/04 15:10:21 DEBUG smtpserver : Sent: 354 Ok Send data ending with <CRLF>.<CRLF> 19/05/04 15:10:25 INFO smtpserver : Successfully spooled mail Mail1084972225857-1 from hes@izecom.com for [hes@secure.izemail.com] 19/05/04 15:10:25 DEBUG smtpserver : Sent: 250 Message received 19/05/04 15:10:25 DEBUG smtpserver : Calling reset() default Worker #13 19/05/04 15:10:25 DEBUG smtpserver : Calling stop() default Worker #13 19/05/04 15:10:25 DEBUG smtpserver : Closing socket. 19/05/04 15:10:25 DEBUG smtpserver : Calling disposeWatchdog() default Worker #13 19/05/04 15:10:25 DEBUG smtpserver : Returning SMTPHandler to pool. 19/05/04 15:10:25 DEBUG smtpserver : Returning a org.apache.james.smtpserver.SMTPHandler to the pool 19/05/04 15:10:25 DEBUG smtpserver : Watchdog default Worker #13 is exiting run(). 19/05/04 15:10:26 INFO James.Mailet : RemoteDelivery: Attempting delivery of Mail1084972225857-1 to host 192.168.0.18 at 192.168.0.18 to addresses [hes@exchange.izecom.com] No exception occurs, so the mail is processed. Since no data is specified, only a stub message is delivered. Other mail servers we tested (Exchange. Sendmail, Exim) do not process the message when presented with this data.
        Hide
        Noel J. Bergman added a comment -

        OK, this partial message problem is reproducible and comes from the fact that when the socket prematurely closes (as opposed to times out, which does generate an exception), the associated stream just returns -1 when asked for more data. This gets passed back through the chain until it reaches James, which couldn't tell the difference between the pre-mature end of stream and the legitimate end of the "Character Terminated" stream.

        A fix will be committed. This does not, however, explain the other error for which this issue was opened.

        Show
        Noel J. Bergman added a comment - OK, this partial message problem is reproducible and comes from the fact that when the socket prematurely closes (as opposed to times out, which does generate an exception), the associated stream just returns -1 when asked for more data. This gets passed back through the chain until it reaches James, which couldn't tell the difference between the pre-mature end of stream and the legitimate end of the "Character Terminated" stream. A fix will be committed. This does not, however, explain the other error for which this issue was opened.
        Hide
        Noel J. Bergman added a comment -

        Fixed.

        And Hes Siemelink reports that the initial problem reported in this issue appears to be related to sendmail disconnecting pre-maturely, although they aren't sure why.

        "What we finally figured out was that Sendmail tried to resolve the From: address as a sort of anti-spam measure. The DNS result was an error so I suppose Sendmail interrupted the connection. This caused the 'partial message delivery'."

        Show
        Noel J. Bergman added a comment - Fixed. And Hes Siemelink reports that the initial problem reported in this issue appears to be related to sendmail disconnecting pre-maturely, although they aren't sure why. "What we finally figured out was that Sendmail tried to resolve the From: address as a sort of anti-spam measure. The DNS result was an error so I suppose Sendmail interrupted the connection. This caused the 'partial message delivery'."

          People

          • Assignee:
            Noel J. Bergman
            Reporter:
            Hes Siemelink
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development