[Postfixbuch-users] Timed out during fwd-data

Martin Fischer martin.fischer at bcc.de
Di Sep 23 11:06:06 CEST 2003


hallo,

vor ein zwei wochen habe ich meinen mailserver um amavisd-new erweitert. 
soweit klappt auch alles und läuft so wie ich es mir vorstelle.

dennoch habe ich ein problem mit grossen mails. diese verbleiben in der mailq 
und bekommen eine status:

9ECF6FA4    7970624 Sun Sep 21 02:13:53  foo at bar.tld
(host 127.0.0.1[127.0.0.1] said: 450 4.4.2 Timed out during fwd-data, 
id=28951-09)
                                         postmaster at foobar.tld

also die mail von foo at bar.tld kann wegen einem timeout nicht an den postmaster 
von @foobar.tld geliefert werden.

mir ist nicht so ganz klar wo das ganze nun hängt.. wenn ich das logfile 
ansehe, interpretiere ich es so, das amavis die mails verarbeitet und an den 
lokalen smtpd übergeben will und es dann zu einem timeout kommt:

Sep 21 02:13:53 raptor postfix/smtpd[10499]: 9ECF6FA4: 
client=moutvdom.xxxxxx.de[xxx.xxx.xxx.xxx]
Sep 21 02:13:53 raptor postfix/cleanup[10500]: 9ECF6FA4: 
message-id=<025501c37fd3$98a82810$0200a8c0 at kd1>

[...]

Sep 21 05:18:00 raptor postfix/nqmgr[27652]: 9ECF6FA4: from=<foo at bar.tld>, 
size=7970624, nrcpt=1 (queue active)
Sep 21 05:18:00 raptor amavis[13449]: (13449-03) ESMTP::10024 
/var/amavis/amavis-20030921T043718-13449: <foo at bar.tld> -> 
<postmaster at foobar.tld> Received: SIZE=7970624 from mail.xxxxxx.de 
([127.0.0.1]) by localhost (raptor [127.0.0.1]) (amavisd-new, port 10024) 
with ESMTP id 13449-03 for <postmaster at foobar.tld>; Sun, 21 Sep 2003 05:18:00 
+0200 (CEST)
Sep 21 05:18:00 raptor postfix/smtpd[10499]: disconnect from 
moutvdom.xxxxxx.de[xxx.xxx.xxx.xxx]
Sep 21 05:18:06 raptor amavis[13449]: (13449-03) Checking: <foo at bar.tld> -> 
<postmaster at foobar.tld>
Sep 21 05:18:13 raptor amavis[13449]: (13449-03) spam_scan: not wasting time 
on SA, message longer than 65536 bytes: 1298+7867052
Sep 21 05:18:13 raptor amavis[13449]: (13449-03) spam_scan: hits=
Sep 21 05:18:13 raptor amavis[13449]: (13449-03) FWD via SMTP: 
[127.0.0.1:10025] <foo at bar.tld> -> <postmaster at foobar.tld>
Sep 21 05:18:13 raptor postfix/smtpd[14502]: connect from localhost[127.0.0.1]
Sep 21 05:18:13 raptor postfix/smtpd[14502]: 5CE8911EA: 
client=localhost[127.0.0.1]
Sep 21 05:18:13 raptor postfix/cleanup[10500]: 5CE8911EA: 
message-id=<025501c37fd3$98a82810$0200a8c0 at kd1>

[...]

Sep 21 05:26:03 raptor amavis[13449]: (13449-03) mail_via_smtp: NOTICE: 
aborting SMTP session, timed out
Sep 21 05:26:03 raptor amavis[13449]: (13449-03) mail_via_smtp: 450 4.4.2 
Timed out during fwd-data, id=13449-03
Sep 21 05:26:03 raptor amavis[13449]: (13449-03) Not-Delivered, <foo at bar.tld> 
-> <postmaster at foobar.tld>, Message-ID: <025501c37fd3$98a8
2810$0200a8c0 at kd1>, Hits: -
Sep 21 05:26:03 raptor amavis[13449]: (13449-03) TIMING [total 482908 ms] - 
SMTP EHLO: 3 (0%), SMTP pre-MAIL: 1 (0%), SMTP pre-DATA-flush: 5 (0%), SMTP 
DATA
: 4980 (1%), body hash: 680 (0%), mime_decode: 5056 (1%), get-file-type: 53 
(0%), get-file-type: 54 (0%), get-file-type: 11 (0%), get-file-type: 12 (0%), 
ge
t-file-type: 12 (0%), get-file-type: 11 (0%), get-file-type: 62 (0%), 
get-file-type: 14 (0%), get-file-type: 12 (0%), get-file-type: 14 (0%), 
get-file-type:
 12 (0%), get-file-type: 12 (0%), get-file-type: 11 (0%), decompose_part: 4 
(0%), decompose_part: 0 (0%), decompose_part: 0 (0%), decompose_part: 0 (0%), 
de
compose_part: 0 (0%), decompose_part: 0 (0%), decompose_part: 0 (0%), 
decompose_part: 0 (0%), decompose_part: 1 (0%), decompose_part: 0 (0%), 
decompose_part
: 0 (0%), decompose_part: 0 (0%), decompose_part: 0 (0%), parts: 0 (0%), 
AV-scan-1: 1673 (0%), fwd-connect: 119 (0%), fwd-mail-from: 5 (0%), 
fwd-rcpt-to: 74
 (0%), write-header: 16 (0%), fwd-rundown: 469915 (97%), unlink-13-files: 79 
(0...
Sep 21 05:26:03 raptor amavis[13449]: (13449-03) ...%), rundown: 2 (0%)
Sep 21 05:26:03 raptor postfix/smtp[14487]: 9ECF6FA4: 
to=<postmaster at foobar.tld>, relay=127.0.0.1[127.0.0.1], delay=11530, 
status=deferred (host 127.
0.0.1[127.0.0.1] said: 450 4.4.2 Timed out during fwd-data, id=13449-03)
Sep 21 05:28:36 raptor postfix/smtpd[14502]: lost connection after DATA from 
localhost[127.0.0.1]
Sep 21 05:28:40 raptor postfix/smtpd[14502]: disconnect from 
localhost[127.0.0.1]


und dann geht's von vorne los.. mail ist wieder in der queue...

dazu jetzt ein paar fragen:

wenn man die zeiten so sieht: 02:13 connect.. senden von 7.9mb um 5:18 
abgeschlossen -> 3 stunden? ist das nicht etwas viel..

wo ist der flaschenhals?

warum kommt ewig ein timeout? selbst bei mails die 'nur 1.6mb' gross sind..

was braucht ihr noch für angaben?

danke für jede hilfe..

gruß martin



hier auszüge aus der config:

master.cf
# ==========================================================================
# service type  private unpriv  chroot  wakeup  maxproc command + args
#               (yes)   (yes)   (yes)   (never) (50)
# ==========================================================================
smtp      inet  n       -       n       -       -       smtpd
smtp-amavis       unix  -       -       n       -       2       smtp
        -o smtpd_data_done_timeout=1200
        -o disable_dns_lookups=yes
127.0.0.1:10025 inet    n       -       n       -       -       smtpd
        -o mynetworks=127.0.0.0/8
        -o content_filter=
        -o local_recipient_maps=
        -o relay_recipient_maps=
        -o smtpd_restriction_classes=
        -o smtpd_client_restrictions=
        -o smtpd_helo_restrictions=
        -o smtpd_sender_restrictions=
        -o 
smtpd_recipient_restrictions=permit_mynetworks,reject_unauth_destination
        -o strict_rfc821_envelopes=yes



main.cf

content_filter = smtp-amavis:[127.0.0.1]:10024
mail_name = mail.xxxxx.de

# The message_size_limit parameter limits the total size in bytes of
message_size_limit = 102400000

# TLS
# Transport Layer Security
# STARTTLS wenn Postfix Server ist
#
smtpd_use_tls = yes
#smtpd_tls_auth_only = yes
smtpd_tls_key_file = /etc/postfix/ssl/serverKey.pem
smtpd_tls_cert_file = /etc/postfix/ssl/serverCert.pem
smtpd_tls_CAfile = /etc/postfix/ssl/dependenceCA.pem
smtpd_tls_loglevel = 1
smtpd_tls_received_header = no
smtpd_tls_session_cache_timeout = 3600s
tls_random_source = dev:/dev/urandom

# SASL SUPPORT FOR CLIENTS
#
# The following options set parameters needed by Postfix to enable
# Cyrus-SASL support for authentication of mailclients.
#
smtpd_sasl_auth_enable = yes
smtpd_sasl_security_options = noanonymous
smtpd_sasl_local_domain = $myhostname
#smtp_sasl_password_maps = hash:/etc/postfix/saslpass
broken_sasl_auth_clients = yes

access_map_reject_code       = 550
reject_code                  = 550
relay_domains_reject_code    = 550
invalid_hostname_reject_code = 501
#unknown_address_reject_code  = 554
unknown_hostname_reject_code = 554
#unknown_client_reject_code   = 554
maps_rbl_reject_code         = 550

maps_rbl_domains = relays.ordb.org

smtpd_client_restrictions =
  # Erlaubt den eigene IP's das relaying
    permit_mynetworks,
  # SMTP-Auth, SMTP-After-POP
    permit_sasl_authenticated,
    check_client_access hash:/etc/postfix/pop-before-smtp,
  # Blocken nach RBL
    reject_maps_rbl

smtpd_helo_restricitions =
    permit_mynetworks,
    permit_sasl_authenticated,
    check_client_access hash:/etc/postfix/pop-before-smtp,
    reject_maps_rbl,
    reject_invalid_hostname,
    reject_non_fqdn_hostname,
    reject_unknown_hostname,
    permit_naked_ip_address

smtpd_recipient_restrictions =
    permit_mynetworks,
    permit_sasl_authenticated,
    check_client_access hash:/etc/postfix/pop-before-smtp,
  # Blocken wenn nicht FQDN
    reject_non_fqdn_sender,
    reject_non_fqdn_recipient,
  # Blocken wenn Sender oder Empfänger weder A noch MX Record haben
    reject_unknown_sender_domain,
    reject_unknown_recipient_domain,
  # Blocken wenn Zieladresse nicht bekannt
    reject_unauth_destination,
  # Blockt Pipelinig wenn vorher keine Abfrage erfolgte
    reject_unauth_pipelining,
  # Blocken wenn nach HELO/EHLO ungültige Angaben gemacht werden
    reject_invalid_hostname,
  # Blocken wenn Hostname nicht FQGN ist
    reject_non_fqdn_hostname,
  # Gesperrte Sender
    # check_sender_access hash:/etc/postfix/sender_access,
  # Blocken nach RBL
    reject_maps_rbl

#
#

virtual_mailbox_base=/var/spool/virtual
virtual_mailbox_limit = 102400000
virtual_mailbox_maps=mysql:/etc/postfix/mysql_virt.mysql
virtual_uid_maps=mysql:/etc/postfix/uids.mysql
virtual_gid_maps=mysql:/etc/postfix/gids.mysql
virtual_maps =  mysql:/etc/postfix/virtual.mysql,
                hash:/etc/postfix/virtual

transport_maps = mysql:/etc/postfix/transport.mysql,
                 hash:/etc/postfix/transport

mydestination = $myhostname, localhost.$mydomain, $transport_maps
relay_domains = $mydestination




Mehr Informationen über die Mailingliste Postfixbuch-users