[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