Uploaded image for project: 'James Server'
  1. James Server
  2. JAMES-1251

Problem sending to second MX Host

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 3.0-beta3
    • Fix Version/s: 3.0-beta3
    • Component/s: SMTPServer
    • Labels:
      None
    • Environment:
      Linux OpenSuse 11.2

      Description

      Hello!

      I have problems sending email with James 3.0-M3.
      Suppose to send an email to destination@testdomain.com and suppose
      testdomain.com domain has two mx record: mx1.tesdomain.com
      (192.168.1.1) and mx2.testdomain.com (192.168.1.2).
      If, for any reason, the destination SMTP server mx1.tesdomain.com is
      down, James does not retry to send on mx2.testdomain.com.
      As normal behavior I would expect that James tried to send on
      mx2.testdomain.com but instead, sending the next runs again on
      mx1.testdomain.com.

      Regards,

      Nicola.

      INFO 09:31:56,578 | james.smtpserver | ID=468922697 Connection established from localhost (127.0.0.1)
      DEBUG 09:31:56,579 | james.smtpserver | ID=468922697 org.apache.james.smtpserver.JamesWelcomeMessageHandler disconnect=false
      DEBUG 09:32:04,761 | james.smtpserver | ID=468922697 org.apache.james.protocols.smtp.core.SMTPCommandDispatcherLineHandler received: helo test
      DEBUG 09:32:04,761 | james.smtpserver | ID=468922697 Lookup command handler for command: HELO
      DEBUG 09:32:04,761 | james.smtpserver | ID=468922697 org.apache.james.protocols.smtp.core.HeloCmdHandler: 250 [localhost. Hello test (localhost [127.0.0.1])]
      DEBUG 09:32:04,762 | james.smtpserver | ID=468922697 org.apache.james.protocols.smtp.core.SMTPCommandDispatcherLineHandler disconnect=false
      DEBUG 09:32:18,984 | james.smtpserver | ID=468922697 org.apache.james.protocols.smtp.core.SMTPCommandDispatcherLineHandler received: mail from:<test@tester.local.com>
      DEBUG 09:32:18,984 | james.smtpserver | ID=468922697 Lookup command handler for command: MAIL
      DEBUG 09:32:18,984 | james.smtpserver | ID=468922697 org.apache.james.smtpserver.JamesMailCmdHandler: 250 [2.1.0 Sender <test@tester.local.com> OK]
      DEBUG 09:32:18,985 | james.smtpserver | ID=468922697 org.apache.james.protocols.smtp.core.SMTPCommandDispatcherLineHandler disconnect=false
      DEBUG 09:32:43,287 | james.smtpserver | ID=468922697 org.apache.james.protocols.smtp.core.SMTPCommandDispatcherLineHandler received: rcpt to:<destination@testdomain.com>
      DEBUG 09:32:43,287 | james.smtpserver | ID=468922697 Lookup command handler for command: RCPT
      DEBUG 09:32:43,287 | james.smtpserver | ID=468922697 executing hook org.apache.james.smtpserver.fastfail.ValidRcptHandler
      DEBUG 09:32:43,291 | james.smtpserver | ID=468922697 executing hook org.apache.james.protocols.smtp.core.log.HookResultLogger@2ae61f87
      DEBUG 09:32:43,291 | james.smtpserver | ID=468922697 org.apache.james.smtpserver.fastfail.ValidRcptHandler: result=8 (DECLINED)
      DEBUG 09:32:43,291 | james.smtpserver | ID=468922697 executing hook org.apache.james.smtpserver.jmx.HookResultJMXMonitor@6a1fee11
      DEBUG 09:32:43,291 | james.smtpserver | ID=468922697 executing hook org.apache.james.smtpserver.AuthRequiredToRelayRcptHook
      DEBUG 09:32:43,292 | james.smtpserver | ID=468922697 executing hook org.apache.james.protocols.smtp.core.log.HookResultLogger@2ae61f87
      DEBUG 09:32:43,292 | james.smtpserver | ID=468922697 org.apache.james.smtpserver.AuthRequiredToRelayRcptHook: result=8 (DECLINED)
      DEBUG 09:32:43,292 | james.smtpserver | ID=468922697 executing hook org.apache.james.smtpserver.jmx.HookResultJMXMonitor@6a1fee11
      DEBUG 09:32:43,292 | james.smtpserver | ID=468922697 executing hook org.apache.james.smtpserver.SenderAuthIdentifyVerificationRcptHook
      DEBUG 09:32:43,292 | james.smtpserver | ID=468922697 executing hook org.apache.james.protocols.smtp.core.log.HookResultLogger@2ae61f87
      DEBUG 09:32:43,293 | james.smtpserver | ID=468922697 org.apache.james.smtpserver.SenderAuthIdentifyVerificationRcptHook: result=8 (DECLINED)
      DEBUG 09:32:43,293 | james.smtpserver | ID=468922697 executing hook org.apache.james.smtpserver.jmx.HookResultJMXMonitor@6a1fee11
      DEBUG 09:32:43,293 | james.smtpserver | ID=468922697 executing hook org.apache.james.protocols.smtp.core.PostmasterAbuseRcptHook
      DEBUG 09:32:43,293 | james.smtpserver | ID=468922697 executing hook org.apache.james.protocols.smtp.core.log.HookResultLogger@2ae61f87
      DEBUG 09:32:43,294 | james.smtpserver | ID=468922697 org.apache.james.protocols.smtp.core.PostmasterAbuseRcptHook: result=8 (DECLINED)
      DEBUG 09:32:43,294 | james.smtpserver | ID=468922697 executing hook org.apache.james.smtpserver.jmx.HookResultJMXMonitor@6a1fee11
      DEBUG 09:32:43,294 | james.smtpserver | ID=468922697 org.apache.james.smtpserver.JamesRcptCmdHandler: 250 [2.1.5 Recipient <destination@testdomain.com> OK]
      DEBUG 09:32:43,295 | james.smtpserver | ID=468922697 org.apache.james.protocols.smtp.core.SMTPCommandDispatcherLineHandler disconnect=false
      DEBUG 09:32:46,231 | james.smtpserver | ID=468922697 org.apache.james.protocols.smtp.core.SMTPCommandDispatcherLineHandler received: Data
      DEBUG 09:32:46,231 | james.smtpserver | ID=468922697 Lookup command handler for command: DATA
      DEBUG 09:32:46,232 | james.smtpserver | ID=468922697 org.apache.james.smtpserver.JamesDataCmdHandler: 354 [Ok Send data ending with <CRLF>.<CRLF>]
      DEBUG 09:32:46,233 | james.smtpserver | ID=468922697 org.apache.james.protocols.smtp.core.SMTPCommandDispatcherLineHandler disconnect=false
      DEBUG 09:32:56,470 | james.smtpserver | ID=468922697 executing james message handler org.apache.james.protocols.smtp.core.esmtp.MailSizeEsmtpExtension@7cb523dc
      DEBUG 09:32:56,470 | james.smtpserver | ID=468922697 executing hook org.apache.james.protocols.smtp.core.log.HookResultLogger@2ae61f87
      DEBUG 09:32:56,470 | james.smtpserver | ID=468922697 org.apache.james.protocols.smtp.core.esmtp.MailSizeEsmtpExtension: result=8 (DECLINED)
      DEBUG 09:32:56,471 | james.smtpserver | ID=468922697 executing hook org.apache.james.smtpserver.jmx.HookResultJMXMonitor@6a1fee11
      DEBUG 09:32:56,471 | james.smtpserver | ID=468922697 executing james message handler org.apache.james.smtpserver.AddDefaultAttributesMessageHook@3af5f6dc
      DEBUG 09:32:56,471 | james.smtpserver | ID=468922697 executing hook org.apache.james.protocols.smtp.core.log.HookResultLogger@2ae61f87
      DEBUG 09:32:56,471 | james.smtpserver | ID=468922697 org.apache.james.smtpserver.AddDefaultAttributesMessageHook: result=8 (DECLINED)
      DEBUG 09:32:56,471 | james.smtpserver | ID=468922697 executing hook org.apache.james.smtpserver.jmx.HookResultJMXMonitor@6a1fee11
      DEBUG 09:32:56,472 | james.smtpserver | ID=468922697 executing james message handler org.apache.james.smtpserver.SendMailHandler@6a2203c1
      DEBUG 09:32:56,472 | james.smtpserver | ID=468922697 sending mail
      INFO 09:32:56,491 | james.smtpserver | ID=468922697 Successfully spooled mail Mail1305703976470-c7e398f1-e355-4b6a-895c-4991f2ac628e from test@tester.local.com on 127.0.0.1 for [destination@testdomain.com]
      DEBUG 09:32:56,492 | james.smtpserver | ID=468922697 executing hook org.apache.james.protocols.smtp.core.log.HookResultLogger@2ae61f87
      DEBUG 09:32:56,492 | james.smtpserver | ID=468922697 org.apache.james.smtpserver.SendMailHandler: result=1 (OK)
      DEBUG 09:32:56,493 | james.smtpserver | ID=468922697 executing hook org.apache.james.smtpserver.jmx.HookResultJMXMonitor@6a1fee11
      DEBUG 09:32:56,494 | james.mailspooler | ==== Begin processing mail Mail1305703976470-c7e398f1-e355-4b6a-895c-4991f2ac628e====
      DEBUG 09:32:56,494 | james.mailprocessor | Call MailProcessor root
      DEBUG 09:32:56,502 | james.mailprocessor | Call MailProcessor transport
      DEBUG 09:32:56,518 | james.mailprocessor | End of mailetprocessor for state root reached
      DEBUG 09:32:56,525 | james.dnsservice | Found MX record mx1.tesdomain.com.
      DEBUG 09:32:56,526 | james.dnsservice | Found MX record mx2.tesdomain.com.
      INFO 09:32:56,578 | james.mailetcontext | Attempting delivery of Mail1305703976470-c7e398f1-e355-4b6a-895c-4991f2ac628e-to-mailtrend.net to host mx1.tesdomain.com. at 192.168.1.1 from test@tester.local.com for addresses [destination@testdomain.com]
      DEBUG 09:33:03,222 | james.smtpserver | ID=468922697 org.apache.james.protocols.smtp.core.SMTPCommandDispatcherLineHandler received: quit
      DEBUG 09:33:03,222 | james.smtpserver | ID=468922697 Lookup command handler for command: QUIT
      DEBUG 09:33:03,222 | james.smtpserver | ID=468922697 org.apache.james.protocols.smtp.core.QuitCmdHandler: 221 [2.0.0 localhost. Service closing transmission channel]
      INFO 09:33:03,224 | james.smtpserver | ID=468922697 Connection closed for localhost (127.0.0.1)
      DEBUG 09:33:03,224 | james.smtpserver | ID=468922697 org.apache.james.protocols.smtp.core.SMTPCommandDispatcherLineHandler disconnect=false
      INFO 09:33:56,608 | james.mailetcontext | Could not connect to SMTP host: 192.168.1.1, port: 25
      INFO 09:33:56,608 | james.mailetcontext | Temporary exception delivering mail (Mail1305703976470-c7e398f1-e355-4b6a-895c-4991f2ac628e-to-mailtrend.net:
      INFO 09:33:56,609 | james.mailetcontext | Storing message Mail1305703976470-c7e398f1-e355-4b6a-895c-4991f2ac628e-to-mailtrend.net into outgoing after 0 retries
      DEBUG 09:38:56,743 | james.dnsservice | Found MX record mx1.tesdomain.com.
      DEBUG 09:38:56,744 | james.dnsservice | Found MX record mx2.tesdomain.com.
      INFO 09:38:56,886 | james.mailetcontext | Attempting delivery of Mail1305703976470-c7e398f1-e355-4b6a-895c-4991f2ac628e-to-mailtrend.net to host mx1.tesdomain.com. at 192.168.1.1 from test@tester.local.com for addresses [destination@testdomain.com]
      INFO 09:39:56,947 | james.mailetcontext | Could not connect to SMTP host: 192.168.1.1, port: 25
      INFO 09:39:56,947 | james.mailetcontext | Temporary exception delivering mail (Mail1305703976470-c7e398f1-e355-4b6a-895c-4991f2ac628e-to-mailtrend.net:
      INFO 09:39:56,947 | james.mailetcontext | Storing message Mail1305703976470-c7e398f1-e355-4b6a-895c-4991f2ac628e-to-mailtrend.net into outgoing after 1 retries
      DEBUG 09:44:57,027 | james.dnsservice | Found MX record mx1.tesdomain.com.
      DEBUG 09:44:57,027 | james.dnsservice | Found MX record mx2.tesdomain.com.
      INFO 09:44:57,217 | james.mailetcontext | Attempting delivery of Mail1305703976470-c7e398f1-e355-4b6a-895c-4991f2ac628e-to-mailtrend.net to host mx1.tesdomain.com. at 192.168.1.1 from test@tester.local.com for addresses [destination@testdomain.com]
      INFO 09:45:57,254 | james.mailetcontext | Could not connect to SMTP host: 192.168.1.1, port: 25
      INFO 09:45:57,255 | james.mailetcontext | Temporary exception delivering mail (Mail1305703976470-c7e398f1-e355-4b6a-895c-4991f2ac628e-to-mailtrend.net:
      INFO 09:45:57,255 | james.mailetcontext | Storing message Mail1305703976470-c7e398f1-e355-4b6a-895c-4991f2ac628e-to-mailtrend.net into outgoing after 2 retries
      DEBUG 09:50:57,392 | james.dnsservice | Found MX record mx1.tesdomain.com.
      DEBUG 09:50:57,393 | james.dnsservice | Found MX record mx2.tesdomain.com.
      INFO 09:50:57,538 | james.mailetcontext | Attempting delivery of Mail1305703976470-c7e398f1-e355-4b6a-895c-4991f2ac628e-to-mailtrend.net to host mx1.tesdomain.com. at 192.168.1.1 from test@tester.local.com for addresses [destination@testdomain.com]

        Attachments

          Activity

            People

            • Assignee:
              norman Norman Maurer
              Reporter:
              nicolasalvemini Nicola Salvemini
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: