Apologies for replying to self, turns out the log lines are out of sync by a second so my greps weren't showing it up.
The MTA is indeeed showing "SMTP data timeout (message abandoned) on connection from" so I'll change my report. The connection is being opened to the MTA but it looks like ASSP is not passing the message to the MTA after scanning it and getting "message ok". The result is then either the MTA or ASSP timing out, I think the timeouts are set to the same so either one could kick in first - that explains difference between the last two logs. On 08/07/2014 15:50, Colin wrote: > Hi Folks, > > I've given up on the list accepting messages from my main account. SF > didn't respond to my request for help either. > > I have had an ongoing issue for a good few weeks now where its seems > like ASSP accepts a message but does not pass it on to the MTA. It > talks to the remote host and goes through the motions. There is no > evidence at all in the MTA logs that ASSP has even opened a connection > to it for the message concerned. When I originally spotted the > problem, ASSP didn't output anything for the message past "message ok". > > One of the recent revisions changed that and now ASSP reports a > timeout, but I have seen it reported in two different ways - logs below. > > Example 1 - no timeout reported by ASSP > > 2014-06-25 11:14:28 m1-91268-01851 [Worker_5] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld <mailto:sen...@domain.tld>> info: found > message size announcement: 13.54 kByte > > 2014-06-25 11:14:28 m1-91268-01851 [Worker_5] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld <mailto:sen...@domain.tld>> [SMTP Reply] 250 OK > > 2014-06-25 11:14:28 m1-91268-01851 [Worker_5] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> [SMTP Reply] 250 > Accepted > > 2014-06-25 11:14:28 m1-91268-01851 [Worker_5] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> [SMTP Reply] 354 > Enter message, ending with "." on a line by itself > > 2014-06-25 11:14:28 m1-91268-01851 [Worker_5] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> info: found known > good HELO 'mout1.freenet.de' - weight is -2 > > 2014-06-25 11:14:28 m1-91268-01851 [Worker_5] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> Message-Score: > added -40 for KnownGoodHelo, total score for this message is now -40 > > 2014-06-25 11:14:28 m1-91268-01851 [Worker_5] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> Message-Score: > added -15 (pbwValencePB) for In Penalty White Box, total score for > this message is now -55 > > 2014-06-25 11:14:28 m1-91268-01851 [Worker_5] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> Message-Score: > added -5 for 195.4.92 in griplist (0.00), total score for this message > is now -60 > > 2014-06-25 11:14:28 m1-91268-01851 [Worker_5] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> [scoring] SPF: none > ip=1.1.1.1 mailfrom=sen...@domain.tld > <mailto:mailfrom=sen...@domain.tld> helo=mout1.freenet.de > > 2014-06-25 11:14:28 m1-91268-01851 [Worker_5] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> Whitelisted sender > address: sen...@domain.tld <mailto:sen...@domain.tld> for recipient > recipi...@domain.tld <mailto:recipi...@domain.tld> > > 2014-06-25 11:14:29 m1-91268-01851 [Worker_5] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> [Plugin] calling > plugin ASSP_AFC > > 2014-06-25 11:14:29 m1-91268-01851 [Worker_5] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> whitelisted (no bad > attachments) > > 2014-06-25 11:14:29 m1-91268-01851 [Worker_5] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> [Plugin] calling > plugin ASSP_DCC > > 2014-06-25 11:14:29 m1-91268-01851 [Worker_5] [TLS-in] [TLS-out] > [MessageOK] 1.1.1.1 <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> message ok [Fwd Re > Test] > > > Example 2 - ASSP reported its own timeout > > 2014-06-30 17:42:49 m1-46569-09929 [Worker_4] [TLS-out] 1.1.1.1 > <sen...@domain.tld <mailto:sen...@domain.tld>> [SMTP Reply] 250 OK > > 2014-06-30 17:42:50 m1-46569-09929 [Worker_4] [TLS-out] 1.1.1.1 > <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> [SMTP Reply] 250 > Accepted > > 2014-06-30 17:42:50 m1-46569-09929 [Worker_4] [TLS-out] 1.1.1.1 > <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> [SMTP Reply] 354 > Enter message, ending with "." on a line by itself > > 2014-06-30 17:42:50 m1-46569-09929 [Worker_4] [TLS-out] 1.1.1.1 > <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> Whitelisted sender > address: sen...@domain.tld <mailto:sen...@domain.tld> for recipient > recipi...@domain.tld <mailto:recipi...@domain.tld> > > 2014-06-30 17:42:50 m1-46569-09929 [Worker_4] [TLS-out] 1.1.1.1 > <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> [Plugin] calling > plugin ASSP_AFC > > 2014-06-30 17:42:50 m1-46569-09929 [Worker_4] [TLS-out] 1.1.1.1 > <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> whitelisted (no bad > attachments) > > 2014-06-30 17:42:50 m1-46569-09929 [Worker_4] [TLS-out] [MessageOK] > 1.1.1.1 <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> message ok [SUBJECT] > > 2014-06-30 18:03:04 m1-46569-09929 [Worker_4] [TLS-out] 1.1.1.1 > <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> Connection idle for > 360 secs - timeout > > 2014-06-30 18:03:04 m1-46569-09929 [Worker_4] [TLS-out] 1.1.1.1 > <sen...@domain.tld <mailto:sen...@domain.tld>> to: > recipi...@domain.tld <mailto:recipi...@domain.tld> [SMTP Status] 451 > Connection timeout, try later > > > Example 3 - ASSP claims the MTA reports a timeout yet there is not a > single log from the MTA indicating this. > > 2014-07-08 13:30:31 m1-22631-13843 [Worker_7] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld> info: found message size announcement: > 5.53 kByte > > 2014-07-08 13:30:33 m1-22631-13843 [Worker_7] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld> [SMTP Reply] 250 OK > > 2014-07-08 13:30:35 m1-22631-13843 [Worker_7] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld> to: recipi...@domain.tld [SMTP Reply] 250 > Accepted > > 2014-07-08 13:30:39 m1-22631-13843 [Worker_7] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld> to: recipi...@domain.tld [SMTP Reply] 354 > Enter message, ending with "." on a line by itself > > 2014-07-08 13:30:40 m1-22631-13843 [Worker_7] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld> to: recipi...@domain.tld Whitelisted > sender address: sen...@domain.tld for recipient recipi...@domain.tld > > 2014-07-08 13:30:40 m1-22631-13843 [Worker_7] [TLS-in] [TLS-out] > [Noprocessing] 1.1.1.1 <sen...@domain.tld> to: recipi...@domain.tld > info: found valid MSGID signature in [References:] - accept mail > > 2014-07-08 13:30:40 m1-22631-13843 [Worker_7] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld> to: recipi...@domain.tld DKIM-Signature found > > 2014-07-08 13:30:42 m1-22631-13843 [Worker_7] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld> to: recipi...@domain.tld info: removed > MSGID-signature from [References:] > > 2014-07-08 13:30:42 m1-22631-13843 [Worker_7] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld> to: recipi...@domain.tld info: removed > MSGID-signature from [In-Reply-To:] > > 2014-07-08 13:30:42 m1-22631-13843 [Worker_7] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld> to: recipi...@domain.tld info: removed > MSGID-signature from header > > 2014-07-08 13:30:42 m1-22631-13843 [Worker_7] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld> to: recipi...@domain.tld [Plugin] calling > plugin ASSP_AFC > > 2014-07-08 13:30:42 m1-22631-13843 [Worker_7] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld> to: recipi...@domain.tld message proxied > without processing (no bad attachments) > > 2014-07-08 13:30:42 m1-22631-13843 [Worker_7] [TLS-in] [TLS-out] > [MessageOK] 1.1.1.1 <sen...@domain.tld> to: recipi...@domain.tld > message ok - (noprocessing and whitelisted - found valid Message-ID > signature) - [URGENT NEW BOOKING] > > 2014-07-08 13:37:24 m1-22631-13843 [Worker_7] [TLS-in] [TLS-out] > [MessageOK] 1.1.1.1 <sen...@domain.tld> to: recipi...@domain.tld info: > got reply '421 mail.smtphost.co.uk SMTP incoming data timeout - > closing connection.' - message is rejeted by the server host 127.0.0.1 > > 2014-07-08 13:37:24 m1-22631-13843 [Worker_7] [TLS-in] [TLS-out] > 1.1.1.1 <sen...@domain.tld> to: recipi...@domain.tld [SMTP Status] 421 > mail.smtphost.co.uk SMTP incoming data timeout - closing connection. > > 2014-07-08 13:37:27 [Worker_7] Disconnected: session:7FD282862A58 > 1.1.1.1 - processing time 421 seconds > > > ------------------------------------------------------------------------------ Open source business process management suite built on Java and Eclipse Turn processes into business applications with Bonita BPM Community Edition Quickly connect people, data, and systems into organized workflows Winner of BOSSIE, CODIE, OW2 and Gartner awards http://p.sf.net/sfu/Bonitasoft _______________________________________________ Assp-test mailing list Assp-test@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/assp-test
