Hi Thomas, I think my logs are getting confused - having the MTA only accept 1 message per connection is causing ASSP to write debug logs for the ones it doesn't accept. Oddly, ASSP still accepts the message from the remote sender when the MTA has rejected the message at the MAIL FROM: stage as the debug file shows both complete messages.
I will remove the MTA restriction, empty the debug folder and restart ASSP to make sure only fresh connections get written to the debug folder before sending anything over. Thanks for the help, Colin. On 09/07/2014 11:14, Thomas Eckardt wrote: >> 2014-07-09 10:47:23 server unpoll from main sub main::ThreadMain 165 > This signals that assp has written all received data to the MTA's > connection. Please could you anyhow check, if the trailing "CRLF.CRLF" was > sent to the MTA in DATA part of the mail - or better first, if the client > has sent the "CRLF.CRLF" (should be in the logged .eml file). > > Thomas > > > > > > Von: Colin <colin.war...@gmail.com> > An: assp-test@lists.sourceforge.net > Datum: 09.07.2014 12:02 > Betreff: Re: [Assp-test] Timeout issues > > > > Hi Thomas, > > Further to this I set a 1 message limit on the MTA. The number of > affected connections seems to have reduced but I am still seeing > timeouts being logged on individual messages. The only extra thing the > full connection debug shows after the end of receiving the data is > server unpoll. > > 2014-07-09 10:47:23 server unpoll from main sub main::ThreadMain 165 > 2014-07-09 10:53:24 client Timeout after 360 secs^M > 2014-07-09 10:53:24 client was readable^M > 2014-07-09 10:53:24 client was not writable^M > > All the best, > Colin Waring. > > On 09/07/2014 10:21, Thomas Eckardt wrote: >> enable 'ConTimeOutDebug' >> >> assp will write the connection states in to files in the debug folder. >> >> Thomas >> >> >> >> >> >> Von: Colin <colin.war...@gmail.com> >> An: Assp-test@lists.sourceforge.net >> Datum: 08.07.2014 17:04 >> Betreff: Re: [Assp-test] Timeout issues >> >> >> >> 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 >> >> >> >> >> DISCLAIMER: >> ******************************************************* >> This email and any files transmitted with it may be confidential, > legally >> privileged and protected in law and are intended solely for the use of > the >> individual to whom it is addressed. >> This email was multiple times scanned for viruses. There should be no >> known virus in this email! >> ******************************************************* >> >> >> >> >> > ------------------------------------------------------------------------------ >> 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 > > ------------------------------------------------------------------------------ > 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 > > > > > DISCLAIMER: > ******************************************************* > This email and any files transmitted with it may be confidential, legally > privileged and protected in law and are intended solely for the use of the > > individual to whom it is addressed. > This email was multiple times scanned for viruses. There should be no > known virus in this email! > ******************************************************* > > > > > ------------------------------------------------------------------------------ > 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 ------------------------------------------------------------------------------ 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
