Postfix 2.5.1 cleanup(8) Date: issue?

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

Postfix 2.5.1 cleanup(8) Date: issue?

Matthias Andree-6
(although I'm subscribed, please Cc: me on replies for a quicker
turnaround -- also, the list appears to drop messages from non-subscribers
silently, rather than bouncing them. If it was held for moderation, sorry...)

Greetings,

I have observed a very strange behaviour related to the DST switch
yesterday morning.

Issue: On the most direct route I can fancy, i. e. injecting a trivial
message (just a Subject: line) directly into port 10025 (to bypass spam
filtering) and delivering to a Maildir/, Postfix appears to produce a
bogus Date: header in the received message (UTC is correct, but local time
and timezone are wrong, timezone name is missing). Interestingly, the time
logged in Received: is correct. I would have hoped that the Date: header
produces the same timestamp as in the Received: header.

It would appear this is a cleanup(8) bug, but I'm apparently unable to
debug it.  The relevant code in cleanup appears to call mail_date which
itself works OK.

I confirmed that the three files /etc/localtime,
/var/spool/postfix/etc/localtime, usr/share/zoneinfo/Europe/Berlin are all
identical (according to md5sum) and none is a symlink.

I've stopped and re-started postfix. Postfix check doesn't produce output.
The Ubuntu and Debian bug trackers don't contain strikingly obvious bugs.

I've tried to run cleanup outside the chroot jail, to no avail. I've run
cleanup under strace, nothing strikingly obvious, opening /etc/localtime
succeeds.
(Information not included, but will figure relevant information from the
logs upon request.)

The system runs the official Ubuntu Linux 8.04 LTS Server postfix packages
(i686/32-bit on a Xeon with ECC memory/Fujitsu Primergy RX100S3 IIRC and
with AMCC RAID1), and it is in production, so testing is somewhat limited.

Evidence given below (hostnames and IPs were anonymized to example.org and
10.0.0.NNN with a sed script):

#1 the message as received in Maildir/
#2 relevant log
#3 postfinger information.

Any help to further debug this will be appreciated.

-------- #1 -------------

Return-Path: <>
X-Original-To: ma+direct
Delivered-To: [hidden email]
Received: from x (localhost [127.0.0.1])
           by mail.example.org (Postfix) with ESMTP id A3F59481E3
           for <ma+direct>; Mon, 29 Mar 2010 16:38:10 +0200 (CEST)
Subject: yet another Postfix test
Message-Id: <[hidden email]>
Date: Mon, 29 Mar 2010 16:38:10 +0200 (CEST)
From: MAILER-DAEMON
To: undisclosed-recipients:;


-------- #2 -------------

Mar 29 16:38:10 mailserver postfix/smtpd[14732]: A3F59481E3:
client=localhost[127.0.0.1]
Mar 29 16:38:15 mailserver postfix/cleanup[14739]: A3F59481E3:
message-id=<[hidden email]>
Mar 29 16:38:15 mailserver postfix/qmgr[12968]: A3F59481E3: from=<>,
size=381, nrcpt=1 (queue active)
Mar 29 16:38:15 mailserver postfix/local[14743]: A3F59481E3:
to=<[hidden email]>, orig_to=<ma+direct>, relay=local, delay=5.3,
delays=5.3/0.01/0/0.02, dsn=2.0.0, status=sent (delivered to maildir)
Mar 29 16:38:15 mailserver postfix/qmgr[12968]: A3F59481E3: removed

-------- #3 -------------

postfinger - postfix configuration on Mon Mar 29 16:40:53 CEST 2010
version: 1.30

--System Parameters--
mail_version = 2.5.1
hostname = mailserver
uname = Linux mailserver 2.6.24-26-server #1 SMP Tue Dec 1 19:19:20 UTC
2009 i686 GNU/Linux

--Packaging information--
looks like this postfix comes from deb package: postfix-2.5.1-2ubuntu1.2

--main.cf non-default parameters--
alias_database = hash:/etc/aliases hash:/etc/aliases-users
alias_maps = hash:/etc/aliases hash:/var/lib/mailman/data/aliases
hash:/etc/aliases-users
append_dot_mydomain = no
biff = no
body_checks = pcre:/etc/postfix/body_checks
bounce_queue_lifetime = 3d
canonical_maps = hash:/etc/postfix/canonical
delay_warning_time = 255m
forward_path =
/var/mail/${user}/.forward${recipient_delimiter}${extension}
/var/mail/${user}/.forward
header_checks = pcre:/etc/postfix/header_checks
html_directory = /usr/share/doc/postfix/html
local_recipient_maps = proxy:nis:passwd.byname $relocated_maps $alias_maps
mailbox_command = /usr/bin/maildrop -d "$USER" -f "$SENDER" "$EXTENSION"
"$RECIPIENT" "$USER" "$SENDER"
mailbox_size_limit = 0
masquerade_domains = example.org example.org
message_size_limit = 32000000
mydestination = $myhostname, localhost.$mydomain, $mydomain,
example.org,       mailserver.example.org, localhost.example.org,
mail.example.org, example.org,   mailserver.example.org,
localhost.example.org, mail.example.org, localhost,
pcre:/etc/postfix/mydestination
myhostname = mail.example.org
mynetworks = 127.0.0.0/8 [::ffff:127.0.0.0]/104 [::1]/128 10.0.0.0/26
192.168.0.0/24 192.168.2.0/24
myorigin = /etc/mailname
recipient_delimiter = +
relocated_maps = hash:/etc/postfix/relocated
show_user_unknown_table_name = no
smtpd_authorized_verp_clients = localhost localhost.$mydomain $myhostname
smtpd_authorized_xforward_hosts = 127.0.0.1 10.0.0.25 10.0.0.28
smtpd_banner = $myhostname ESMTP $mail_name (Ubuntu)
smtpd_client_restrictions = cidr:/etc/postfix/filtered-clients-cidr
smtpd_etrn_restrictions = reject
smtpd_helo_required = yes
smtpd_helo_restrictions = reject_invalid_hostname permit_mynetworks
reject_non_fqdn_hostname
smtpd_recipient_restrictions = pcre:/etc/postfix/regexp_access
reject_unlisted_recipient reject_multi_recipient_bounce permit_mynetworks
permit_sasl_authenticated reject_unauth_pipelining
reject_unauth_destination
smtpd_restriction_classes = localsite_sender_access
smtpd_sasl_path = private/auth
smtpd_sasl_type = dovecot
smtpd_sender_restrictions = reject_non_fqdn_sender
reject_unknown_sender_domain reject_unlisted_sender
hash:/etc/postfix/access permit_mynetworks check_sender_mx_access
cidr:/etc/postfix/mx_cidr_access localsite_sender_access permit
smtpd_tls_cert_file = /etc/ssl/certs/dovecot.pem
smtpd_tls_key_file = /etc/ssl/private/dovecot.pem
smtpd_tls_session_cache_database = btree:${data_directory}/smtpd_scache
smtp_helo_name = mailserver.example.org
unverified_sender_reject_code = 550

--master.cf--
smtp      inet  n       -       -       -       -       smtpd
submission inet n       -       -       -       -       smtpd
     -o smtpd_tls_security_level=encrypt
     -o smtpd_sasl_auth_enable=yes
     -o smtpd_client_restrictions=permit_sasl_authenticated,reject
     -o milter_macro_daemon_name=ORIGINATING
smtps     inet  n       -       -       -       -       smtpd
     -o smtpd_tls_wrappermode=yes
     -o smtpd_sasl_auth_enable=yes
     -o smtpd_client_restrictions=permit_sasl_authenticated,reject
     -o milter_macro_daemon_name=ORIGINATING
pickup    fifo  n       -       -       60      1       pickup
cleanup   unix  n       -       -       -       0       cleanup
qmgr      fifo  n       -       n       300     1       qmgr
tlsmgr    unix  -       -       -       1000?   1       tlsmgr
rewrite   unix  -       -       -       -       -       trivial-rewrite
bounce    unix  -       -       -       -       0       bounce
defer     unix  -       -       -       -       0       bounce
trace     unix  -       -       -       -       0       bounce
verify    unix  -       -       -       -       1       verify
flush     unix  n       -       -       1000?   0       flush
proxymap  unix  -       -       n       -       -       proxymap
proxywrite unix -       -       n       -       1       proxymap
smtp      unix  -       -       -       -       -       smtp
relay     unix  -       -       -       -       -       smtp
           -o smtp_fallback_relay=
showq     unix  n       -       -       -       -       showq
error     unix  -       -       -       -       -       error
retry     unix  -       -       -       -       -       error
discard   unix  -       -       -       -       -       discard
local     unix  -       n       n       -       -       local
virtual   unix  -       n       n       -       -       virtual
lmtp      unix  -       -       -       -       -       lmtp
anvil     unix  -       -       -       -       1       anvil
scache    unix  -       -       -       -       1       scache
mailman   unix  -       n       n       -       -       pipe
     flags=FR user=list argv=/usr/lib/mailman/bin/postfix-to-mailman.py
     ${nexthop} ${user}
amavisfeed unix    -       -       n        -      2     lmtp
       -o lmtp_data_done_timeout=1200
       -o lmtp_send_xforward_command=yes
       -o disable_dns_lookups=yes
       -o max_use=20
127.0.0.1:10025 inet n    -       n       -       -     smtpd
       -o content_filter=
       -o smtpd_delay_reject=no
       -o smtpd_client_restrictions=permit_mynetworks,reject
       -o smtpd_helo_restrictions=
       -o smtpd_sender_restrictions=
       -o smtpd_recipient_restrictions=permit_mynetworks,reject
       -o smtpd_data_restrictions=reject_unauth_pipelining
       -o smtpd_end_of_data_restrictions=
       -o smtpd_restriction_classes=
       -o mynetworks=127.0.0.0/8
       -o smtpd_error_sleep_time=0
       -o smtpd_soft_error_limit=1001
       -o smtpd_hard_error_limit=1000
       -o smtpd_client_connection_count_limit=0
       -o smtpd_client_connection_rate_limit=0
       -o
receive_override_options=no_header_body_checks,no_unknown_recipient_checks
       -o local_header_rewrite_clients=

-- end of postfinger output --



--
Matthias Andree
Reply | Threaded
Open this post in threaded view
|

Re: Postfix 2.5.1 cleanup(8) Date: issue?

Wietse Venema
Matthias Andree:
> and timezone are wrong, timezone name is missing). Interestingly, the time
> logged in Received: is correct. I would have hoped that the Date: header
> produces the same timestamp as in the Received: header.
...

> Return-Path: <>
> X-Original-To: ma+direct
> Delivered-To: [hidden email]
> Received: from x (localhost [127.0.0.1])
>            by mail.example.org (Postfix) with ESMTP id A3F59481E3
>            for <ma+direct>; Mon, 29 Mar 2010 16:38:10 +0200 (CEST)
> Subject: yet another Postfix test
> Message-Id: <[hidden email]>
> Date: Mon, 29 Mar 2010 16:38:10 +0200 (CEST)
> From: MAILER-DAEMON
> To: undisclosed-recipients:;

In the above message:

    Received header date = Mon, 29 Mar 2010 16:38:10 +0200 (CEST)
    Date header date =     Mon, 29 Mar 2010 16:38:10 +0200 (CEST)

These time stamps are identical, and all headers have the form that
I would expect from Postfix.

Your postfix-users submission has:

Received: from [131.234.21.116] (baloo.cs.uni-paderborn.de [131.234.21.116])
        (authenticated bits=0)
        by unimail.uni-dortmund.de (8.14.4/8.14.4) with ESMTP id o2TFXok8003087
        (version=TLSv1/SSLv3 cipher=DHE-RSA-CAMELLIA256-SHA bits=256 verify=NOT)
        for <[hidden email]>; Mon, 29 Mar 2010 17:33:51 +0200 (CEST)
Message-ID: <[hidden email]>
Date: Mon, 29 Mar 2010 17:33:48 +0200

This has a NON-POSTFIX Message-ID: header, and a Date: header
without time zone.

        Wietse
Reply | Threaded
Open this post in threaded view
|

[SOLVED] Re: Postfix 2.5.1 cleanup(8) Date: issue?

Matthias Andree-6
Wietse Venema wrote on 2010-03-29:

> Matthias Andree:
>> and timezone are wrong, timezone name is missing). Interestingly, the  
>> time
>> logged in Received: is correct. I would have hoped that the Date: header
>> produces the same timestamp as in the Received: header.
> ...
>> Return-Path: <>
>> X-Original-To: ma+direct
>> Delivered-To: [hidden email]
>> Received: from x (localhost [127.0.0.1])
>>            by mail.example.org (Postfix) with ESMTP id A3F59481E3
>>            for <ma+direct>; Mon, 29 Mar 2010 16:38:10 +0200 (CEST)
>> Subject: yet another Postfix test
>> Message-Id: <[hidden email]>
>> Date: Mon, 29 Mar 2010 16:38:10 +0200 (CEST)
>> From: MAILER-DAEMON
>> To: undisclosed-recipients:;
>
> In the above message:
>
>     Received header date = Mon, 29 Mar 2010 16:38:10 +0200 (CEST)
>     Date header date =     Mon, 29 Mar 2010 16:38:10 +0200 (CEST)
>
> These time stamps are identical, and all headers have the form that
> I would expect from Postfix.

Thank you.  It matches what I'd read in the source (the strftime format string).

> This has a NON-POSTFIX Message-ID: header, and a Date: header
> without time zone.

That's ok, and wasn't what I'd tested.

Now that's embarrassing, for me (not noticing the discrepancy between mailer's
display and Maildir contents), and for the Opera guys (for goofing up the time
zone).

Here's the story:  I was looking at what Opera 10.51's mail client was
presenting me in "all headers and body" view (whatever the exact name is,  I'm
using a localized version).

Original:

Return-Path: <>
X-Original-To: ma+direct
Delivered-To: [hidden email]
Received: from x (localhost [127.0.0.1])
         by mail.example.org (Postfix) with ESMTP id E753548DA6
         for <ma+direct>; Mon, 29 Mar 2010 19:19:04 +0200 (CEST)
Subject: yet another Postfix test
Message-Id: <[hidden email]>
Date: Mon, 29 Mar 2010 19:19:04 +0200 (CEST)
From: MAILER-DAEMON
To: undisclosed-recipients:;


Opera representation (Note Return-path misspelling, b0rked Date timezone, and
omitted To - it's not in the headline either):

Return-path: <>
X-Original-To: ma+direct
Delivered-To: [hidden email]
Received: from x (localhost [127.0.0.1]) by mail.example.org
  (Postfix) with ESMTP id E753548DA6 for <ma+direct>; Mon, 29 Mar 2010  19:19:04
  +0200 (CEST)
Subject: yet another Postfix test
Message-ID: <[hidden email]>
Date: Mon, 29 Mar 2010 20:19:04 +0300
From: MAILER-DAEMON


Looks like a one of the many Opera mail bugs. Filed as bug #291618 with Opera,
and that bug address in Bcc: so they know this is being discussed in public.
Sorry for the lack of displomacy, but you get to share the embarrassment anyways :)

Off-topic: Anyone know a Thunderbird add-in that auto-creates virtual folders
for mailing lists? It's the sole reason why I'm still using Opera M2.

--
Matthias Andree