Problem sending to second MX Host
---------------------------------
Key: JAMES-1251
URL: https://issues.apache.org/jira/browse/JAMES-1251
Project: JAMES Server
Issue Type: Bug
Components: SMTPServer
Affects Versions: 3.0-M3
Environment: Linux OpenSuse 11.2
Reporter: Nicola Salvemini
Hello!
I have problems sending email with James 3.0-M3.
Suppose to send an email to [email protected] 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:<[email protected]>
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
<[email protected]> 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:<[email protected]>
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
<[email protected]> 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
[email protected] on 127.0.0.1 for [[email protected]]
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 [email protected] for addresses
[[email protected]]
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 [email protected] for addresses
[[email protected]]
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 [email protected] for addresses
[[email protected]]
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 [email protected] for addresses
[[email protected]]
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
