May 12 12:08:50 lookup (score_sender) => undef, "quintons8@radclyffegroup.com" does not match May 12 12:08:50 SpamControl: calling spam scanner SpamAssassin May 12 12:08:50 spam_scan: DSPAM not available, skipping it May 12 12:08:50 timer set to 320 s for SA (was 480 s) May 12 12:08:50 calling SA parse, SA version 3.2.5, 3.002005, data as GLOB May 12 12:08:50 CALLING SA check May 12 12:08:51 prolong_timer spam_scan_sa_finish: timer set to 479 s May 12 12:08:51 spam_scan: score=24.351 autolearn=spam tests=[BAYES_99=3.5,DOS_OE_TO_MX=2.75,HTML_MESSAGE=0.001,MIME_QP_LONG_LINE=1.396,RCVD_IN_BL_SPAMCOP_NET=1.96,RCVD_IN_NJABL_PROXY=1.643,RCVD_IN_PBL=0.905,RCVD_IN_SORBS_DUL=0.877,RCVD_IN_XBL=3.033,RDNS_NONE=0.1,TVD_RCVD_SINGLE=1.351,URIBL_AB_SURBL=1.86,URIBL_JP_SURBL=1.501,URIBL_OB_SURBL=1.5,URIBL_SC_SURBL=0.474,URIBL_WS_SURBL=1.5] May 12 12:08:51 prolong_timer spam_scan: remaining time = 479 s May 12 12:08:51 enqueue: stat is not numeric: "" May 12 12:08:51 enqueue: deleting: 12d3a27136d0d786bae7c2ed49895448 May 12 12:08:51 enqueue: stat is not numeric: "" May 12 12:08:51 lookup_sql_field(spam_tag_level) "me@edv-kaschig.de" result=3 May 12 12:08:51 lookup (spam_tag_level) => true, "me@edv-kaschig.de" matches, result="3", matching_key="/cached/" May 12 12:08:51 lookup_sql_field(spam_tag2_level) "me@edv-kaschig.de" result=6.9 May 12 12:08:51 lookup (spam_tag2_level) => true, "me@edv-kaschig.de" matches, result="6.9", matching_key="/cached/" May 12 12:08:51 lookup (spam_tag3_level) => undef, "me@edv-kaschig.de" does not match May 12 12:08:51 lookup_sql_field(spam_kill_level) "me@edv-kaschig.de" result=6.9 May 12 12:08:51 lookup (spam_kill_level) => true, "me@edv-kaschig.de" matches, result="6.9", matching_key="/cached/" May 12 12:08:51 lookup_sql_field(message_size_limit) "me@edv-kaschig.de" result=0 May 12 12:08:51 lookup (message_size_limit) => false, "me@edv-kaschig.de" matches, result="0", matching_key="/cached/" May 12 12:08:51 final_destiny (ccat=6) is PASS, recip me@edv-kaschig.de May 12 12:08:51 final_destiny (ccat=5) is PASS, recip me@edv-kaschig.de May 12 12:08:51 final_destiny (ccat=0) is PASS, recip me@edv-kaschig.de May 12 12:08:51 final_destiny PASS, recip me@edv-kaschig.de [weiterer empfänger] May 12 12:08:51 do_notify_and_quar: ccat=Spam (6,0) ("6":Spam, "5":Spammy, "1,1":CleanTag, "1":Clean, "0":CatchAll) ccat_block=(), q_mth=local:spam-%m.gz, qar_mth= May 12 12:08:51 lookup_sql_field(spam_tag_level) "me@edv-kaschig.de" result=3 May 12 12:08:51 lookup (spam_tag_level) => true, "me@edv-kaschig.de" matches, result="3", matching_key="/cached/" May 12 12:08:51 lookup_sql_field(spam_tag2_level) "me@edv-kaschig.de" result=6.9 May 12 12:08:51 lookup (spam_tag2_level) => true, "me@edv-kaschig.de" matches, result="6.9", matching_key="/cached/" May 12 12:08:51 lookup_sql_field(spam_kill_level) "me@edv-kaschig.de" result=6.9 May 12 12:08:51 lookup (spam_kill_level) => true, "me@edv-kaschig.de" matches, result="6.9", matching_key="/cached/" May 12 12:08:51 lookup_sql_field(spam_quarantine_to) "me@edv-kaschig.de" result= May 12 12:08:51 lookup (spam_quarantine_to) => false, "me@edv-kaschig.de" matches, result="", matching_key="/cached/" May 12 12:08:51 lookup_sql_field(spam_admin) "me@edv-kaschig.de" result= May 12 12:08:51 lookup (spam_admin) => false, "me@edv-kaschig.de" matches, result="", matching_key="/cached/" [weiterer empfänger] May 12 12:08:51 lookup (spam_quarantine_bysender_to) => undef, "quintons8@radclyffegroup.com" does not match May 12 12:08:51 SPAM, -> ,,, Yes, score=24.351 tag=3 tag2=6.9 kill=6.9 tests=[BAYES_99=3.5, DOS_OE_TO_MX=2.75, HTML_MESSAGE=0.001, MIME_QP_LONG_LINE=1.396, RCVD_IN_BL_SPAMCOP_NET=1.96, RCVD_IN_NJABL_PROXY=1.643, RCVD_IN_PBL=0.905, RCVD_IN_SORBS_DUL=0.877, RCVD_IN_XBL=3.033, RDNS_NONE=0.1, TVD_RCVD_SINGLE=1.351, URIBL_AB_SURBL=1.86, URIBL_JP_SURBL=1.501, URIBL_OB_SURBL=1.5, URIBL_SC_SURBL=0.474, URIBL_WS_SURBL=1.5], autolearn=spam May 12 12:08:51 skip admin notification, no administrators May 12 12:08:51 do_notify_and_quarantine - done May 12 12:08:51 lookup_sql_field(spam_tag_level) "me@edv-kaschig.de" result=3 May 12 12:08:51 lookup (spam_tag_level) => true, "me@edv-kaschig.de" matches, result="3", matching_key="/cached/" May 12 12:08:51 lookup_sql_field(spam_tag2_level) "me@edv-kaschig.de" result=6.9 May 12 12:08:51 lookup (spam_tag2_level) => true, "me@edv-kaschig.de" matches, result="6.9", matching_key="/cached/" May 12 12:08:51 headers CLUSTERING: NEW CLUSTER : score=24.351, tag=1, tag2=1, local=0, bl=, s=, mangle= May 12 12:08:51 header: X-Virus-Scanned: Debian amavisd-new at kallisto.edv-kaschig.de\n May 12 12:08:51 header: Received: from kallisto.edv-kaschig.de ([127.0.0.1])\n\tby localhost (kallisto.edv-kaschig.de [127.0.0.1]) (amavisd-new, port 10024)\n\twith ESMTP id yfk7gcfB18K2; Tue, 12 May 2009 12:08:50 +0200 (CEST)\n [weiterer empfänger] May 12 12:08:51 headers CLUSTERING: joining cluster May 12 12:08:51 headers CLUSTERING: done all 3 recips in one go May 12 12:08:51 (about to connect to [127.0.0.1]:10025) FWD via SMTP: -> ,, May 12 12:08:51 smtp session reuse, 2 transactions so far May 12 12:08:51 establish_or_refresh, state: ehlo May 12 12:08:51 smtp cmd> NOOP May 12 12:08:51 rw_loop: needline=0, flush=1, wr=1, timeout=15 May 12 12:08:51 rw_loop: sending May 12 12:08:51 rw_loop sent 6> NOOP\r\n May 12 12:08:51 rw_loop: needline=1, flush=0, wr=0, timeout=15 May 12 12:08:51 rw_loop: receiving May 12 12:08:51 rw_loop read 14 chars< 250 2.0.0 Ok\r\n May 12 12:08:51 smtp resp to NOOP (idle 39.0 s): 250 2.0.0 Ok May 12 12:08:51 Remote host presents itself as: kallisto.edv-kaschig.de, handles DSN, handles PIPELINING May 12 12:08:51 AUTH not needed, user='', MTA offers 'PLAIN LOGIN' May 12 12:08:51 smtp cmd> MAIL FROM: BODY=7BIT May 12 12:08:51 smtp cmd> RCPT TO: ORCPT=rfc822;me@edv-kaschig.de [weiterer empfänger] May 12 12:08:51 smtp cmd> DATA May 12 12:08:51 rw_loop: needline=0, flush=1, wr=1, timeout=120 May 12 12:08:51 rw_loop: sending May 12 12:08:51 rw_loop sent 260> MAIL FROM: BODY=7BIT\r\nRCPT TO: ORCPT=rfc822;me@edv-kaschig.de\r\nRCPT TO: ORCPT=rfc822;weiterer@edv-kaschig.de\r\nRCPT TO:.\r\n May 12 12:08:51 smtp resp to MAIL (pip): 250 2.1.0 Ok May 12 12:08:51 smtp resp to RCPT (pip) (): 250 2.1.5 Ok [weiterer empfänger] May 12 12:08:51 smtp resp to DATA: 354 End data with . May 12 12:08:51 write_header: 0, Amavis::Out::SMTP::Protocol=HASH(0xc7c4340) May 12 12:08:51 smtp cmd> QUIT May 12 12:08:51 rw_loop: needline=0, flush=1, wr=1, timeout=479 May 12 12:08:51 rw_loop: sending May 12 12:08:51 rw_loop sent 7999> X-Virus-Scanned: Debian amavisd-new at kallisto.edv-kaschig.de\r\nReceived: from kallisto.edv-kaschig.de ([127.0.0.1])\r\n\tby localhost (kallisto.edv-kaschig.de [127.0.0.1]) (amavisd-new, port 10024)\r\n\twi [...] May 12 12:08:51 rw_loop: needline=1, flush=0, wr=0, timeout=479 May 12 12:08:51 rw_loop: receiving May 12 12:08:51 rw_loop read 52 chars< 250 2.0.0 Ok: queued as 7617021607D\r\n221 2.0.0 Bye\r\n May 12 12:08:51 smtp resp to data-dot (, etc.): 250 2.0.0 Ok: queued as 7617021607D May 12 12:08:51 Amavis::Out::SMTP::Session close, disconnecting May 12 12:08:51 prolong_timer fwd-end-chkpnt: timer set to 479 s May 12 12:08:51 FWD via SMTP: -> ,,,BODY=7BIT 250 2.0.0 Ok, id=21559-07, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 7617021607D May 12 12:08:51 prolong_timer forwarding: remaining time = 479 s May 12 12:08:51 DSN: sender NOT credible May 12 12:08:51 lookup: (scalar) matches, result="100" May 12 12:08:51 lookup (spam_dsn_cutoff_level_bysender) => true, "quintons8@radclyffegroup.com" matches, result="100", matching_key="(constant:100)" May 12 12:08:51 dsn: from MTA 250 NonBlocking:Spam -> : on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=1, mta_resp: "250 2.0.0 Ok, id=21559-07, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 7617021607D" May 12 12:08:51 DSN: SUCC from MTA 250 NonBlocking:Spam, no DSN requested: -> [weiterer empfänger] May 12 12:08:51 one_response_for_all : success, r=0,b=0,d=0, ndn_needed=0, '250 2.0.0 Ok, id=21559-07, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 7617021607D' May 12 12:08:51 notif=N, suppressed=0, ndn_needed=0, exit=0, 250 2.0.0 Ok, id=21559-07, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 7617021607D May 12 12:08:51 prolong_timer delivery-notification: remaining time = 479 s May 12 12:08:51 fish_out_ip_from_received: 59.93.69.16 May 12 12:08:51 lookup_ip_acl (publicnetworks): key="59.93.69.16" matches "::FFFF:0:0/96", result=1 May 12 12:08:51 parse_ip_address_from_received: 59.93.69.16 May 12 12:08:51 Passed SPAM, [59.93.69.16] [59.93.69.16] -> ,,, Message-ID: <000d01c9d2e9$8bdd0320$6400a8c0@quintons8>, mail_id: yfk7gcfB18K2, Hits: 24.351, size: 7724, queued_as: 7617021607D, 1204 ms May 12 12:08:51 prolong_timer main_log_entry: remaining time = 479 s May 12 12:08:51 updating snmp variables May 12 12:08:51 prolong_timer check done: remaining time = 479 s May 12 12:08:51 sending SMTP response: "250 2.0.0 Ok, id=21559-07, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 7617021607D" May 12 12:08:51 ESMTP> 250 2.0.0 Ok, id=21559-07, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 7617021607D May 12 12:08:51 switch_to_client_time 480 s, smtp response sent May 12 12:08:51 TempDir::strip: /var/lib/amavis/tmp/amavis-20090512T120648-21559 May 12 12:08:51 rmdir_recursively: /var/lib/amavis/tmp/amavis-20090512T120648-21559/parts, excl=1 May 12 12:08:51 TIMING [total 1227 ms] - SMTP greeting: 5 (0%)0, SMTP EHLO: 4 (0%)1, SMTP pre-MAIL: 4 (0%)1, lookup_sql: 10 (1%)2, lookup_sql: 10 (1%)3, lookup_sql: 11 (1%)3, SMTP pre-DATA-flush: 4 (0%)4, SMTP DATA: 6 (0%)4, check_init: 2 (0%)4, digest_hdr: 1 (0%)5, digest_body: 1 (0%)5, gen_mail_id: 2 (0%)5, mime_decode: 37 (3%)8, get-file-type2: 45 (4%)11, parts_decode: 1 (0%)12, check_header: 5 (0%)12, AV-scan-1: 25 (2%)14, AV-scan-2: 2 (0%)14, lookup_sql: 8 (1%)15, lookup_sql: 10 (1%)16, lookup_sql: 10 (1%)16, spam-wb-list: 5 (0%)17, SA parse: 7 (1%)17, SA check: 848 (69%)87, update_cache: 18 (1%)88, decide_mail_destiny: 12 (1%)89, fwd-connect: 24 (2%)91, fwd-mail-pip: 16 (1%)92, fwd-rcpt-pip: 1 (0%)92, fwd-data-chkpnt: 0 (0%)92, write-header: 2 (0%)93, fwd-data-contents: 1 (0%)93, fwd-end-chkpnt: 40 (3%)96, prepare-dsn: 4 (0%)96, main_log_entry: 33 (3%)99, update_snmp: 4 (0%)99, SMTP pre-response: 1 (0%)99, SMTP response: 7 (1%)100, unlink-2-files: 1 (0%)100, rundown: 1 (0%)100 May 12 12:08:51 idle_proc, 6: was busy, 1183.4 ms, total idle 116.095 s, busy 7.065 s May 12 12:08:51 idle_proc, 5: was idle, 0.3 ms, total idle 116.095 s, busy 7.065 s May 12 12:08:51 ESMTP< QUIT\r\n May 12 12:08:51 switch_to_my_time 480 s, SMTP QUIT received May 12 12:08:51 ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel May 12 12:08:51 switch_to_client_time 480 s, smtp response sent May 12 12:08:51 SMTP session over, timer stopped May 12 12:08:51 exiting process_request May 12 12:08:51 post_process_request_hook: timer was not running May 12 12:08:51 idle_proc, bye: was busy, 3.9 ms, total idle 116.095 s, busy 7.069 s May 12 12:08:51 load: 6 %, total idle 116.095 s, busy 7.069 s