[Postfixbuch-users] Spam Problem

[Mario Duve]

Ralf Hildebrandt wrote:
>> * Ralf Hildebrandt <Ralf.Hildebrandt at charite.de>:
>>> * Mario Duve <list-debian at nomagic.de>:
>>>
>>>> So, jetzt steht folgendes in meiner master.cf:
>>>>
>>>> smtp      inet  n       -       n       -       -       smtpd
>>>>   -o smtpd_proxy_filter=127.0.0.1:10024
>>>
>>> Alles, was per SMTP reinkommt auf Port 25 geht an 127.0.0.1:10024
>>> Gut
>>
>> Läuft das jetzt?

Anbei mal das log mit vollem debug von einer Mailzustellung. Was mich
in diesem log irritiert, ist der Eintrag:

Aug 18 16:04:04 ns2 postfix/qmgr[14904]: 99DF53F842: from=<postmaster at nameslave.net>, size=263, nrcpt=1 (queue active)
Aug 18 16:04:05 ns2 postfix/smtp[14981]: 99DF53F842: to=<technik at net-art.de>, relay=mail.net-art.de[194.174.237.130],
delay=1, status=deliverable (250 2.1.5 <technik at net-art.de>... Recipient ok)

Was passiert da genau? Sehe ich das richtig, das versucht wird, ob der Sender auch OK ist?

Gruss, mario
-------------- nächster Teil --------------
Aug 18 16:04:03 ns2 postfix/smtpd[14978]: connect from mail.net-art.de[194.174.237.130]
Aug 18 16:04:03 ns2 amavis[14114]: (14114-06) lookup_ip_acl: key="127.0.0.1" matches "127/8", result=1
Aug 18 16:04:03 ns2 amavis[14114]: (14114-06) prolong_timer after new request - timer reset: remaining time = 300 s
Aug 18 16:04:03 ns2 amavis[14114]: (14114-06) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Aug 18 16:04:03 ns2 amavis[14114]: (14114-06) prolong_timer after reading SMTP command: remaining time = 300 s
Aug 18 16:04:03 ns2 amavis[14114]: (14114-06) SMTP< EHLO ns2.nameslave.net\r\n
Aug 18 16:04:03 ns2 amavis[14114]: (14114-06) ESMTP> 250-[127.0.0.1]
Aug 18 16:04:03 ns2 amavis[14114]: (14114-06) ESMTP> 250-PIPELINING
Aug 18 16:04:03 ns2 amavis[14114]: (14114-06) ESMTP> 250-SIZE
Aug 18 16:04:03 ns2 amavis[14114]: (14114-06) ESMTP> 250-8BITMIME
Aug 18 16:04:03 ns2 amavis[14114]: (14114-06) ESMTP> 250 ENHANCEDSTATUSCODES
Aug 18 16:04:03 ns2 amavis[14114]: (14114-06) prolong_timer after reading SMTP command: remaining time = 300 s
Aug 18 16:04:03 ns2 amavis[14114]: (14114-06) ESMTP< MAIL From:<technik at net-art.de> SIZE=609\r\n
Aug 18 16:04:03 ns2 amavis[14114]: (14114-06) prolong_timer after MAIL FROM received - timer reset: remaining time = 300 s
Aug 18 16:04:03 ns2 amavis[14114]: (14114-07) lookup_acl: key="technik at net-art.de", no match
Aug 18 16:04:03 ns2 amavis[14114]: (14114-07) ESMTP> 250 2.1.0 Sender technik at net-art.de OK
Aug 18 16:04:04 ns2 postfix/cleanup[14980]: 99DF53F842: message-id=<20030818160404.99DF53F842 at ns2.nameslave.net>
Aug 18 16:04:04 ns2 postfix/qmgr[14904]: 99DF53F842: from=<postmaster at nameslave.net>, size=263, nrcpt=1 (queue active)
Aug 18 16:04:05 ns2 postfix/smtp[14981]: 99DF53F842: to=<technik at net-art.de>, relay=mail.net-art.de[194.174.237.130], delay=1, status=deliverable (250 2.1.5 <technik at net-art.de>... Recipient ok)
Aug 18 16:04:07 ns2 amavis[14114]: (14114-07) prolong_timer after reading SMTP command: remaining time = 297 s
Aug 18 16:04:07 ns2 amavis[14114]: (14114-07) ESMTP< RCPT To:<mario at duve.biz>\r\n
Aug 18 16:04:07 ns2 amavis[14114]: (14114-07) ESMTP> 250 2.1.5 Recipient mario at duve.biz OK
Aug 18 16:04:07 ns2 amavis[14114]: (14114-07) prolong_timer after reading SMTP command: remaining time = 297 s
Aug 18 16:04:07 ns2 amavis[14114]: (14114-07) ESMTP< DATA\r\n
Aug 18 16:04:07 ns2 amavis[14114]: (14114-07) prolong_timer after DATA received - timer reset: remaining time = 300 s
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) ESMTP::10024 /var/amavis/tmp/amavis-20030818T093128-14114: <technik at net-art.de> -> <mario at duve.biz> Received: SIZE=609 from ns2.nameslave.net ([127.0.0.1]) by localhost (ns2.nameslave.net [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 14114-07 for <mario at duve.biz>; Mon, 18 Aug 2003 16:04:03 +0000 (UTC)
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) ESMTP> 354 End data with <CR><LF>.<CR><LF>
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) ESMTP< .\r\n
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) body hash: 2228e977ebea8966e27929f43e39cb67
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) Original mail size: 757; quota set to: 378500 bytes
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) Checking: <technik at net-art.de> -> <mario at duve.biz>
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) lookup_acl: key="mario at duve.biz", no match
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) lookup_acl: key="mario at duve.biz", no match
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) Extracting mime components
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) Issued a new file name: part-00001
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) mime_decode: Content-type: text/plain, name:
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) Charging 3 bytes to remaining quota 378500 (out of 378500, (0%)) - by mime_decode
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) prolong_timer after mime_decode-1: remaining time = 300 s
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) Checking for banned MIME types and names
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) check_for_banned - mime-type: text/plain
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) lookup_RE: key="text/plain", no match
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) lookup_acl: key="mario at duve.biz", no match
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) decode_parts: level=1, #parts=1 : part-00001
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) run_command: [14982] /usr/bin/file /var/amavis/tmp/amavis-20030818T093128-14114/parts/part-00001 </dev/null 2>/dev/null
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) File-type of part-00001: ASCII text; (.asc)
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) lookup_acl: key="mario at duve.biz", no match
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) Checking for banned (contents-based) file types, 1 parts
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) check_for_banned (part-00001) - file type: .asc
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) lookup_RE: key=".asc", no match
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) check_for_banned (part-00001) - file type: ASCII text
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) lookup_RE: key="ASCII text", no match
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) do_ascii: Decoding part part-00001 (0 items)
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) decompose_part: part-00001 - atomic
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) prolong_timer after decoding: remaining time = 300 s
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) WARN: all primary virus scanners failed, considering backups
Aug 18 16:04:08 ns2 amavis[14114]: (14114-07) Using FRISK F-Prot Antivirus: /usr/local/bin/f-prot -dumb -archive -packed /var/amavis/tmp/amavis-20030818T093128-14114/parts
Aug 18 16:04:09 ns2 amavis[14114]: (14114-07) run_command: [14983] /usr/local/bin/f-prot -dumb -archive -packed /var/amavis/tmp/amavis-20030818T093128-14114/parts </dev/null 2>&1
Aug 18 16:04:09 ns2 amavis[14114]: (14114-07) run_av: /usr/local/bin/f-prot status=0 (0 ),Virus scanning report  -  18 August 2003 @ 16:04\n\nF-PROT ANTIVIRUS\nProgram version: 4.1.2\nEngine version: 3.13.4\n\nVIRUS SIGNATURE FILES\nSIGN.DEF created 13 August 2003\nSIGN2.DEF created 13 August 2003\nMACRO.DEF created 11 August 2003\n\nSearch: /var/amavis/tmp/amavis-20030818T093128-14114/parts\nAction: Report only\nFiles: "Dumb" scan of all files\nSwitches: -ARCHIVE -PACKED\n\n\nResults of virus scanning:\n\nFiles: 1\nMBRs: 0\nBoot sectors: 0\nObjects scanned: 1\n\nTime: 0:00\n\nNo viruses or suspicious files/boot sectors were found.
Aug 18 16:04:09 ns2 amavis[14114]: (14114-07) run_av: clean
Aug 18 16:04:09 ns2 amavis[14114]: (14114-07) prolong_timer after virus_scan: remaining time = 300 s
Aug 18 16:04:09 ns2 amavis[14114]: (14114-07) white_black_list: checking sender <technik at net-art.de>
Aug 18 16:04:09 ns2 amavis[14114]: (14114-07) lookup_acl: key="technik at net-art.de", no match
Aug 18 16:04:09 ns2 amavis[14114]: (14114-07) lookup_RE: key="technik at net-art.de", no match
Aug 18 16:04:09 ns2 amavis[14114]: (14114-07) lookup_hash: key="technik at net-art.de", no match
Aug 18 16:04:09 ns2 amavis[14114]: (14114-07) lookup_hash: key="technik@", no match
Aug 18 16:04:09 ns2 amavis[14114]: (14114-07) lookup_hash: key="net-art.de", no match
Aug 18 16:04:09 ns2 amavis[14114]: (14114-07) lookup_hash: key=".net-art.de", no match
Aug 18 16:04:09 ns2 amavis[14114]: (14114-07) lookup_hash: key=".de", no match
Aug 18 16:04:09 ns2 amavis[14114]: (14114-07) lookup_hash: key=".", no match
Aug 18 16:04:09 ns2 amavis[14114]: (14114-07) lookup_acl: key="technik at net-art.de", no match
Aug 18 16:04:09 ns2 amavis[14114]: (14114-07) lookup_acl: key="mario at duve.biz", no match
Aug 18 16:04:09 ns2 amavis[14114]: (14114-07) CALLING NoMailAudit::check
Aug 18 16:04:10 ns2 amavis[14114]: (14114-07) RETURNED FROM NoMailAudit::check, time left: 20 s
Aug 18 16:04:10 ns2 amavis[14114]: (14114-07) prolong_timer after spam_scan_SA: remaining time = 300 s
Aug 18 16:04:10 ns2 amavis[14114]: (14114-07) spam_scan: hits=0 tests=
Aug 18 16:04:10 ns2 amavis[14114]: (14114-07) prolong_timer after spam_scan: remaining time = 300 s
Aug 18 16:04:10 ns2 amavis[14114]: (14114-07) lookup: (scalar) matches, result="8"
Aug 18 16:04:10 ns2 amavis[14114]: (14114-07) prolong_timer after deal_with_spam: remaining time = 300 s
Aug 18 16:04:10 ns2 amavis[14114]: (14114-07) header: X-Virus-Scanned: by ns.nameslave.net\n
Aug 18 16:04:10 ns2 amavis[14114]: (14114-07) lookup_acl: key="mario at duve.biz", no match
Aug 18 16:04:10 ns2 amavis[14114]: (14114-07) lookup: (scalar) matches, result="3"
Aug 18 16:04:10 ns2 amavis[14114]: (14114-07) lookup: (scalar) matches, result="6.3"
Aug 18 16:04:10 ns2 amavis[14114]: (14114-07) headers CLUSTERING: NEW CLUSTER <mario at duve.biz>: hits=0.0, tag=0, tag2=0, subj=0, local=0, bl=0
Aug 18 16:04:10 ns2 amavis[14114]: (14114-07) headers CLUSTERING: done all 1 recips in one go
Aug 18 16:04:10 ns2 amavis[14114]: (14114-07) FWD via SMTP: [127.0.0.1:10025] <technik at net-art.de> -> <mario at duve.biz>
Aug 18 16:04:11 ns2 postfix/smtpd[14984]: connect from localhost[127.0.0.1]
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) Remote host introduces itself as: ESMTP
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) prolong_timer after fwd-connect: remaining time = 300 s
Aug 18 16:04:11 ns2 postfix/smtpd[14984]: 17F153F842: client=localhost[127.0.0.1]
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) prolong_timer after fwd-mail-from: remaining time = 300 s
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) prolong_timer after fwd-rcpt-to: remaining time = 300 s
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) response to DATA: "354 End data with <CR><LF>.<CR><LF>"
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) prolong_timer after fwd-data: remaining time = 300 s
Aug 18 16:04:11 ns2 postfix/cleanup[14980]: 17F153F842: message-id=<00a001c365a2$b9616120$0801a8c0 at pcmario>
Aug 18 16:04:11 ns2 postfix/qmgr[14904]: 17F153F842: from=<technik at net-art.de>, size=988, nrcpt=1 (queue active)
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) prolong_timer after fwd-data-end: remaining time = 300 s
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) response to data end: "250 Ok: queued as 17F153F842"
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) prolong_timer after fwd-rundown-1: remaining time = 300 s
Aug 18 16:04:11 ns2 postfix/smtpd[14984]: disconnect from localhost[127.0.0.1]
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) mail_via_smtp: 250 2.6.0 Ok, id=14114-07, from MTA: 250 Ok: queued as 17F153F842
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) prolong_timer after forwarding: remaining time = 300 s
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) one_response_for_all <technik at net-art.de>: success, dsn_needed=0, '250 2.6.0 Ok, id=14114-07, from MTA: 250 Ok: queued as 17F153F842'
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) warnsender_with_pass=, dsn_needed=0, exit=0, 250 2.6.0 Ok, id=14114-07, from MTA: 250 Ok: queued as 17F153F842
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) prolong_timer after delivery-notification: remaining time = 300 s
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) Passed, <technik at net-art.de> -> <mario at duve.biz>, Message-ID: <00a001c365a2$b9616120$0801a8c0 at pcmario>, Hits: 0
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) sending SMTP response: "250 2.6.0 Ok, id=14114-07, from MTA: 250 Ok: queued as 17F153F842"
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) rmdir_recursively: /var/amavis/tmp/amavis-20030818T093128-14114/parts, excl=1
Aug 18 16:04:11 ns2 postfix/local[14985]: 17F153F842: to=<mario at duve.biz>, relay=local, delay=0, status=sent (delivered to maildir)
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) TIMING [total 7932 ms] - SMTP EHLO: 163 (2%), SMTP pre-MAIL: 21 (0%), SMTP pre-DATA-flush: 4274 (54%), SMTP DATA: 19 (0%), body hash: 22 (0%), mime_decode: 506 (6%), get-file-type: 269 (3%), decompose_part: 92 (1%), parts: 0 (0%), AV-scan-1: 382 (5%), SA msg read: 62 (1%), SA parse: 59 (1%), SA check: 1185 (15%), fwd-connect: 471 (6%), fwd-mail-from: 13 (0%), fwd-rcpt-to: 12 (0%), write-header: 28 (0%), fwd-data: 0 (0%), fwd-data-end: 111 (1%), fwd-rundown: 10 (0%), unlink-1-files: 152 (2%), rundown: 83 (1%)
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) ESMTP> 250 2.6.0 Ok, id=14114-07, from MTA: 250 Ok: queued as 17F153F842
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) ESMTP: NOTICE: client broke the connection without a QUIT
Aug 18 16:04:11 ns2 postfix/smtpd[14978]: disconnect from mail.net-art.de[194.174.237.130]
Aug 18 16:04:11 ns2 amavis[14114]: (14114-07) timer stopped after DATA end