delay_warning_time not honored

[lst_hoe02]

Hello

today i detected a mail lingering in the queue since around 24h. The  
warning_delay_time is set to 12h but there was no warning message to  
the sender until yet. So i used postcat to inspect the message and get  
the following:

*** ENVELOPE RECORDS deferred/9/900086FA13 ***
message_size:           29109             754               1          
     12           29109
message_arrival_time: Wed Nov  4 10:58:27 2009
create_time: Wed Nov  4 10:58:27 2009
named_attribute: rewrite_context=remote
named_attribute:  
envelope_id=FR_AN_0001M[r[k@fyki38zbeCpm8B0aNJjbVwFR_AN[_[_[__0001M[qQ15
sender: xxxxx@...
named_attribute: log_client_name=xxxxx.hq.kwsoft.de
named_attribute: log_client_address=x.x.x.x
named_attribute: log_client_port=1349
named_attribute: log_message_origin=xxxxx.hq.kwsoft.de[x.x.x.x]
named_attribute: log_helo_name=xxxxxx
named_attribute: log_protocol_name=ESMTP
named_attribute: client_name=xxxxx.hq.kwsoft.de
named_attribute: reverse_client_name=xxxxx.hq.kwsoft.de
named_attribute: client_address=x.x.x.x
named_attribute: client_port=1349
named_attribute: helo_name=xxxxx
named_attribute: client_address_type=2
warning_message_time: Thu Jan  1 01:00:00 1970
named_attribute: notify_flags=6


I fired up a second message to the same destination (DNS timeouts) and  
get what is expected:


*** ENVELOPE RECORDS deferred/5/5B6556FEC9 ***
message_size:            1779             646               1          
      0            1779
message_arrival_time: Thu Nov  5 12:09:51 2009
create_time: Thu Nov  5 12:09:51 2009
named_attribute: rewrite_context=remote
warning_message_time: Fri Nov  6 00:09:51 2009

Any ideas what was wrong with the first message so it get the wrong  
warning time??

I have checked if postfix was restarted or if there are any errors in  
the logfile around the submission of the first one, but nothing found.

postconf -n

biff = no
bounce_queue_lifetime = 2d
broken_sasl_auth_clients = yes
command_directory = /usr/sbin
config_directory = /etc/postfix
daemon_directory = /usr/lib/postfix
debug_peer_level = 2
delay_warning_time = 12h
fast_flush_domains =
html_directory = /usr/share/doc/packages/postfix/html
inet_interfaces = all
inet_protocols = ipv4
local_recipient_maps = $alias_maps
mail_owner = postfix
mail_spool_directory = /var/spool/mail
mailq_path = /usr/bin/mailq
manpage_directory = /usr/share/man
maximal_queue_lifetime = 3d
message_size_limit = 52000000
mydestination = $myhostname, localhost
mydomain = kwsoft.de
myhostname = mailer.kwsoft.de
mynetworks = 192.168.2.0/24, 127.0.0.0/8
myorigin = $mydomain
newaliases_path = /usr/bin/newaliases
queue_directory = /var/spool/postfix
readme_directory = /usr/share/doc/packages/postfix/README_FILES
sample_directory = /usr/share/doc/packages/postfix/samples
sender_canonical_maps = proxy:ldap:/etc/postfix/ldap-canonical.cf
sendmail_path = /usr/sbin/sendmail
smtp_sasl_auth_enable = no
smtp_skip_5xx_greeting = no
smtp_tls_CApath = /etc/ssl/certs
smtp_tls_loglevel = 1
smtp_tls_security_level = may
smtpd_banner = $myhostname ESMTP $mail_name
smtpd_recipient_restrictions = reject_non_fqdn_sender,          
reject_non_fqdn_recipient,          permit_mynetworks,          
permit_saslauthenticated,          reject_unauth_destination
smtpd_sasl_auth_enable = no
smtpd_tls_cert_file = /etc/ssl/postfix/mailer.kwsoft.de.cert
smtpd_tls_key_file = /etc/ssl/postfix/mailer.kwsoft.de.key
smtpd_tls_loglevel = 1
smtpd_tls_security_level = may
transport_maps = hash:/etc/postfix/transport
unknown_local_recipient_reject_code = 550
virtual_alias_domains = hash:/etc/postfix/virtual-alias-domains
virtual_alias_maps = hash:/etc/postfix/virtual,  
proxy:ldap:/etc/postfix/ldap-virtaliases.cf

Many thanks for any pointers

Andreas

[Wietse Venema]

lst_hoe02@...:
> Any ideas what was wrong with the first message so it get the wrong  
> warning time??

delay_warning_time is implemented by the cleanup daemon (which
writes the warning time record) and by the queue manager (which
triggers notification).  Perhaps you have "-o delay_warning_time"
in master.cf? Multiple Postfix instances? MailScanner messing
around with files? :-)

The default warning time is "0" meaning that a zero warning time
record is written. This corresponds with January 1 1970.

        Wietse

[lst_hoe02]

Zitat von Wietse Venema <wietse@...>:

> lst_hoe02@...:
>> Any ideas what was wrong with the first message so it get the wrong
>> warning time??
>
> delay_warning_time is implemented by the cleanup daemon (which
> writes the warning time record) and by the queue manager (which
> triggers notification).  Perhaps you have "-o delay_warning_time"
> in master.cf? Multiple Postfix instances? MailScanner messing
> around with files? :-)

- "grep delay_warning /etc/postfix/*"  only shows the one in main.cf
- I have never tried Multiple Postfix instances (yet)
- I would never let touch MailScanner my mail

> The default warning time is "0" meaning that a zero warning time
> record is written. This corresponds with January 1 1970.
>
> Wietse

What's really puzzling me is that it worked since years and still  
works as the second try shows, but failed in this special case. I have  
not altered delay_warning_time since at least half a year and two  
restarts. I have done some changes (and reverted it) in master.cf but  
nothing related to delay_warning_time at all.

Really strange...

Many Thanks

Andreas

[lst_hoe02]

Zitat von lst_hoe02@...:

> Zitat von Wietse Venema <wietse@...>:
>
>> lst_hoe02@...:
>>> Any ideas what was wrong with the first message so it get the wrong
>>> warning time??
>>
>> delay_warning_time is implemented by the cleanup daemon (which
>> writes the warning time record) and by the queue manager (which
>> triggers notification).  Perhaps you have "-o delay_warning_time"
>> in master.cf? Multiple Postfix instances? MailScanner messing
>> around with files? :-)
>
> - "grep delay_warning /etc/postfix/*"  only shows the one in main.cf
> - I have never tried Multiple Postfix instances (yet)
> - I would never let touch MailScanner my mail
>
>> The default warning time is "0" meaning that a zero warning time
>> record is written. This corresponds with January 1 1970.
>>
>> Wietse
>
> What's really puzzling me is that it worked since years and still  
> works as the second try shows, but failed in this special case. I  
> have not altered delay_warning_time since at least half a year and  
> two restarts. I have done some changes (and reverted it) in  
> master.cf but nothing related to delay_warning_time at all.

This message doesn't even bounce???
If have lowered maximal_queue_lifetime to 1d to force it to bounce,  
restarted postfix but still the message does nothing...
Even tried postsuper -r but nothing changes?

Nov  5 13:32:29 mailer postfix/smtp[14960]: A55506FA79:  
to=<xxxxxx@...>, relay=none, delay=95642,  
delays=95622/0.03/20/0, dsn=4.4.3, status=deferred (Host or domain  
name not found. Name service error for name=zwitzerleven.nl type=MX:  
Host not found, try again)


Any ideas?

Many Thanks

Andreas

[Wietse Venema]

lst_hoe02@...:

> Zitat von Wietse Venema <wietse@...>:
>
> > lst_hoe02@...:
> >> Any ideas what was wrong with the first message so it get the wrong
> >> warning time??
> >
> > delay_warning_time is implemented by the cleanup daemon (which
> > writes the warning time record) and by the queue manager (which
> > triggers notification).  Perhaps you have "-o delay_warning_time"
> > in master.cf? Multiple Postfix instances? MailScanner messing
> > around with files? :-)
>
> - "grep delay_warning /etc/postfix/*"  only shows the one in main.cf
> - I have never tried Multiple Postfix instances (yet)
> - I would never let touch MailScanner my mail
>
> > The default warning time is "0" meaning that a zero warning time
> > record is written. This corresponds with January 1 1970.
> >
> > Wietse
>
> What's really puzzling me is that it worked since years and still  
> works as the second try shows, but failed in this special case. I have  
> not altered delay_warning_time since at least half a year and two  
> restarts. I have done some changes (and reverted it) in master.cf but  
> nothing related to delay_warning_time at all.
>
> Really strange...

Does the machine have Parity/ECC memory? Parity on the I/O bus?
Some bit-flips have detectable effects while others don't.

        Wietse

[Wietse Venema]

lst_hoe02@...:

> Zitat von lst_hoe02@...:
>
> > Zitat von Wietse Venema <wietse@...>:
> >
> >> lst_hoe02@...:
> >>> Any ideas what was wrong with the first message so it get the wrong
> >>> warning time??
> >>
> >> delay_warning_time is implemented by the cleanup daemon (which
> >> writes the warning time record) and by the queue manager (which
> >> triggers notification).  Perhaps you have "-o delay_warning_time"
> >> in master.cf? Multiple Postfix instances? MailScanner messing
> >> around with files? :-)
> >
> > - "grep delay_warning /etc/postfix/*"  only shows the one in main.cf
> > - I have never tried Multiple Postfix instances (yet)
> > - I would never let touch MailScanner my mail
> >
> >> The default warning time is "0" meaning that a zero warning time
> >> record is written. This corresponds with January 1 1970.
> >>
> >> Wietse
> >
> > What's really puzzling me is that it worked since years and still  
> > works as the second try shows, but failed in this special case. I  
> > have not altered delay_warning_time since at least half a year and  
> > two restarts. I have done some changes (and reverted it) in  
> > master.cf but nothing related to delay_warning_time at all.
>
> This message doesn't even bounce???
> If have lowered maximal_queue_lifetime to 1d to force it to bounce,  
> restarted postfix but still the message does nothing...
> Even tried postsuper -r but nothing changes?
>
> Nov  5 13:32:29 mailer postfix/smtp[14960]: A55506FA79:  
> to=<xxxxxx@...>, relay=none, delay=95642,  
> delays=95622/0.03/20/0, dsn=4.4.3, status=deferred (Host or domain  
> name not found. Name service error for name=zwitzerleven.nl type=MX:  
> Host not found, try again)
>
>
> Any ideas?

postsuper resets the arrival time.

        Wietse

[lst_hoe02]

Zitat von Wietse Venema <wietse@...>:

> lst_hoe02@...:
>> Zitat von lst_hoe02@...:
>>
>> > Zitat von Wietse Venema <wietse@...>:
>> >
>> >> lst_hoe02@...:
>> >>> Any ideas what was wrong with the first message so it get the wrong
>> >>> warning time??
>> >>
>> >> delay_warning_time is implemented by the cleanup daemon (which
>> >> writes the warning time record) and by the queue manager (which
>> >> triggers notification).  Perhaps you have "-o delay_warning_time"
>> >> in master.cf? Multiple Postfix instances? MailScanner messing
>> >> around with files? :-)
>> >
>> > - "grep delay_warning /etc/postfix/*"  only shows the one in main.cf
>> > - I have never tried Multiple Postfix instances (yet)
>> > - I would never let touch MailScanner my mail
>> >
>> >> The default warning time is "0" meaning that a zero warning time
>> >> record is written. This corresponds with January 1 1970.
>> >>
>> >> Wietse
>> >
>> > What's really puzzling me is that it worked since years and still
>> > works as the second try shows, but failed in this special case. I
>> > have not altered delay_warning_time since at least half a year and
>> > two restarts. I have done some changes (and reverted it) in
>> > master.cf but nothing related to delay_warning_time at all.
>>
>> This message doesn't even bounce???
>> If have lowered maximal_queue_lifetime to 1d to force it to bounce,
>> restarted postfix but still the message does nothing...
>> Even tried postsuper -r but nothing changes?
>>
>> Nov  5 13:32:29 mailer postfix/smtp[14960]: A55506FA79:
>> to=<xxxxxx@...>, relay=none, delay=95642,
>> delays=95622/0.03/20/0, dsn=4.4.3, status=deferred (Host or domain
>> name not found. Name service error for name=zwitzerleven.nl type=MX:
>> Host not found, try again)
>>
>>
>> Any ideas?
>
> postsuper resets the arrival time.
>

Uff, yes. I was confused about output of mailq which still lists the  
old arrival time. Is it intentional that postsuper -r does not reset  
the "warning_message_time"?

BTW: This is one of the few machines with ECC we have. I will check if  
the error counters have changed lately.

Thanks

Andreas

[Wietse Venema]

lst_hoe02@...:
> > postsuper resets the arrival time.
>
> Uff, yes. I was confused about output of mailq which still lists the  
> old arrival time. Is it intentional that postsuper -r does not reset  
> the "warning_message_time"?

Yes. I guess the reasoning is as follows: delay warnings are
time-critical, and it would be surprising if the warning did not
come timely. Non-delivery notifications after maximal_queue_lifetime
are different in that they aren't time critical.

> BTW: This is one of the few machines with ECC we have. I will check if  
> the error counters have changed lately.

Besides hardware, automatic updates have been known to mess up
perfectly-working Postfix installations. One really should not
replace libraries on a server without restarting programs.

        Wietse