OSEC

Neohapsis is currently accepting applications for employment. For more information, please visit our website www.neohapsis.com or email hr@neohapsis.com
Re: No delay warnings although delay_warning_time is set?

From: Ralph Seichter (postfix-mlseichter.de)
Date: Fri May 23 2008 - 12:27:54 CDT


* Wietse Venema:

> Obviously, things are not configured in the way you describe,
> so instead of an eyewitness report, actual concrete logging,
> postconf -n, and master.cf would be more suitable.

I included two "postconf -f" outputs in my original message; please see
<http://archives.neohapsis.com/archives/postfix/2008-05/1146.html>. Here
are the contents of the corresponding master.cf files:

  # grep -v '^#' /etc/postfix/master.cf
  smtp inet n - n - - smtpd
  pickup fifo n - n 60 1 pickup
  cleanup unix n - n - 0 cleanup
  qmgr fifo n - n 300 1 qmgr
  tlsmgr unix - - n 1000? 1 tlsmgr
  rewrite unix - - n - - trivial-rewrite
  bounce unix - - n - 0 bounce
  defer unix - - n - 0 bounce
  trace unix - - n - 0 bounce
  verify unix - - n - 1 verify
  flush unix n - n 1000? 0 flush
  proxymap unix - - n - - proxymap
  smtp unix - - n - - smtp
  relay unix - - n - - smtp
   -o fallback_relay=
  showq unix n - n - - showq
  error unix - - n - - error
  retry unix - - n - - error
  discard unix - - n - - discard
  local unix - n n - - local
  virtual unix - n n - - virtual
  lmtp unix - - n - - lmtp
  anvil unix - - n - 1 anvil
  scache unix - - n - 1 scache
  proxywrite unix - - n - 1 proxymap
  amavisd unix - - n - 2 smtp
   -o smtp_data_done_timeout=1200
   -o disable_dns_lookups=yes
  127.0.0.1:10025 inet n - n - - smtpd
   -o content_filter=
   -o local_recipient_maps=
   -o smtpd_helo_restrictions=
   -o smtpd_client_restrictions=
   -o smtpd_sender_restrictions=
   -o smtpd_recipient_restrictions=permit_mynetworks,reject
   -o mynetworks=127.0.0.0/8

  # grep -v '^#' /etc/postfix-out/master.cf
  smtp inet n - n - - smtpd
  pickup fifo n - n 60 1 pickup
  cleanup unix n - n - 0 cleanup
  qmgr fifo n - n 300 1 qmgr
  tlsmgr unix - - n 1000? 1 tlsmgr
  rewrite unix - - n - - trivial-rewrite
  bounce unix - - n - 0 bounce
  defer unix - - n - 0 bounce
  trace unix - - n - 0 bounce
  verify unix - - n - 1 verify
  flush unix n - n 1000? 0 flush
  proxymap unix - - n - - proxymap
  smtp unix - - n - - smtp
  relay unix - - n - - smtp
   -o fallback_relay=
  showq unix n - n - - showq
  error unix - - n - - error
  retry unix - - n - - error
  discard unix - - n - - discard
  local unix - n n - - local
  virtual unix - n n - - virtual
  lmtp unix - - n - - lmtp
  anvil unix - - n - 1 anvil
  scache unix - - n - 1 scache
  proxywrite unix - - n - 1 proxymap
  amavisd unix - - n - 2 smtp
   -o smtp_data_done_timeout=1200
   -o disable_dns_lookups=yes
  127.0.0.1:11025 inet n - n - - smtpd
   -o content_filter=
   -o local_recipient_maps=
   -o smtpd_helo_restrictions=
   -o smtpd_client_restrictions=
   -o smtpd_sender_restrictions=
   -o smtpd_recipient_restrictions=permit_mynetworks,reject
   -o mynetworks=127.0.0.0/8

I send my test emails using

  $ date | mutt -s "Test mail $(date) - Please ignore" foobaddom.org

And the log shows lines like these:

  May 23 19:02:04 mailhub postfix/pickup[31739]: DD1987F7E3: uid=1001 from=<seichter>
  May 23 19:02:04 mailhub postfix/cleanup[31826]: DD1987F7E3: message-id=<20080523170204.GA31821mailhub.domain.tld>
  May 23 19:02:04 mailhub postfix/qmgr[12551]: DD1987F7E3: from=<seichterdomain.tld>, size=527, nrcpt=1 (queue active)
  May 23 19:02:09 mailhub postfix/smtpd[31834]: connect from localhost[127.0.0.1]
  May 23 19:02:09 mailhub postfix/smtpd[31834]: 9DA957F7E4: client=localhost[127.0.0.1]
  May 23 19:02:09 mailhub postfix/cleanup[31826]: 9DA957F7E4: message-id=<20080523170204.GA31821mailhub.domain.tld>
  May 23 19:02:09 mailhub postfix/qmgr[12551]: 9DA957F7E4: from=<seichterdomain.tld>, size=970, nrcpt=1 (queue active)
  May 23 19:02:09 mailhub postfix/smtpd[31834]: disconnect from localhost[127.0.0.1]
  May 23 19:02:09 mailhub postfix/smtp[31828]: DD1987F7E3: to=<foobaddom.org>, relay=127.0.0.1[127.0.0.1]:10024, delay=4.8, delays=0.06/0.02/0.01/4.8, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 9DA957F7E4)
  May 23 19:02:09 mailhub postfix/qmgr[12551]: DD1987F7E3: removed
  May 23 19:02:09 mailhub postfix/smtp[31835]: setting up TLS connection to relay.domain.tld[123.123.123.123]:25
  May 23 19:02:09 mailhub postfix/smtp[31835]: Untrusted TLS connection established to relay.domain.tld[123.123.123.123]:25: TLSv1 with cipher ADH-CAMELLIA256-SHA (256/256 bits)
  May 23 19:02:10 mailhub postfix/smtp[31835]: 9DA957F7E4: host relay.domain.tld[123.123.123.123] said: 450 4.1.2 <foobaddom.org>: Recipient address rejected: Domain not found (in reply to RCPT TO command)
  May 23 19:02:10 mailhub postfix/smtp[31835]: setting up TLS connection to fallback-relay.domain.tld[234.234.234.234]:25
  May 23 19:02:10 mailhub postfix/smtp[31835]: Untrusted TLS connection established to fallback-relay.domain.tld[234.234.234.234]:25: TLSv1 with cipher ADH-CAMELLIA256-SHA (256/256 bits)
  May 23 19:02:10 mailhub postfix/smtp[31835]: 9DA957F7E4: to=<foobaddom.org>, relay=fallback-relay.domain.tld[234.234.234.234]:25, delay=1.3, delays=0.03/0.04/0.77/0.49, dsn=4.1.2, status=deferred (host fallback-relay.domain.tld[234.234.234.234] said: 450 4.1.2 <foobaddom.org>: Recipient address rejected: Domain not found (in reply to RCPT TO command))

  # mailq
  -Queue ID- --Size-- ----Arrival Time---- -Sender/Recipient-------
  9DA957F7E4 970 Fri May 23 19:02:09 seichterdomain.tld
  (host fallback-relay.domain.tld[234.234.234.234] said: 450 4.1.2 <foobaddom.org>: Recipient address rejected: Domain not found (in reply to RCPT TO command))
                                           foobaddom.org

  -- 1 Kbytes in 1 Request.

  # postcat -q 9DA957F7E4
  *** ENVELOPE RECORDS deferred/9/9DA957F7E4 ***
  message_size: 970 592 1 0 970
  message_arrival_time: Fri May 23 19:02:09 2008
  create_time: Fri May 23 19:02:09 2008
  named_attribute: rewrite_context=local
  sender: seichterdomain.tld
  named_attribute: encoding=7bit
  named_attribute: log_client_name=localhost
  named_attribute: log_client_address=127.0.0.1
  named_attribute: log_client_port=60585
  named_attribute: log_message_origin=localhost[127.0.0.1]
  named_attribute: log_helo_name=localhost
  named_attribute: log_protocol_name=ESMTP
  named_attribute: client_name=localhost
  named_attribute: reverse_client_name=localhost
  named_attribute: client_address=127.0.0.1
  named_attribute: client_port=60585
  named_attribute: helo_name=localhost
  named_attribute: client_address_type=2
  warning_message_time: Fri May 23 19:12:09 2008
  named_attribute: dsn_orig_rcpt=rfc822;foobaddom.org
  original_recipient: foobaddom.org
  recipient: foobaddom.org
  *** MESSAGE CONTENTS deferred/9/9DA957F7E4 ***
  Received: from localhost (localhost [127.0.0.1])
          by mailhub.domain.tld (Postfix) with ESMTP id 9DA957F7E4
          for <foobaddom.org>; Fri, 23 May 2008 19:02:09 +0200 (CEST)
  X-Virus-Scanned: at ElektroPhysik
  Received: from mailhub.domain.tld ([127.0.0.1])
          by localhost (mailhub.domain.tld [127.0.0.1]) (amavisd-new, port 10024)
          with ESMTP id FJJklrZfPPsR for <foobaddom.org>;
          Fri, 23 May 2008 19:02:04 +0200 (CEST)
  Received: by mailhub.domain.tld (Postfix, from userid 1001)
          id DD1987F7E3; Fri, 23 May 2008 19:02:04 +0200 (CEST)
  Date: Fri, 23 May 2008 19:02:04 +0200
  From: Ralph Seichter <seichterdomain.tld>
  To: foobaddom.org
  Subject: Test mail Fri May 23 19:02:04 CEST 2008 - Please ignore
  Message-ID: <20080523170204.GA31821mailhub.domain.tld>
  MIME-Version: 1.0
  Content-Type: text/plain; charset=us-ascii
  Content-Disposition: inline
  User-Agent: Mutt/1.5.16 (2007-06-09)

  Fri May 23 19:02:04 CEST 2008
  *** HEADER EXTRACTED deferred/9/9DA957F7E4 ***
  named_attribute: encoding=7bit
  *** MESSAGE FILE END deferred/9/9DA957F7E4 ***

If read "warning_message_time: Fri May 23 19:12:09 2008" correctly, a
delayed mail notification should have been sent at 19:12:09, but it is
now approximately 19:27 and I can't see any notification so far. I
checked the mail log again, but

  # grep 9DA957F7E4 /var/log/mail

returns no log entries after the following line:

  May 23 19:02:10 mailhub postfix/smtp[31835]: 9DA957F7E4: to=<foobaddom.org>, relay=fallback-relay.domain.tld[234.234.234.234]:25, delay=1.3, delays=0.03/0.04/0.77/0.49, dsn=4.1.2, status=deferred (host fallback-relay.domain.tld[234.234.234.234] said: 450 4.1.2 <foobaddom.org>: Recipient address rejected: Domain not found (in reply to RCPT TO command))

That seems rather strange to me.

-R