[JAMES-1627] Delay in processing mail

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 3.0.0-beta5
• Component/s: SMTPServer
• Environment: Red Hat Enterprise Linux Server release 5.5
• Assignee: Unassigned
• Reporter: Soprano Support
• Created: 25/Oct/15 23:04
• Updated: 25/Oct/15 23:43

Description

Hello,
We would like to ask for your kind input on mail processing delays that we are experiencing with james 3.0-beta5.

The delay occurs occasionally, roughly 1-5 time per day. The delay is generally between 3-8 seconds during client connect and disconnect.

Log with debug info:

INFO 01:06:04,881 | james.smtpserver | Id='10009693' User='' Connection established from 203.22.201.1
DEBUG 01:06:04,939 | james.smtpserver | Id='10009693' User='' org.apache.james.protocols.api.handler.CommandDispatcher received: EHLO
DEBUG 01:06:04,940 | james.smtpserver | Id='10009693' User='' Lookup command handler for command: EHLO
DEBUG 01:06:04,940 | james.smtpserver | Id='10009693' User='' org.apache.james.protocols.smtp.core.esmtp.EhloCmdHandler: [250-tim2.tim.telstra.com Hello HQOVCADPRD01 [203.22.201.1]), 250-PIPELINING, 250-ENHANCEDSTATUSCODES, 250-8BITMIME, 250 STARTTLS]
DEBUG 01:06:04,998 | james.smtpserver | Id='10009693' User='' org.apache.james.protocols.api.handler.CommandDispatcher received: MAIL
DEBUG 01:06:04,998 | james.smtpserver | Id='10009693' User='' Lookup command handler for command: MAIL
DEBUG 01:06:04,998 | james.smtpserver | Id='10009693' User='' org.apache.james.smtpserver.JamesMailCmdHandler: [250 2.1.0 Sender <[e-mail]> OK]
DEBUG 01:06:05,056 | james.smtpserver | Id='10009693' User='' org.apache.james.protocols.api.handler.CommandDispatcher received: RCPT
DEBUG 01:06:05,056 | james.smtpserver | Id='10009693' User='' Lookup command handler for command: RCPT
DEBUG 01:06:05,056 | james.smtpserver | Id='10009693' User='' executing hook org.apache.james.smtpserver.AuthRequiredToRelayRcptHook
DEBUG 01:06:05,056 | james.smtpserver | Id='10009693' User='' executing hook org.apache.james.protocols.smtp.core.log.HookResultLogger@154d4f9
DEBUG 01:06:05,056 | james.smtpserver | Id='10009693' User='' org.apache.james.smtpserver.AuthRequiredToRelayRcptHook: result=8 (DECLINED)
DEBUG 01:06:05,056 | james.smtpserver | Id='10009693' User='' executing hook org.apache.james.smtpserver.jmx.HookResultJMXMonitor@6a2a2b
DEBUG 01:06:05,056 | james.smtpserver | Id='10009693' User='' executing hook org.apache.james.smtpserver.SenderAuthIdentifyVerificationRcptHook
DEBUG 01:06:05,057 | james.smtpserver | Id='10009693' User='' executing hook org.apache.james.protocols.smtp.core.log.HookResultLogger@154d4f9
DEBUG 01:06:05,057 | james.smtpserver | Id='10009693' User='' org.apache.james.smtpserver.SenderAuthIdentifyVerificationRcptHook: result=8 (DECLINED)
DEBUG 01:06:05,057 | james.smtpserver | Id='10009693' User='' executing hook org.apache.james.smtpserver.jmx.HookResultJMXMonitor@6a2a2b
DEBUG 01:06:05,057 | james.smtpserver | Id='10009693' User='' executing hook org.apache.james.protocols.smtp.core.PostmasterAbuseRcptHook
DEBUG 01:06:05,057 | james.smtpserver | Id='10009693' User='' executing hook org.apache.james.protocols.smtp.core.log.HookResultLogger@154d4f9
DEBUG 01:06:05,057 | james.smtpserver | Id='10009693' User='' org.apache.james.protocols.smtp.core.PostmasterAbuseRcptHook: result=8 (DECLINED)
DEBUG 01:06:05,057 | james.smtpserver | Id='10009693' User='' executing hook org.apache.james.smtpserver.jmx.HookResultJMXMonitor@6a2a2b
DEBUG 01:06:05,057 | james.smtpserver | Id='10009693' User='' org.apache.james.smtpserver.JamesRcptCmdHandler: [250 2.1.5 Recipient <[e-mail]> OK]
DEBUG 01:06:05,115 | james.smtpserver | Id='10009693' User='' org.apache.james.protocols.api.handler.CommandDispatcher received: DATA
DEBUG 01:06:05,115 | james.smtpserver | Id='10009693' User='' Lookup command handler for command: DATA
DEBUG 01:06:05,115 | james.smtpserver | Id='10009693' User='' org.apache.james.smtpserver.JamesDataCmdHandler: [354 Ok Send data ending with <CRLF>.<CRLF>]
DEBUG 01:06:13,233 | james.smtpserver | Id='10009693' User='' executing james message handler org.apache.james.protocols.smtp.core.esmtp.MailSizeEsmtpExtension@550344
DEBUG 01:06:13,233 | james.smtpserver | Id='10009693' User='' executing hook org.apache.james.protocols.smtp.core.log.HookResultLogger@154d4f9
DEBUG 01:06:13,233 | james.smtpserver | Id='10009693' User='' org.apache.james.protocols.smtp.core.esmtp.MailSizeEsmtpExtension: result=8 (DECLINED)
DEBUG 01:06:13,233 | james.smtpserver | Id='10009693' User='' executing hook org.apache.james.smtpserver.jmx.HookResultJMXMonitor@6a2a2b
DEBUG 01:06:13,233 | james.smtpserver | Id='10009693' User='' executing james message handler org.apache.james.smtpserver.AddDefaultAttributesMessageHook@798781
DEBUG 01:06:13,233 | james.smtpserver | Id='10009693' User='' executing hook org.apache.james.protocols.smtp.core.log.HookResultLogger@154d4f9
DEBUG 01:06:13,233 | james.smtpserver | Id='10009693' User='' org.apache.james.smtpserver.AddDefaultAttributesMessageHook: result=8 (DECLINED)
DEBUG 01:06:13,233 | james.smtpserver | Id='10009693' User='' executing hook org.apache.james.smtpserver.jmx.HookResultJMXMonitor@6a2a2b
DEBUG 01:06:13,233 | james.smtpserver | Id='10009693' User='' executing james message handler org.apache.james.smtpserver.SendMailHandler@af3cf6
DEBUG 01:06:13,233 | james.smtpserver | Id='10009693' User='' sending mail
INFO 01:06:13,235 | james.smtpserver | Id='10009693' User='' Successfully spooled mail Mail1444917973232-d3d653d9-692a-49d6-a0fe-35ac5c7f1276 from [e-mail] on 203.22.201.1/203.22.201.1 for [[e-mail]]
DEBUG 01:06:13,235 | james.smtpserver | Id='10009693' User='' executing hook org.apache.james.protocols.smtp.core.log.HookResultLogger@154d4f9
DEBUG 01:06:13,235 | james.smtpserver | Id='10009693' User='' org.apache.james.smtpserver.SendMailHandler: result=1 (OK)
DEBUG 01:06:13,235 | james.smtpserver | Id='10009693' User='' executing hook org.apache.james.smtpserver.jmx.HookResultJMXMonitor@6a2a2b
DEBUG 01:06:13,293 | james.smtpserver | Id='10009693' User='' org.apache.james.protocols.api.handler.CommandDispatcher received: QUIT
DEBUG 01:06:13,293 | james.smtpserver | Id='10009693' User='' Lookup command handler for command: QUIT
DEBUG 01:06:13,294 | james.smtpserver | Id='10009693' User='' org.apache.james.protocols.smtp.core.QuitCmdHandler: [221 2.0.0 tim2.tim.telstra.com Service closing transmission channel]
INFO 01:06:13,294 | james.smtpserver | Id='10009693' User='' Connection closed for 203.22.201.1

From the log above we notice an approximately 8sec delay,
DEBUG 01:06:05,115 | james.smtpserver | Id='10009693' User='' org.apache.james.smtpserver.JamesDataCmdHandler: [354 Ok Send data ending with <CRLF>.<CRLF>]
DEBUG 01:06:13,233 | james.smtpserver | Id='10009693' User='' executing james message handler

Could this be network related or a bug? Please help us understand.

Kind regards,
Ali Hussain
Email: [e-mail]
Phone: [phone]
Soprano Support, Sydney, Australia.