[Postfixbuch-users] Verzögerte Zustellung von Mail bei Einbindung des Amavis über Policy-Filter

Martin Wibbing mwibbing at bfs.de
Fr Mai 3 17:55:03 CEST 2013


Hallo,



ich setze gerade ein Mail-Gateway auf und möchte den Amavis als 
smtpd_proxy_filter einbinden. Dabei habe ich eine Verzögerung bei der 
Zustellung der Mail von ca 5 Sekunden.
Ich teste im moment noch mit
smtp-source -s 10 -l 5000 -t test at example.com  -f test at example.eu -C 1 
-S "Subject: Testmail vom `date "+%d.%m.%y %H:%M - "   ` " 
mx01-sz.example.com

Eingebunden habe ich den Amavis mit:
smtp      inet  n       -       n       -       -       smtpd
   -o smtpd_proxy_filter=localhost:10024
   -o content_filter=

127.0.0.1:10025 inet n  -               n         -               -      
smtpd
         -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
         -o mynetworks=127.0.0.0/8
         -o smtpd_authorized_xforward_hosts=127.0.0.0/8
         -o strict_rfc821_envelopes=yes
         -o smtpd_error_sleep_time=0
         -o smtpd_soft_error_limit=1001
         -o smtpd_hard_error_limit=1000

In der Mail Log steht:
May  3 17:40:54 mx01-sz postfix/smtpd[2421]: connect from 
server01.example.eu[123.102.10.123]
May  3 17:40:55 mx01-sz amavis[2288]: process_request: fileno sock=10, 
STDIN=0, STDOUT=1
May  3 17:40:55 mx01-sz postfix/smtpd[2421]: NOQUEUE: 
client=server01.example.eu[123.102.10.123]
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) ESMTP::10024 
/var/spool/amavisd/tmp/amavis-20130503T173237-02288-L5rXHPJR: 
<test at example.eu> -> <test at example.com> Received: from 
mx01-sz.example.com ([127.0.0.1]) by localhost (mx01-sz.example.com 
[127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <test at example.com>; F
ri,  3 May 2013 17:40:55 +0200 (CEST)
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) smtp connection cache, 
dt: 489.9, state: 1
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) smtp connection cache, 
dt: 489.9 -> disabling
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) body hash: 
b543b36740b7b7976ab76a2e0a3a93b1
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) Checking: fX3EVe9VBEo1 
[123.102.10.123] <test at example.eu> -> <test at example.com>
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) 2822.From: 
<test at example.eu>
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) p001 1 Content-Type: 
text/plain, size: 4939 B, name:
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) inspect_dsn: not a bounce
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) Checking for banned 
types and filenames
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) collect banned 
table[0]: test at example.com, tables: 
DEFAULT=>Amavis::Lookup::RE=ARRAY(0x2b83d48)
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) p.path 
test at example.com: "P=p001,L=1,M=text/plain,T=asc"
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) presenting full 
original message to scanners as 
/var/spool/amavisd/tmp/amavis-20130503T173237-02288-L5rXHPJ
R/parts/p002
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) run_av Using 
(ClamAV-clamd): (code) CONTSCAN 
/var/spool/amavisd/tmp/amavis-20130503T173237-02288-L5rXHPJR/p
arts\n
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) ClamAV-clamd: 
Connecting to socket  /var/run/clamav/clamd.sock
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) new socket by 
IO::Socket::UNIX to /var/run/clamav/clamd.sock, timeout 10
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) ClamAV-clamd: Sending 
CONTSCAN 
/var/spool/amavisd/tmp/amavis-20130503T173237-02288-L5rXHPJR/parts\n to sock
et /var/run/clamav/clamd.sock
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) rw_loop read: got eof
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) run_av (ClamAV-clamd): 
CLEAN
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) run_av (ClamAV-clamd) 
result: clean
May  3 17:40:55 mx01-sz amavis[2288]: (02288-02) calling SA parse (0), 
SA vers 3.3.2, 3.003002, data as STRING, recips_ind [0], user: "amavis"
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) spam_scan: score=-1.392 
autolearn=ham tests=[RP_MATCHES_RCVD=-2.581,UPPERCASE_75_100=1.189] recips=0
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) do_notify_and_quar: 
ccat=Clean (1,0) ("1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) delivery method is 1, 
recips: test at example.com
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) smtp session reuse 
(smtp:[127.0.0.1]:10025), 1 transactions so far
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) smtp cmd> NOOP
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) smtp resp to NOOP (idle 
495.4 s): 421 4.4.2 mx01-sz.example.com Error: timeout exceeded
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) 
Amavis::Out::SMTP::Session close, disconnecting
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) new socket using 
IO::Socket::INET to [127.0.0.1]:10025, timeout 35
May  3 17:41:00 mx01-sz postfix/smtpd[2430]: connect from 
localhost[127.0.0.1]
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) smtp greeting: 220 
mx01-sz.example.com ESMTP Postfix, dt: 7.5 ms
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) smtp cmd> EHLO localhost
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) smtp resp to EHLO: 250 
mx01-sz.example.com\nPIPELINING\nSIZE 10240000\nVRFY\nETRN\nXFORWARD 
NAME ADDR PROTO HELO SOURCE PORT\nENHANCEDSTATUSCODES\n8BITMIME\nDSN
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) smtp cmd> XFORWARD 
ADDR=123.102.10.123 NAME=server01.example.eu PORT=47256 PROTO=SMTP 
HELO=server01.example.eu SOURCE=REMOTE
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) smtp resp to XFORWARD: 
250 2.0.0 Ok
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) AUTH not needed, 
user='', MTA offers ''
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) smtp cmd> MAIL 
FROM:<test at example.eu> BODY=7BIT
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) smtp cmd> RCPT 
TO:<test at example.com>
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) smtp cmd> DATA
May  3 17:41:00 mx01-sz postfix/smtpd[2430]: C15B5EE1: 
client=server01.example.eu[123.102.10.123]
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) smtp resp to MAIL 
(pip): 250 2.1.0 Ok
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) smtp resp to RCPT (pip) 
(<test at example.com>): 250 2.1.5 Ok
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) smtp resp to DATA: 354 
End data with <CR><LF>.<CR><LF>
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) smtp cmd> QUIT
May  3 17:41:00 mx01-sz postfix/cleanup[2431]: C15B5EE1: 
message-id=<75c0.0003.fffffff7 at server01.example.eu>
May  3 17:41:00 mx01-sz postfix/smtpd[2430]: disconnect from 
localhost[127.0.0.1]
May  3 17:41:00 mx01-sz postfix/qmgr[2382]: C15B5EE1: 
from=<test at example.eu>, size=5797, nrcpt=1 (queue active)
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) smtp resp to data-dot 
(<test at example.com>): 250 2.0.0 Ok: queued as C15B5EE1, dt: 6.8 ms
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) 
Amavis::Out::SMTP::Session close, disconnecting
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) FWD from 
<test at example.eu> -> <test at example.com>,BODY=7BIT 250 2.0.0 from 
MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as C15B5EE1
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) status counters: 
InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInbound}
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) Passed CLEAN 
{RelayedInbound}, [123.102.10.123]:47256 [123.102.10.123] 
<test at example.eu> -> <test at example.com>, Message-ID: 
<75c0.0003.fffffff7 at server01.example.eu>, mail_id: fX3EVe9VBEo1, Hits: 
-1.392, size: 5382, queued_as: C15B5EE1, 5519 ms
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) TIMING-SA total 5371 ms 
- parse: 1.42 (0.0%), extract_message_metadata: 28 (0.5%), 
poll_dns_idle: 20 (0.4%), get_uri_detail_list: 6 (0.1%), 
tests_pri_-1000: 12 (0.2%), tests_pri_-950: 1.37 (0.0%), tests_pri_-900: 
1.50 (0.0%), tests_pri_-400: 1.20 (0.0%), tests_pri_0: 5264 (98.0%), 
check_dkim_adsp: 8 (0.1%), check_spf: 13 (0.2%), check_razor2: 5001 
(93.1%), check_pyzor: 0.23 (0.0%), tests_pri_500: 3 (0.1%), learn: 32 
(0.6%), get_report: 2 (0.0%)
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) sending SMTP response: 
"250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 
C15B5EE1"
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) size: 5382, TIMING 
[total 5524 ms] - SMTP greeting: 2 (0%)0, SMTP EHLO: 1 (0%)0, SMTP 
pre-MAIL: 0 (0%)0, SMTP pre-DATA-flush: 21 (0%)0, SMTP DATA: 60 (1%)2, 
check_init: 1 (0%)2, digest_hdr: 1 (0%)2, digest_body_dkim: 0 (0%)2, 
mime_decode: 6 (0%)2, get-file-type1: 11 (0%)2, parts_decode: 0 (0%)2, 
check_header: 0 (0%)2, AV-scan-1: 6 (0%)2, spam-wb-list: 1 (0%)2, SA msg 
read: 1 (0%)2, SA parse: 2 (0%)2, SA check: 5361 (97%)99, 
decide_mail_destiny: 10 (0%)99, notif-quar: 1 (0%)99, fwd-connect: 12 
(0%)99, fwd-xforward: 1 (0%)100, fwd-mail-pip: 8 (0%)100, fwd-rcpt-pip: 
0 (0%)100, fwd-data-chkpnt: 0 (0%)100, write-header: 1 (0%)100, 
fwd-data-contents: 0 (0%)100, fwd-end-chkpnt: 8 (0%)100, prepare-dsn: 1 
(0%)100, main_log_entry: 7 (0%)100, update_snmp: 2 (0%)100, SMTP 
pre-response: 0 (0%)100, SMTP response: 0 (0%)100, unlink-2-files: 0 
(0%)100, rundown: 0 (0%)100
May  3 17:41:00 mx01-sz amavis[2288]: (02288-02) load: 3 %, total idle 
490.217 s, busy 13.525 s
May  3 17:41:00 mx01-sz postfix/smtp[2432]: C15B5EE1: 
to=<test at example.com>,relay=10.10.10.10[10.10.10.10]:25:25, delay=0.03, 
delays=0.01/0.01/0/0.01, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 
D439361440)
May  3 17:41:00 mx01-sz postfix/qmgr[2382]: C15B5EE1: removed
May  3 17:41:00 mx01-sz postfix/smtpd[2421]: disconnect from 
server01.example.eu[123.102.10.123]

Was ist eine normale Verzögerung. Wo kann das Problem liegen ?

MIt freundlichen Grüßen

Martin WIbbing




Mehr Informationen über die Mailingliste Postfixbuch-users