[Postfixbuch-users] Amavisproblem

Mi Mär 28 16:09:55 CEST 2012

Distribution Ubuntu 10.04 LTS

Versionen von postfix 2.7.0-1ubuntu0.2, amavisd-new 2.6.4-1ubuntu5, spamassassin 3.3.1-1, Virenscanner 0.96.5+dfsg-1ubuntu1.10.04.3

Softwarepakete aus Distri

Min 1 Gbit/s zwischen allen Systemen. Die Böse Layer 7 Fierwall ist in dem Fall im Spiel. Also sowohl wenn es langsam geht als auch wenn es schnell geht.

Amavis Log:

Mar 28 02:48:51 amavisServer amavis[25545]: (25545-06) ESMTP::10026 /var/lib/amavis/tmp/amavis-20120328T020011-25545: <emailSen> -> <EmailEmp> SIZE=7648556 Received: from mailserver ([mailserverIP]) by localhost (amavis [172.16.1.247]) (amavisd-new, port 10026) with ESMTP for <EmailEmp>; Wed, 28 Mar 2012 02:48:51 +0200 (CEST)
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) smtp connection cache, dt: 384.8, state: 0
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) body hash: 7adee408caa57ee2dc33e2f7ef3c50f0
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) Checking: hiHo6KceNBZX EXT [mailserverAbs] <emailEmp> -> <EmailEmp>
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) 2822.From: <emailSen>
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) p008 1 Content-Type: multipart/mixed
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) p009 1/1 Content-Type: multipart/alternative
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) p001 1/1/1 Content-Type: text/plain, size: 400 B, name:
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) p002 1/1/2 Content-Type: text/html, size: 3783 B, name:
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) p003 1/2 Content-Type: application/pdf, size: 1366792 B, name:.pdf
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) p004 1/3 Content-Type: application/pdf, size: 297629 B, name:.pdf
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) p005 1/4 Content-Type: application/pdf, size: 504943 B, name:.pdf
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) p006 1/5 Content-Type: application/pdf, size: 920844 B, name:.pdf
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) p007 1/6 Content-Type: application/pdf, size: 2493083 B, name:.pdf
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) Checking for banned types and filenames
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) collect banned table[0]: EmailEmp, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x1eabb90)
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) p.path EmailEmp: "P=p008,L=1,M=multipart/mixed | P=p003,L=1/2,M=application/pdf,T=pdf,N=.pdf"
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) p.path EmailEmp: "P=p008,L=1,M=multipart/mixed | P=p004,L=1/3,M=application/pdf,T=pdf,N=.pdf"
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) p.path EmailEmp: "P=p008,L=1,M=multipart/mixed | P=p005,L=1/4,M=application/pdf,T=pdf,N=.pdf"
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) p.path EmailEmp: "P=p008,L=1,M=multipart/mixed | P=p006,L=1/5,M=application/pdf,T=pdf,N=.pdf"
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) p.path EmailEmp: "P=p008,L=1,M=multipart/mixed | P=p007,L=1/6,M=application/pdf,T=pdf,N=.pdf"
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) p.path EmailEmp: "P=p008,L=1,M=multipart/mixed | P=p009,L=1/1,M=multipart/alternative | P=p001,L=1/1/1,M=text/plain,T=txt"
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) p.path EmailEmp: "P=p008,L=1,M=multipart/mixed | P=p009,L=1/1,M=multipart/alternative | P=p002,L=1/1/2,M=text/html,T=html"
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) ask_av Using (ClamAV-clamd): CONTSCAN /var/lib/amavis/tmp/amavis-20120328T020011-25545/parts\n
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) ClamAV-clamd: Connecting to socket  /var/run/clamav/clamd.ctl
Mar 28 02:49:21 amavisServer amavis[25545]: (25545-06) ClamAV-clamd: Sending CONTSCAN /var/lib/amavis/tmp/amavis-20120328T020011-25545/parts\n to UNIX socket /var/run/clamav/clamd.ctl
Mar 28 02:49:22 amavisServer amavis[25545]: (25545-06) run_av (ClamAV-clamd): CLEAN
Mar 28 02:49:22 amavisServer amavis[25545]: (25545-06) run_av (ClamAV-clamd) result: clean
Mar 28 02:49:22 amavisServer amavis[25545]: (25545-06) truncating a message passed to SA at 205941 bytes, orig 7647897
Mar 28 02:49:24 amavisServer amavis[25545]: (25545-06) spam_scan: score=-1.898 autolearn=unavailable tests=[BAYES_00=-1.9,CTYPE_001C_B=0.001,HTML_MESSAGE=0.001]
Mar 28 02:49:24 amavisServer amavis[25545]: (25545-06) do_notify_and_quar: ccat=Clean (1,0) ("1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
Mar 28 02:49:24 amavisServer amavis[25545]: (25545-06) dynamic destination: smtp:*:10025 -> smtp:[mailserverIP]:10025
Mar 28 02:49:24 amavisServer amavis[25545]: (25545-06) smtp session: setting up a new session
Mar 28 02:49:24 amavisServer amavis[25545]: (25545-06) smtp creating socket by IO::Socket::INET to [mailserverIP]:10025
Mar 28 02:49:24 amavisServer amavis[25545]: (25545-06) smtp resp to greeting: 220 mailserver ESMTP Postfix (Ubuntu)
Mar 28 02:49:24 amavisServer amavis[25545]: (25545-06) smtp cmd> EHLO localhost
Mar 28 02:49:24 amavisServer amavis[25545]: (25545-06) smtp resp to EHLO: 250 mailserver\nPIPELINING\nSIZE 104857600\nVRFY\nETRN\nSTARTTLS\nXFORWARD NAME ADDR PROTO HELO SOURCE PORT\nENHANCEDSTATUSCODES\n8BITMIME\nDSN
Mar 28 02:49:24 amavisServer amavis[25545]: (25545-06) smtp cmd> XFORWARD ADDR=mailserverAbs NAME=mailserverAbs PORT=39181 PROTO=ESMTP HELO=mailserverAbs SOURCE=REMOTE
Mar 28 02:49:24 amavisServer amavis[25545]: (25545-06) smtp resp to XFORWARD: 250 2.0.0 Ok
Mar 28 02:49:24 amavisServer amavis[25545]: (25545-06) AUTH not needed, user='', MTA offers ''
Mar 28 02:49:24 amavisServer amavis[25545]: (25545-06) smtp cmd> MAIL FROM:<emailSen> BODY=7BIT
Mar 28 02:49:24 amavisServer amavis[25545]: (25545-06) smtp cmd> RCPT TO:<EmailEmp>
Mar 28 02:49:24 amavisServer amavis[25545]: (25545-06) smtp cmd> DATA
Mar 28 02:49:24 amavisServer amavis[25545]: (25545-06) smtp resp to MAIL (pip): 250 2.1.0 Ok
Mar 28 02:49:24 amavisServer amavis[25545]: (25545-06) smtp resp to RCPT (pip) (<EmailEmp>): 250 2.1.5 Ok
Mar 28 02:49:24 amavisServer amavis[25545]: (25545-06) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
Mar 28 02:52:37 amavisServer amavis[25545]: (25545-06) smtp cmd> QUIT
Mar 28 02:52:42 amavisServer amavis[25545]: (25545-06) smtp resp to data-dot (<EmailEmp>): 250 2.0.0 Ok: queued as D90CB7FC30
Mar 28 02:52:42 amavisServer amavis[25545]: (25545-06) Amavis::Out::SMTP::Session close, disconnecting
Mar 28 02:52:42 amavisServer amavis[25545]: (25545-06) FWD via SMTP: <emailSen> -> <EmailEmp>,BODY=7BIT 250 2.0.0 from MTA([mailserverIP]:10025): 250 2.0.0 Ok: queued as D90CB7FC30
Mar 28 02:52:42 amavisServer amavis[25545]: (25545-06) Passed CLEAN, EXT [mailserverAbs] [mailserverIP] <emailSen> -> <EmailEmp>, Message-ID: <7B60A95976F741B28C1FF8C29E8763BD at Bernd3>, mail_id: hiHo6KceNBZX, Hits: -1.898, size: 7647897, queued_as: D90CB7FC30, 230548 ms
Mar 28 02:52:42 amavisServer amavis[25545]: (25545-06) TIMING-SA total 2017 ms - parse: 18 (0.9%), extract_message_metadata: 38 (1.9%), poll_dns_idle: 58 (2.9%), get_uri_detail_list: 2 (0.1%), tests_pri_-1000: 7 (0.4%), tests_pri_-950: 1.39 (0.1%), tests_pri_-900: 1.46 (0.1%), tests_pri_-400: 30 (1.5%), check_bayes: 27 (1.4%), tests_pri_0: 1874 (92.9%), check_dkim_adsp: 20 (1.0%), check_spf: 69 (3.4%), check_razor2: 1552 (77.0%), check_pyzor: 65 (3.2%), tests_pri_500: 7 (0.3%), learn: 9 (0.4%), get_report: 1.89 (0.1%)
Mar 28 02:52:42 amavisServer amavis[25545]: (25545-06) sending SMTP response: "250 2.0.0 from MTA([mailserverIP]:10025): 250 2.0.0 Ok: queued as D90CB7FC30"
Mar 28 02:52:42 amavisServer amavis[25545]: (25545-06) TIMING [total 230555 ms] - SMTP greeting: 2 (0%)0, SMTP EHLO: 2 (0%)0, SMTP pre-MAIL: 2 (0%)0, SMTP pre-DATA-flush: 3 (0%)0, SMTP DATA: 29356 (13%)13, check_init: 1 (0%)13, digest_hdr: 1 (0%)13, digest_body_dkim: 48 (0%)13, gen_mail_id: 1 (0%)13, mime_decode: 287 (0%)13, get-file-type7: 32 (0%)13, parts_decode: 0 (0%)13, check_header: 1 (0%)13, AV-scan-1: 587 (0%)13, spam-wb-list: 2 (0%)13, SA parse: 19 (0%)13, SA check: 1994 (1%)14, update_cache: 10 (0%)14, decide_mail_destiny: 1 (0%)14, fwd-connect: 33 (0%)14, fwd-xforward: 2 (0%)14, fwd-mail-pip: 19 (0%)14, fwd-rcpt-pip: 0 (0%)14, fwd-data-chkpnt: 0 (0%)14, write-header: 1 (0%)14, fwd-data-contents: 193458 (84%)98, fwd-end-chkpnt: 4678 (2%)100, prepare-dsn: 1 (0%)100, main_log_entry: 8 (0%)100, update_snmp: 3 (0%)100, SMTP pre-response: 0 (0%)100, SMTP response: 0 (0%)100, unlink-7-files: 2 (0%)100, rundown: 1 (0%)100
Mar 28 02:52:42 amavisServer amavis[25545]: (25545-06) ESMTP: NOTICE: client broke the connection without a QUIT ()
Mar 28 02:52:42 amavisServer amavis[25545]: (25545-06) load: 8 %, total idle 2903.831 s, busy 246.667 s
Mar 28 03:18:16 amavisServer amavis[25545]: (25545-06) loaded policy bank "EXT"
Mar 28 03:18:16 amavisServer amavis[25545]: (25545-06) process_request: fileno sock=12, STDIN=0, STDOUT=1

Mit freundlichen Grüßen

Marc Grooz

-----Ursprüngliche Nachricht-----
Von: postfixbuch-users-bounces at listen.jpberlin.de [mailto:postfixbuch-users-bounces at listen.jpberlin.de] Im Auftrag von Sascha Peters
Gesendet: Mittwoch, 28. März 2012 14:44
An: Eine Diskussionsliste rund um das Postfix-Buch von Peer Heinlein.
Betreff: Re: [Postfixbuch-users] Amavisproblem

Am 28.03.2012 14:15, schrieb Grooz, Marc (regio iT):
> OK dann habe ich das ja richtig verstanden.
> Warum der Postfix das aber macht ist mir nicht klar, habe gerade eine ähnliche Mail mit PDF Dokumenten in 19 Sekunden durch die Systeme bekommen.

Was sagt denn dsa Logfile von Amavis, da warten glaube ich noch alle drauf... da wird man wohl sehen was er macht, nicht macht oder wo er stehen bleibt...

Alternativ, wenn er "nur" lange braucht, dann mal die "smtpd_proxy_timeout" hoch setzen und schauen ob Sie dann irgendwann zurück kommt.

In jedem Fall wäre es nun Hilfreich mal zu wissen:

  - Distribution
  - Versionen von postfix, amavisd-new, spamassassin, Virenscanner
  - selbst installiert, oder von der Distribution
  - Logfile von amavisd-new (debug)
  - Netzwerkanbindung zwischen postfix/amavisd-new
    Firewall (Layer-7)

All diese informationen stehen doch noch aus, verelasse also den Lichtkegel der Laterne und suche auch mal im Dunkeln weiter...

-- 

Gruß
Sascha
-- 
_______________________________________________
Postfixbuch-users -- http://www.postfixbuch.de
Heinlein Professional Linux Support GmbH

Postfixbuch-users at listen.jpberlin.de
https://listi.jpberlin.de/mailman/listinfo/postfixbuch-users