[JAMES-1251] Problem sending to second MX Host

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 3.0-beta3
• Fix Version/s: 3.0-beta3
• Component/s: SMTPServer
• Environment: Linux OpenSuse 11.2
• Assignee: Norman Maurer
• Reporter: Nicola Salvemini
• Created: 18/May/11 09:35
• Updated: 18/Jul/11 19:43
• Resolved: 22/Jun/11 07:09

Description

Hello!

I have problems sending email with James 3.0-M3.
Suppose to send an email to [e-mail] 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:<[e-mail]>
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 <[e-mail]> 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:<[e-mail]>
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 <[e-mail]> 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 [e-mail] on 127.0.0.1 for [[e-mail]]
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 [e-mail] for addresses [[e-mail]]
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 [e-mail] for addresses [[e-mail]]
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 [e-mail] for addresses [[e-mail]]
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 [e-mail] for addresses [[e-mail]]