[postfix-users] Delay bei internen zustellen der Mails

Fr Feb 15 20:54:55 CET 2013

> > Tatsächlich ist das so. Habe mal in der "main.cf" Datei die Zeile
> > mailbox_command = /usr/bin/procmail -a "$EXTENSION"
> > auskommentiert und die Mails gehen in Windeseile in die Postfächer.
> 
> Vorher hat procmail die zustellung korrekt gemacht. Nach Deaktivierung
> wird die Mail irgendwo hingeschrieben
>  
> > Jetzt stehe ich aber immer noch vor dem gleichen Problem. Wo trödelt
> > das Mail herum nachdem procmail aufgerufen wurde. 

na im spamd

Habe nun mal im spamd (SPAMD_ARGS="-d -x -c -L -D") die debug Funktion eingeschaltet. Aber wo sehe ich die Zeit zweischen 20:37:18 bis 20:37:29 ?
Kann man irrgendwie sehen wie lange Postfix braucht die die Realtime Blacklist abzufragen? da ich einige abfrage, kann es sein, dass dort die meiste Zeit verloren geht.

Feb 15 20:37:18 server postfix/pickup[27237]: 6FA4726C070: uid=0 from=<absender at meinserver.com>
Feb 15 20:37:18 server postfix/cleanup[30061]: 6FA4726C070: message-id=<1360957038.30055 at meinserver.com>
Feb 15 20:37:18 server postfix/qmgr[15753]: 6FA4726C070: from=<absender at meinserver.com>, size=584, nrcpt=1 (queue active)
Feb 15 20:37:29 server spamd[30013]: prefork: ordered 30015 to accept
Feb 15 20:37:29 server spamd[30013]: prefork: sysread(7) not ready, wait max 300 secs
Feb 15 20:37:29 server spamd[30013]: prefork: child 30015: entering state 2
Feb 15 20:37:29 server spamd[30015]: spamd: connection from localhost [127.0.0.1] at port 38399
Feb 15 20:37:29 server spamd[30013]: prefork: new lowest idle kid: 30016
Feb 15 20:37:29 server spamd[30015]: spamd: setuid to mathias succeeded
Feb 15 20:37:29 server spamd[30015]: info: user has changed
Feb 15 20:37:29 server spamd[30015]: bayes: tie-ing to DB file R/O /var/spool/spamassassin/bayes_toks
Feb 15 20:37:29 server spamd[30015]: bayes: tie-ing to DB file R/O /var/spool/spamassassin/bayes_seen
Feb 15 20:37:29 server spamd[30015]: bayes: found bayes db version 3
Feb 15 20:37:29 server spamd[30015]: bayes: DB journal sync: last sync: 1360933333
Feb 15 20:37:29 server spamd[30015]: config: score set 2 chosen.
Feb 15 20:37:29 server spamd[30015]: spamd: running as uid 500
Feb 15 20:37:29 server spamd[30015]: dns: name server: 8.8.8.8, LocalAddr: 0.0.0.0
Feb 15 20:37:29 server spamd[30015]: dns: resolver socket rx buffer size is 114688 bytes
Feb 15 20:37:29 server spamd[30015]: message: main message type: multipart/mixed
Feb 15 20:37:29 server spamd[30015]: spamd: processing message <1360957038.30055 at meinserver.com> for benutzer:500
Feb 15 20:37:29 server spamd[30015]: conf: trusted_networks are not configured; it is recommended that you configure trusted_networks manually
Feb 15 20:37:29 server spamd[30015]: received-header: parsed as [ ip=83.77.173.231 rdns= helo= by= ident= envfrom= intl=0 id= auth= msa=0 ]
Feb 15 20:37:29 server spamd[30015]: received-header: do not trust any hosts from here on
Feb 15 20:37:29 server spamd[30015]: received-header: relay 83.77.173.231 trusted? no internal? no msa? no
Feb 15 20:37:29 server spamd[30015]: metadata: X-Spam-Relays-Trusted: 
Feb 15 20:37:29 server spamd[30015]: metadata: X-Spam-Relays-Untrusted: [ ip=83.77.173.231 rdns= helo= by= ident= envfrom= intl=0 id= auth= msa=0 ]
Feb 15 20:37:29 server spamd[30015]: metadata: X-Spam-Relays-Internal: 
Feb 15 20:37:29 server spamd[30015]: metadata: X-Spam-Relays-External: [ ip=83.77.173.231 rdns= helo= by= ident= envfrom= intl=0 id= auth= msa=0 ]
Feb 15 20:37:29 server spamd[30015]: message: ---- MIME PARSER START ----
Feb 15 20:37:29 server spamd[30015]: message: parsing multipart, got boundary: bound1360957038
Feb 15 20:37:29 server spamd[30015]: message: found part of type text/plain, boundary: bound1360957038
Feb 15 20:37:29 server spamd[30015]: message: added part, type: text/plain
Feb 15 20:37:29 server spamd[30015]: message: parsing normal part
Feb 15 20:37:29 server spamd[30015]: message: ---- MIME PARSER END ----
Feb 15 20:37:29 server spamd[30015]: message: decoding other encoding type (7bit), ignoring
Feb 15 20:37:29 server spamd[30015]: rules: local tests only, ignoring RBL eval
Feb 15 20:37:29 server spamd[30015]: check: running tests for priority: -1000
Feb 15 20:37:29 server spamd[30015]: rules: running head tests; score so far=0
Feb 15 20:37:29 server spamd[30015]: rules: ran eval rule USER_IN_WHITELIST ======> got hit (1)
Feb 15 20:37:29 server spamd[30015]: rules: running body tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running uri tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running rawbody tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running full tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running meta tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: check: running tests for priority: -950
Feb 15 20:37:29 server spamd[30015]: rules: running head tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running body tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running uri tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running rawbody tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running full tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running meta tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: check: running tests for priority: -900
Feb 15 20:37:29 server spamd[30015]: rules: running head tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running body tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running uri tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running rawbody tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running full tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running meta tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: check: running tests for priority: -400
Feb 15 20:37:29 server spamd[30015]: rules: running head tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running body tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running uri tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: plugin: Mail::SpamAssassin::Plugin::WLBLEval=HASH(0x9115cbc) implements 'check_wb_list', priority 0
Feb 15 20:37:29 server spamd[30015]: bayes: DB journal sync: last sync: 1360933333
Feb 15 20:37:29 server spamd[30015]: bayes: corpus size: nspam = 73264, nham = 13465
Feb 15 20:37:29 server spamd[30015]: bayes: score = 1.17131387712965e-05
Feb 15 20:37:29 server spamd[30015]: bayes: DB journal sync: last sync: 1360933333
Feb 15 20:37:29 server spamd[30015]: bayes: DB expiry: tokens in DB: 134013, Expiry max size: 150000, Oldest atime: 1346717594, Newest atime: 1360949986, Last expire: 1357772363, Current time: 1360957049
Feb 15 20:37:29 server spamd[30015]: bayes: untie-ing
Feb 15 20:37:29 server spamd[30015]: rules: running rawbody tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running full tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: running meta tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: check: running tests for priority: 0
Feb 15 20:37:29 server spamd[30015]: rules: running head tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: ran header rule __TVD_MIME_CT_MM ======> got hit: "multipart/mixed"
Feb 15 20:37:29 server spamd[30015]: rules: ran header rule __CTYPE_HAS_BOUNDARY ======> got hit: "boundary"
Feb 15 20:37:29 server spamd[30015]: rules: ran header rule __CT ======> got hit: "m"
Feb 15 20:37:29 server spamd[30015]: rules: ran header rule __RDNS_NONE ======> got hit: "[ ip=83.77.173.231 rdns= "
Feb 15 20:37:29 server spamd[30015]: rules: ran header rule __LAST_UNTRUSTED_RELAY_NO_AUTH ======> got hit: "[ ip=83.77.173.231 rdns= helo= by= ident= envfrom= intl=0 id= auth= "
Feb 15 20:37:29 server spamd[30015]: rules: ran header rule __HELO_NO_DOMAIN ======> got hit: "[ ip=83.77.173.231 rdns= helo= by= ident= envfrom= intl=0 id= auth= msa=0 "
Feb 15 20:37:29 server spamd[30015]: rules: ran header rule __MISSING_REF ======> got hit: "UNSET"
Feb 15 20:37:29 server spamd[30015]: rules: ran header rule __MIME_VERSION ======> got hit: "1"
Feb 15 20:37:29 server spamd[30015]: rules: ran header rule __TOCC_EXISTS ======> got hit: "m"
Feb 15 20:37:29 server spamd[30015]: rules: ran header rule __MSOE_MID_WRONG_CASE ======> got hit: "
Feb 15 20:37:29 server spamd[30015]: rules: Message-Id: "
Feb 15 20:37:29 server spamd[30015]: rules: ran header rule __HAS_X_MAILER ======> got hit: "W"
Feb 15 20:37:29 server spamd[30015]: rules: ran header rule __DOS_SINGLE_EXT_RELAY ======> got hit: "[ ip=83.77.173.231 rdns= helo= by= ident= envfrom= intl=0 id= auth= msa=0 ]"
Feb 15 20:37:29 server spamd[30015]: rules: ran header rule __HAS_RCVD ======> got hit: "b"
Feb 15 20:37:29 server spamd[30015]: rules: ran header rule __DOS_RCVD_FRI ======> got hit: " Fri, "
Feb 15 20:37:29 server spamd[30015]: rules: ran header rule __MSGID_OK_DIGITS ======> got hit: "1360957038"
Feb 15 20:37:29 server spamd[30015]: rules: ran header rule __HAS_MSGID ======> got hit: "<"
Feb 15 20:37:29 server spamd[30015]: rules: "
Feb 15 20:37:29 server spamd[30015]: rules: ran header rule __HAS_SUBJECT ======> got hit: "T"
Feb 15 20:37:29 server spamd[30015]: spf: checking to see if the message has a Received-SPF header that we can use
Feb 15 20:37:29 server spamd[30015]: spf: already checked for Received-SPF headers, proceeding with DNS based checks
Feb 15 20:37:29 server spamd[30015]: spf: already checked for Received-SPF headers, proceeding with DNS based checks
Feb 15 20:37:29 server spamd[30015]: spf: already checked for Received-SPF headers, proceeding with DNS based checks
Feb 15 20:37:29 server spamd[30015]: spf: already checked for Received-SPF headers, proceeding with DNS based checks
Feb 15 20:37:29 server spamd[30015]: rules: ran eval rule __ENV_AND_HDR_FROM_MATCH ======> got hit (1)
Feb 15 20:37:29 server spamd[30015]: spf: def_whitelist_from_spf: pager at betschart.com is not in DEF_WHITELIST_FROM_SPF
Feb 15 20:37:29 server spamd[30015]: spf: already checked for Received-SPF headers, proceeding with DNS based checks
Feb 15 20:37:29 server spamd[30015]: spf: already checked for Received-SPF headers, proceeding with DNS based checks
Feb 15 20:37:29 server spamd[30015]: spf: already checked for Received-SPF headers, proceeding with DNS based checks
Feb 15 20:37:29 server spamd[30015]: rules: running body tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: rules: ran body rule __NONEMPTY_BODY ======> got hit: "T"
Feb 15 20:37:29 server spamd[30015]: rules: running uri tests; score so far=-100
Feb 15 20:37:29 server spamd[30015]: eval: stock info total: 0
Feb 15 20:37:29 server spamd[30015]: rules: ran eval rule __TVD_MIME_ATT_TP ======> got hit (1)
Feb 15 20:37:29 server spamd[30015]: rules: ran eval rule BAYES_00 ======> got hit (1)
Feb 15 20:37:29 server spamd[30015]: rules: running rawbody tests; score so far=-102.312
Feb 15 20:37:29 server spamd[30015]: rules: ran rawbody rule __TVD_BODY ======> got hit: "Test"
Feb 15 20:37:29 server spamd[30015]: rules: running full tests; score so far=-102.312
Feb 15 20:37:29 server spamd[30015]: rules: running meta tests; score so far=-102.312
Feb 15 20:37:29 server spamd[30015]: check: running tests for priority: 500
Feb 15 20:37:29 server spamd[30015]: dns: harvest_dnsbl_queries
Feb 15 20:37:29 server spamd[30015]: rules: running head tests; score so far=-102.312
Feb 15 20:37:29 server spamd[30015]: rules: running body tests; score so far=-102.312
Feb 15 20:37:29 server spamd[30015]: rules: running uri tests; score so far=-102.312
Feb 15 20:37:29 server spamd[30015]: rules: running rawbody tests; score so far=-102.312
Feb 15 20:37:29 server spamd[30015]: rules: running full tests; score so far=-102.312
Feb 15 20:37:29 server spamd[30015]: rules: running meta tests; score so far=-102.312
Feb 15 20:37:29 server spamd[30015]: check: running tests for priority: 1000
Feb 15 20:37:29 server spamd[30015]: rules: running head tests; score so far=-102.212
Feb 15 20:37:29 server spamd[30015]: config: using "/home/benutzer/.spamassassin" for user state dir
Feb 15 20:37:29 server spamd[30015]: locker: safe_lock: created /home/benutzer/.spamassassin/auto-whitelist.mutex
Feb 15 20:37:29 server spamd[30015]: locker: safe_lock: trying to get lock on /home/benutzer/.spamassassin/auto-whitelist with 30 timeout
Feb 15 20:37:29 server spamd[30015]: locker: safe_lock: link to /home/benutzer/.spamassassin/auto-whitelist.mutex: link ok
Feb 15 20:37:29 server spamd[30015]: auto-whitelist: tie-ing to DB file of type DB_File R/W in /home/benutzer/.spamassassin/auto-whitelist
Feb 15 20:37:29 server spamd[30015]: auto-whitelist: db-based absender at meinserver.com|ip=83.77 scores 29/73.652
Feb 15 20:37:29 server spamd[30015]: auto-whitelist: AWL active, pre-score: -102.212, autolearn score: -2.212, mean: 2.53972413793103, IP: 83.77.173.231
Feb 15 20:37:29 server spamd[30015]: auto-whitelist: add_score: new count: 30, new totscore: 71.44
Feb 15 20:37:29 server spamd[30015]: auto-whitelist: DB addr list: untie-ing and unlocking
Feb 15 20:37:29 server spamd[30015]: auto-whitelist: DB addr list: file locked, breaking lock
Feb 15 20:37:29 server spamd[30015]: locker: safe_unlock: unlocked /home/benutzer/.spamassassin/auto-whitelist.mutex
Feb 15 20:37:29 server spamd[30015]: auto-whitelist: post auto-whitelist score: -99.8361379310345
Feb 15 20:37:29 server spamd[30015]: rules: running body tests; score so far=-99.8361379310345
Feb 15 20:37:29 server spamd[30015]: rules: running uri tests; score so far=-99.8361379310345
Feb 15 20:37:29 server spamd[30015]: rules: running rawbody tests; score so far=-99.8361379310345
Feb 15 20:37:29 server spamd[30015]: rules: running full tests; score so far=-99.8361379310345
Feb 15 20:37:29 server spamd[30015]: rules: running meta tests; score so far=-99.8361379310345
Feb 15 20:37:29 server spamd[30015]: plugin: Mail::SpamAssassin::Plugin::AutoLearnThreshold=HASH(0x8dd3084) implements 'autolearn_discriminator', priority 0
Feb 15 20:37:29 server spamd[30015]: learn: auto-learn: currently using scoreset 2, recomputing score based on scoreset 0
Feb 15 20:37:29 server spamd[30015]: learn: auto-learn: message score: -99.8361379310345, computed score for autolearn: 0.1
Feb 15 20:37:29 server spamd[30015]: learn: auto-learn? ham=0.1, spam=12, body-points=0.1, head-points=0.1, learned-points=-2.312
Feb 15 20:37:29 server spamd[30015]: learn: auto-learn? no: inside auto-learn thresholds, not considered ham or spam
Feb 15 20:37:29 server spamd[30015]: check: is spam? score=-99.836 required=4.5
Feb 15 20:37:29 server spamd[30015]: check: tests=AWL,BAYES_00,RDNS_NONE,USER_IN_WHITELIST
Feb 15 20:37:29 server spamd[30015]: check: subtests=__CT,__CTYPE_HAS_BOUNDARY,__DOS_DIRECT_TO_MX,__DOS_RCVD_FRI,__DOS_SINGLE_EXT_RELAY,__ENV_AND_HDR_FROM_MATCH,__HAS_MSGID,__HAS_RCVD,__HAS_SUBJECT,__HAS_X_MAILER,__HELO_NO_DOMAIN,__LAST_UNTRUSTED_RELAY_NO_AUTH,__MIME_VERSION,__MISSING_REF,__MSGID_OK_DIGITS,__MSGID_OK_HOST,__MSOE_MID_WRONG_CASE,__NAKED_TO,__NONEMPTY_BODY,__RDNS_NONE,__SANE_MSGID,__TOCC_EXISTS,__TVD_BODY,__TVD_MIME_ATT_TP,__TVD_MIME_CT_MM
Feb 15 20:37:29 server spamd[30015]: spamd: clean message (-99.8/4.5) for benutzer:500 in 0.2 seconds, 1007 bytes.
Feb 15 20:37:29 server spamd[30015]: spamd: result: . -99 - AWL,BAYES_00,RDNS_NONE,USER_IN_WHITELIST scantime=0.2,size=1007,user=mathias,uid=500,required_score=4.5,rhost=localhost,raddr=127.0.0.1,rport=38399,mid=<1360957038.30055 at betschart.com>,bayes=0.000012,autolearn=no
Feb 15 20:37:29 server spamd[30015]: config: copying current conf from backup
Feb 15 20:37:29 server spamd[30015]: prefork: sysread(8) not ready, wait max 300 secs
Feb 15 20:37:29 server spamd[30013]: prefork: child 30015: entering state 1
Feb 15 20:37:29 server spamd[30013]: prefork: new lowest idle kid: 30015
Feb 15 20:37:29 server spamd[30013]: prefork: child reports idle
Feb 15 20:37:29 server spamd[30013]: prefork: child states: II
Feb 15 20:37:29 server postfix/local[30065]: 6FA4726C070: to=<benutzer at mail.meinserver.com>, orig_to=<benutzer at meinserver.com>, relay=local, delay=11, delays=0.27/0.02/0/11, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail -a "$EXTENSION")
Feb 15 20:37:29 server postfix/qmgr[15753]: 6FA4726C070: removed

_______________________________________________
postfix-users mailing list
postfix-users at de.postfix.org
http://de.postfix.org/cgi-bin/mailman/listinfo/postfix-users