[Postfixbuch-users] amavis: Timeout FWD via SMTP

[Ralf Ebeling]

Hi,

habe hier ein kleines Problem mit einer groesseren Mail. Wenn amavisd-new
(debian; amavisd-new 20030616p3-1) die Mail via SMTP an postfix weiter-
gereicht, endet dieses immer in einem Timeout (s.a. angehaengtes Log).

Wenn ich das Log richtig interpretiere ist amavisd hier das Problem
und weniger postfix.

In amavisd.conf habe ich nur '$child_timeout=5*60;' gefunden. Wenn man
dann in 'sub prolong_timer($;$) {' nachsieht, wird hier ein Timeout aber
mit 60 Sekunden restartet?!?

Habe ich irgendwo was übersehen oder ist es tatsaechlich der Restart mit
60 Sekunden, der das Problem verursacht?

Ralf
-------------- nächster Teil --------------
Aug  7 12:52:45 amavis[9701]: DEBUG_ONESHOT: TURNED ON
Aug  7 12:52:45 amavis[9701]: ESMTP< MAIL FROM:<from at domain.tld> SIZE=17988244\r\n
Aug  7 12:52:45 amavis[9701]: ESMTP> 250 2.1.0 Sender from at domain.tld OK
Aug  7 12:52:45 amavis[9701]: prolong_timer after reading SMTP command: remaining time = 0.000 s
Aug  7 12:52:45 amavis[9701]: ESMTP< RCPT TO:<to at domain.tld>\r\n
Aug  7 12:52:45 amavis[9701]: ESMTP> 250 2.1.5 Recipient to at domain.tld OK
Aug  7 12:52:45 amavis[9701]: prolong_timer after reading SMTP command: remaining time = 0.000 s
Aug  7 12:52:45 amavis[9701]: ESMTP< DATA\r\n
Aug  7 12:52:45 amavis[9701]: prolong_timer after DATA received - timer reset: remaining time = 480.000 s
Aug  7 12:52:45 amavis[9701]: ESMTP:[192.168.100.70]:10024 /var/lib/amavis/tmp/amavis-20030807T125245-09701: <from at domain.tld> -> <to at domain.tld> Received: SIZE=17988244 from mta at domain.tld ([192.168.100.70]) by localhost (mta at domain.tld [192.168.100.70]) (amavisd-new, port 10024) with ESMTP id 09701-01 for <to at domain.tld>; Thu,  7 Aug 2003 12:52:45 +0200 (CEST)
Aug  7 12:52:45 amavis[9701]: ESMTP> 354 End data with <CR><LF>.<CR><LF>
Aug  7 12:52:47 amavis[9701]: ESMTP< .\r\n
Aug  7 12:52:47 amavis[9701]: body hash: c93ef70f1b76209cfe643fd2b2e708ed
Aug  7 12:52:47 amavis[9701]: Original mail size: 17757593; quota set to: 314572800 bytes
Aug  7 12:52:47 amavis[9701]: Checking: <from at domain.tld> -> <to at domain.tld>
Aug  7 12:52:47 amavis[9701]: lookup_acl: key="to at domain.tld", no match
Aug  7 12:52:47 amavis[9701]: lookup_acl: key="to at domain.tld", no match
Aug  7 12:52:47 amavis[9701]: Extracting mime components
Aug  7 12:52:47 amavis[9701]: Issued a new file name: part-00001
Aug  7 12:52:48 amavis[9701]: Issued a new file name: part-00002
Aug  7 12:52:49 amavis[9701]: mime_decode: Content-type: multipart/mixed
Aug  7 12:52:49 amavis[9701]: mime_decode_epilogue: 1 lines
Aug  7 12:52:49 amavis[9701]: mime_decode: Content-type: text/plain, name:
Aug  7 12:52:49 amavis[9701]: Charging 1675 bytes to remaining quota 314572800 (out of 314572800, (0%)) - by mime_decode
Aug  7 12:52:49 amavis[9701]: mime_decode: Content-type: application/octet-stream, name: =?iso-8859-1?Q?Bilder.zip.asc?=
Aug  7 12:52:49 amavis[9701]: Charging 13142661 bytes to remaining quota 314571125 (out of 314572800, (4%)) - by mime_decode
Aug  7 12:52:49 amavis[9701]: prolong_timer after mime_decode: remaining time = 0.000 s
Aug  7 12:52:49 amavis[9701]: Checking for banned MIME types and names
Aug  7 12:52:49 amavis[9701]: check_for_banned - mime-type: multipart/mixed
Aug  7 12:52:49 amavis[9701]: lookup_RE: key="multipart/mixed", no match
Aug  7 12:52:49 amavis[9701]: check_for_banned - mime-type: text/plain
Aug  7 12:52:49 amavis[9701]: lookup_RE: key="text/plain", no match
Aug  7 12:52:49 amavis[9701]: check_for_banned - mime-type: application/octet-stream
Aug  7 12:52:49 amavis[9701]: check_for_banned - declared names: =?iso-8859-1?Q?Bilder.zip.asc?=, Bilder.zip.asc
Aug  7 12:52:49 amavis[9701]: lookup_RE: key="application/octet-stream", no match
Aug  7 12:52:49 amavis[9701]: lookup_RE: key="=?iso-8859-1?Q?Bilder.zip.asc?=", no match
Aug  7 12:52:49 amavis[9701]: lookup_RE: key="Bilder.zip.asc", no match
Aug  7 12:52:49 amavis[9701]: lookup_acl: key="to at domain.tld", no match
Aug  7 12:52:49 amavis[9701]: decode_parts: level=1, #parts=2 : part-00001, part-00002
Aug  7 12:52:49 amavis[9701]: run_command: [9941] /usr/bin/file /var/lib/amavis/tmp/amavis-20030807T125245-09701/parts/part-00001 </dev/null 2>/dev/null
Aug  7 12:52:49 amavis[9701]: File-type of part-00001: ISO-8859 text; (.txt)
Aug  7 12:52:49 amavis[9701]: run_command: [9942] /usr/bin/file /var/lib/amavis/tmp/amavis-20030807T125245-09701/parts/part-00002 </dev/null 2>/dev/null
Aug  7 12:52:49 amavis[9701]: File-type of part-00002: PGP armored text message
Aug  7 12:52:49 amavis[9701]: lookup_acl: key="to at domain.tld", no match
Aug  7 12:52:49 amavis[9701]: Checking for banned (contents-based) file types, 2 parts
Aug  7 12:52:49 amavis[9701]: check_for_banned (part-00001) - file type: .txt
Aug  7 12:52:49 amavis[9701]: lookup_RE: key=".txt", no match
Aug  7 12:52:49 amavis[9701]: check_for_banned (part-00001) - file type: ISO-8859 text
Aug  7 12:52:49 amavis[9701]: lookup_RE: key="ISO-8859 text", no match
Aug  7 12:52:49 amavis[9701]: check_for_banned (part-00002) - file type: PGP armored text message
Aug  7 12:52:49 amavis[9701]: lookup_RE: key="PGP armored text message", no match
Aug  7 12:52:49 amavis[9701]: decompose_part: part-00001 - atomic
Aug  7 12:52:49 amavis[9701]: decompose_part: part-00002 - atomic
Aug  7 12:52:49 amavis[9701]: prolong_timer after decoding: remaining time = 0.000 s
Aug  7 12:52:49 amavis[9701]: Using ESET Software NOD32 - Client/Server Version: /usr/local/bin/nod32cli -a -r -d recurse --heur standard /var/lib/amavis/tmp/amavis-20030807T125245-09701/parts
Aug  7 12:52:49 amavis[9701]: run_command: [9943] /usr/local/bin/nod32cli -a -r -d recurse --heur standard /var/lib/amavis/tmp/amavis-20030807T125245-09701/parts </dev/null 2>&1
Aug  7 12:52:49 amavis[9701]: run_av: /usr/local/bin/nod32cli status=0 (0 ),
Aug  7 12:52:49 amavis[9701]: run_av: clean
Aug  7 12:52:49 amavis[9701]: prolong_timer after virus_scan: remaining time = 60.000 s
Aug  7 12:52:49 amavis[9701]: No anti-spam code loaded, skipping spam_scan
Aug  7 12:52:49 amavis[9701]: prolong_timer after deal_with_spam: remaining time = 0.000 s
Aug  7 12:52:49 amavis[9701]: header: Received: from mta at domain.tld ([192.168.100.70])\n by localhost (mta at domain.tld [192.168.100.70]) (amavisd-new, port 10024)\n with ESMTP id 09701-01 for <to at domain.tld>;\n Thu,  7 Aug 2003 12:52:45 +0200 (CEST)\n
Aug  7 12:52:49 amavis[9701]: header: X-Virus-Scanned: by amavisd-new at mta at domain.tld\n
Aug  7 12:52:49 amavis[9701]: headers CLUSTERING: done all 1 recips in one go
Aug  7 12:52:49 amavis[9701]: FWD via SMTP: [127.0.0.1:10025] <from at domain.tld> -> <to at domain.tld>
Aug  7 12:52:49 postfix/smtpd[9845]: connect from localhost[127.0.0.1]
Aug  7 12:52:49 amavis[9701]: Remote host claims to be mta at domain.tld
Aug  7 12:52:49 amavis[9701]: prolong_timer after fwd-connect: remaining time = 60.000 s
Aug  7 12:52:50 postfix/smtpd[9845]: 1D5E915A095: client=localhost[127.0.0.1]
Aug  7 12:52:50 amavis[9701]: prolong_timer after fwd-mail-from: remaining time = 0.000 s
Aug  7 12:52:50 amavis[9701]: prolong_timer after fwd-rcpt-to: remaining time = 0.000 s
Aug  7 12:52:50 amavis[9701]: response to DATA: "354 End data with <CR><LF>.<CR><LF>"
Aug  7 12:52:50 postfix/cleanup[9924]: 1D5E915A095: message-id=<any-msg-id-here>
Aug  7 12:53:50 amavis[9701]: prolong_timer after fwd-data: remaining time = 0.000 s
Aug  7 12:53:50 amavis[9701]: mail_via_smtp: session failed: timed out
Aug  7 12:53:50 amavis[9701]: mail_via_smtp: NOTICE: aborting SMTP session, timed out
Aug  7 12:53:50 amavis[9701]: mail_via_smtp: 450 4.4.2 Timed out during fwd-data, id=09701-01
Aug  7 12:53:50 amavis[9701]: prolong_timer after forwarding: remaining time = 0.000 s
Aug  7 12:53:50 amavis[9701]: one_response_for_all <from at domain.tld>: 4xx found, '450 4.4.2 Timed out during fwd-data, id=09701-01'
Aug  7 12:53:50 amavis[9701]: warnsender_with_pass=, dsn_needed=, exit=75, 450 4.4.2 Timed out during fwd-data, id=09701-01
Aug  7 12:53:50 amavis[9701]: prolong_timer after delivery-notification: remaining time = 0.000 s
Aug  7 12:53:50 amavis[9701]: Not-Delivered, <from at domain.tld> -> <to at domain.tld>, Message-ID: <any-msg-id-here>
Aug  7 12:53:50 amavis[9701]: DEBUG_ONESHOT CAUSES EVIDENCE TO BE PRESERVED
Aug  7 12:53:50 amavis[9701]: sending SMTP response: "450 4.4.2 Timed out during fwd-data, id=09701-01"
Aug  7 12:53:50 amavis[9701]: PRESERVING EVIDENCE in /var/lib/amavis/tmp/amavis-20030807T125245-09701
Aug  7 12:53:50 amavis[9701]: TIMING [total 64635 ms] - SMTP EHLO: 4 (0%), SMTP pre-MAIL: 1 (0%), mkdir tempdir: 0 (0%), create email.txt: 1 (0%), SMTP pre-DATA-flush: 5 (0%), SMTP DATA: 1702 (3%), body hash: 400 (1%), mkdir parts: 14 (0%), mime_decode: 1741 (3%), get-file-type: 20 (0%), get-file-type: 10 (0%), decompose_part: 2 (0%), decompose_part: 0 (0%), parts: 0 (0%), AV-scan-1: 13 (0%), fwd-connect: 10 (0%), fwd-mail-from: 699 (1%), fwd-rcpt-to: 2 (0%), write-header: 5 (0%), fwd-rundown: 59997 (93%), rundown: 9 (0%)
Aug  7 12:53:50 amavis[9701]: ESMTP> 450 4.4.2 Timed out during fwd-data, id=09701-01
Aug  7 12:53:50 amavis[9701]: prolong_timer after reading SMTP command: remaining time = 0.000 s
Aug  7 12:53:50 amavis[9701]: ESMTP< QUIT\r\n
Aug  7 12:53:50 amavis[9701]: ESMTP> 221 2.0.0 [192.168.100.70] (amavisd) closing transmission channel
Aug  7 12:53:50 amavis[9701]: DEBUG_ONESHOT: TURNED OFF
Aug  7 12:53:50 postfix/smtp[9840]: 9DC1D15A091: to=<to at domain.tdl>, relay=127.0.0.1[127.0.0.1], delay=-189, status=deferred (host 127.0.0.1[127.0.0.1] said: 450 4.4.2 Timed out during fwd-data, id=09701-01)
Aug  7 12:53:50 postfix/smtpd[9845]: lost connection after DATA from localhost[127.0.0.1]
Aug  7 12:53:50 postfix/smtpd[9845]: disconnect from localhost[127.0.0.1]