Re: [mailer-dae...@doctor.nl2k.ab.ca: Postfix SMTP server: errors from defout.telus.net[204.209.205.55]]
On Sat, Apr 24, 2010 at 06:36:48PM -0400, Wietse Venema wrote: > Here is my reconstruction from this inadequate logging sample. > > > Apr 24 13:20:10 doctor doctor[31]: postfix/smtpd[17053]: 0762D12CFB0D: > > client=defout.telus.net[204.209.205.55] > > Apr 24 13:20:41 doctor doctor[31]: postfix/cleanup[17311]: 0762D12CFB0D: > > message-id=<6ef179d262924e5a8c03336971544...@taskercomp> > > At 13:22:00, a different Postfix SMTPD process reports a queue file > write error. This Postfix SMTPD process is missing from the logfile. > Also missing is the logging for the postmaster notice delivery. > > > Apr 24 13:22:04 doctor doctor[31]: postfix/qmgr[4921]: 0762D12CFB0D: > > from=, size=5104017, nrcpt=1 (queue active) > > Apr 24 13:22:04 doctor clamsmtpd: 100B1C: from=sender, to=recipient, > > status=CLEAN > > The logging shows a clamsmtpd filter, but the logging is missing > for the process that sends the message into the clamsmtpd filter. > > Let's assume that this missing process was the same missing Postfix > SMTPD process that reported a queue file write error. That is > admittedly optimistic, considering that you left out most of the > relevant information. > > Then, we have the following timeline: > > 13:20:10 The missing Postfix SMTPD process receives a connection. > > 13:20:10 The missing Postfix SMTPD process connects to a before-queue > filter (clamsmtpd). > > 13:20:10 The before-queue filter (clamsmtpd) connects to Postfix > SMTPD process 17053. > > 13:20:41 The before-queue filter (clamsmtpd) sends the message > header and perhaps the first part of the message body. > > 13:22:00 The missing Postfix SMTPD process times out (smtpd_proxy_timeout) > and sends a postmaster notification. I already mentioned > that the postmaster notification is missing in the logging. > > 13:22:04 The before-queue filter (clamsmtpd) finishes after two > and a half minute. This is long after the missing Postfix > SMTPD process has given up. > > If this timeline is correct then you have too many body_checks > rules, or you have a clamsmtpd setup that is taking too much time. > > But it is more likely that you left out a whole lot of other > relevant information with your selective logfile reporting. > > Wietse Let me see if I can find the thorough transaction. I have amavisd-ng on 10024 and clamsmtpd on 10125. Problem is that this is not the only piece of e-mail being inspected at that time frame. -- Member - Liberal International This is doc...@nl2k.ab.ca Ici doc...@nl2k.ab.ca God, Queen and country! Never Satan President Republic! Beware AntiChrist rising! http://twitter.com/rootnl2k http://www.facebook.com/dyadallee UK Time for a Common Sense change vote Liberal Democrat / Alliance
Re: [mailer-dae...@doctor.nl2k.ab.ca: Postfix SMTP server: errors from defout.telus.net[204.209.205.55]]
Here is my reconstruction from this inadequate logging sample. > Apr 24 13:20:10 doctor doctor[31]: postfix/smtpd[17053]: 0762D12CFB0D: > client=defout.telus.net[204.209.205.55] > Apr 24 13:20:41 doctor doctor[31]: postfix/cleanup[17311]: 0762D12CFB0D: > message-id=<6ef179d262924e5a8c03336971544...@taskercomp> At 13:22:00, a different Postfix SMTPD process reports a queue file write error. This Postfix SMTPD process is missing from the logfile. Also missing is the logging for the postmaster notice delivery. > Apr 24 13:22:04 doctor doctor[31]: postfix/qmgr[4921]: 0762D12CFB0D: > from=, size=5104017, nrcpt=1 (queue active) > Apr 24 13:22:04 doctor clamsmtpd: 100B1C: from=sender, to=recipient, > status=CLEAN The logging shows a clamsmtpd filter, but the logging is missing for the process that sends the message into the clamsmtpd filter. Let's assume that this missing process was the same missing Postfix SMTPD process that reported a queue file write error. That is admittedly optimistic, considering that you left out most of the relevant information. Then, we have the following timeline: 13:20:10 The missing Postfix SMTPD process receives a connection. 13:20:10 The missing Postfix SMTPD process connects to a before-queue filter (clamsmtpd). 13:20:10 The before-queue filter (clamsmtpd) connects to Postfix SMTPD process 17053. 13:20:41 The before-queue filter (clamsmtpd) sends the message header and perhaps the first part of the message body. 13:22:00 The missing Postfix SMTPD process times out (smtpd_proxy_timeout) and sends a postmaster notification. I already mentioned that the postmaster notification is missing in the logging. 13:22:04 The before-queue filter (clamsmtpd) finishes after two and a half minute. This is long after the missing Postfix SMTPD process has given up. If this timeline is correct then you have too many body_checks rules, or you have a clamsmtpd setup that is taking too much time. But it is more likely that you left out a whole lot of other relevant information with your selective logfile reporting. Wietse
Re: [mailer-dae...@doctor.nl2k.ab.ca: Postfix SMTP server: errors from defout.telus.net[204.209.205.55]]
The Doctor: > > Apr 24 13:20:10 doctor doctor[31]: postfix/smtpd[17053]: 0762D12CFB0D: > client=defout.telus.net[204.209.205.55] > Apr 24 13:20:41 doctor doctor[31]: postfix/cleanup[17311]: 0762D12CFB0D: > message-id=<6ef179d262924e5a8c03336971544...@taskercomp> > Apr 24 13:22:04 doctor doctor[31]: postfix/qmgr[4921]: 0762D12CFB0D: > from=, size=5104017, nrcpt=1 (queue active) > Apr 24 13:22:04 doctor clamsmtpd: 100B1C: from=sender, to=recipient, > status=CLEAN > Apr 24 13:22:07 doctor postfix/pipe[17941]: 0762D12CFB0D: to=, > orig_to=, relay=spamchk, delay=117, delays=115/0/0/2.9, dsn=2.0.0, > status=sent (delivered via spamchk service) > Apr 24 13:22:07 doctor doctor[31]: postfix/qmgr[4921]: 0762D12CFB0D: removed > Apr 24 13:22:08 doctor doctor[31]: postfix/pickup[4920]: EAE1412CFA9C: uid=28 > from= > Apr 24 13:22:08 doctor doctor[31]: postfix/cleanup[17311]: EAE1412CFA9C: > message-id=<6ef179d262924e5a8c03336971544...@taskercomp> > Apr 24 13:22:09 doctor doctor[31]: postfix/qmgr[4921]: EAE1412CFA9C: > from=, size=5104132, nrcpt=1 (queue active) I asked for logging that covers the entire message life cycle, from SMTP until final delivery. Wietse
Re: [mailer-dae...@doctor.nl2k.ab.ca: Postfix SMTP server: errors from defout.telus.net[204.209.205.55]]
On 4/24/2010 2:41 PM, The Doctor wrote: You were saying about complete life cycle and non-verbose logs - Forwarded message from Mail Delivery System - Return-Path: double-bou...@doctor.nl2k.ab.ca X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on doctor.nl2k.ab.ca X-Spam-Level: X-Spam-Status: No, score=0.0 required=5.0 tests=none autolearn=ham version=3.3.1 X-Original-To: postmaster Delivered-To: postmas...@doctor.nl2k.ab.ca Received: by doctor.nl2k.ab.ca (Postfix) id 28DAB12CFA9C; Sat, 24 Apr 2010 13:22:00 -0600 (MDT) Date: Sat, 24 Apr 2010 13:22:00 -0600 (MDT) From: Mail Delivery System To: Postmaster Subject: Postfix SMTP server: errors from defout.telus.net[204.209.205.55] Message-Id:<20100424192200.28dab12cf...@doctor.nl2k.ab.ca> Transcript of session follows. Out: 220 doctor.nl2k.ab.ca ESMTP Postfix (2.8-20100323) In: EHLO defout.telus.net Out: 250-doctor.nl2k.ab.ca Out: 250-PIPELINING Out: 250-SIZE 2100 Out: 250-ETRN Out: 250-STARTTLS Out: 250-ENHANCEDSTATUSCODES Out: 250-8BITMIME Out: 250 DSN In: MAIL FROM: SIZE=5103584 Out: 250 2.1.0 Ok In: RCPT TO: Out: 250 2.1.5 Ok In: DATA Out: 354 End data with. Out: 451 4.3.0 Error: queue file write error Session aborted, reason: lost connection For other details, see the local mail logfile - End forwarded message - And the logs Apr 24 13:20:10 doctor doctor[31]: postfix/smtpd[17053]: 0762D12CFB0D: client=defout.telus.net[204.209.205.55] Apr 24 13:20:41 doctor doctor[31]: postfix/cleanup[17311]: 0762D12CFB0D: message-id=<6ef179d262924e5a8c03336971544...@taskercomp> Apr 24 13:22:04 doctor doctor[31]: postfix/qmgr[4921]: 0762D12CFB0D: from=, size=5104017, nrcpt=1 (queue active) Apr 24 13:22:04 doctor clamsmtpd: 100B1C: from=sender, to=recipient, status=CLEAN Apr 24 13:22:07 doctor postfix/pipe[17941]: 0762D12CFB0D: to=, orig_to=, relay=spamchk, delay=117, delays=115/0/0/2.9, dsn=2.0.0, status=sent (delivered via spamchk service) Apr 24 13:22:07 doctor doctor[31]: postfix/qmgr[4921]: 0762D12CFB0D: removed This message was accepted by postfix and then successfully sent to the spamchk filter. Nothing out of the ordinary shown here. Looks as if your clamsmtp spent ~1:30 processing the message, which is not unreasonable for a 5 meg file; anyway, it was successful. This is not the transaction that triggered the error sent to postmaster, which would have ended with a 451 queue write error, and would not have been passed to spamchk. Apr 24 13:22:08 doctor doctor[31]: postfix/pickup[4920]: EAE1412CFA9C: uid=28 from= Apr 24 13:22:08 doctor doctor[31]: postfix/cleanup[17311]: EAE1412CFA9C: message-id=<6ef179d262924e5a8c03336971544...@taskercomp> Apr 24 13:22:09 doctor doctor[31]: postfix/qmgr[4921]: EAE1412CFA9C: from=, size=5104132, nrcpt=1 (queue active) This is partial logging of a message submitted via the postfix command sendmail(1), presumably the output of your spamchk filter since the messaage-id is the same. Postfix accepted the message and put it in the active queue, with no logging shown after that. Nothing out of the ordinary shown. You need to show: - complete life cycle of a message that fails, from initial connect to failure. - your config, including "postconf -n" output and non-comment lines from master.cf. -- Noel Jones
[mailer-dae...@doctor.nl2k.ab.ca: Postfix SMTP server: errors from defout.telus.net[204.209.205.55]]
You were saying about complete life cycle and non-verbose logs - Forwarded message from Mail Delivery System - Return-Path: double-bou...@doctor.nl2k.ab.ca X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on doctor.nl2k.ab.ca X-Spam-Level: X-Spam-Status: No, score=0.0 required=5.0 tests=none autolearn=ham version=3.3.1 X-Original-To: postmaster Delivered-To: postmas...@doctor.nl2k.ab.ca Received: by doctor.nl2k.ab.ca (Postfix) id 28DAB12CFA9C; Sat, 24 Apr 2010 13:22:00 -0600 (MDT) Date: Sat, 24 Apr 2010 13:22:00 -0600 (MDT) From: Mail Delivery System To: Postmaster Subject: Postfix SMTP server: errors from defout.telus.net[204.209.205.55] Message-Id: <20100424192200.28dab12cf...@doctor.nl2k.ab.ca> Transcript of session follows. Out: 220 doctor.nl2k.ab.ca ESMTP Postfix (2.8-20100323) In: EHLO defout.telus.net Out: 250-doctor.nl2k.ab.ca Out: 250-PIPELINING Out: 250-SIZE 2100 Out: 250-ETRN Out: 250-STARTTLS Out: 250-ENHANCEDSTATUSCODES Out: 250-8BITMIME Out: 250 DSN In: MAIL FROM: SIZE=5103584 Out: 250 2.1.0 Ok In: RCPT TO: Out: 250 2.1.5 Ok In: DATA Out: 354 End data with . Out: 451 4.3.0 Error: queue file write error Session aborted, reason: lost connection For other details, see the local mail logfile - End forwarded message - And the logs Apr 24 13:20:10 doctor doctor[31]: postfix/smtpd[17053]: 0762D12CFB0D: client=defout.telus.net[204.209.205.55] Apr 24 13:20:41 doctor doctor[31]: postfix/cleanup[17311]: 0762D12CFB0D: message-id=<6ef179d262924e5a8c03336971544...@taskercomp> Apr 24 13:22:04 doctor doctor[31]: postfix/qmgr[4921]: 0762D12CFB0D: from=, size=5104017, nrcpt=1 (queue active) Apr 24 13:22:04 doctor clamsmtpd: 100B1C: from=sender, to=recipient, status=CLEAN Apr 24 13:22:07 doctor postfix/pipe[17941]: 0762D12CFB0D: to=, orig_to=, relay=spamchk, delay=117, delays=115/0/0/2.9, dsn=2.0.0, status=sent (delivered via spamchk service) Apr 24 13:22:07 doctor doctor[31]: postfix/qmgr[4921]: 0762D12CFB0D: removed Apr 24 13:22:08 doctor doctor[31]: postfix/pickup[4920]: EAE1412CFA9C: uid=28 from= Apr 24 13:22:08 doctor doctor[31]: postfix/cleanup[17311]: EAE1412CFA9C: message-id=<6ef179d262924e5a8c03336971544...@taskercomp> Apr 24 13:22:09 doctor doctor[31]: postfix/qmgr[4921]: EAE1412CFA9C: from=, size=5104132, nrcpt=1 (queue active) -- Member - Liberal International This is doc...@nl2k.ab.ca Ici doc...@nl2k.ab.ca God, Queen and country! Never Satan President Republic! Beware AntiChrist rising! http://twitter.com/rootnl2k http://www.facebook.com/dyadallee UK Time for a Common Sense change vote Liberal Democrat / Alliance
