out.txt

Apr 27 08:35:05 roadrunner postfix/smtpd[711]: 4CC90285C7: client=blu0-omc2-s35.blu0.hotmail.com[65.55.111.110]
Apr 27 08:35:05 roadrunner postfix/cleanup[1627]: 4CC90285C7: message-id=<BLU139-W17338F5F8E0530E428E2D19C030@phx.gbl>
Apr 27 08:35:05 roadrunner postfix/qmgr[1497]: 4CC90285C7: from=<lc_fisher@hotmail.com>, size=3314, nrcpt=1 (queue active)
Apr 27 08:35:05 roadrunner amavis[1666]: (01666-19) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Apr 27 08:35:05 roadrunner amavis[1666]: (01666-19) switch_to_client_time 480 s, smtp response sent
Apr 27 08:35:05 roadrunner amavis[1666]: (01666-19) idle_proc, 4: was busy, 282.8 ms, total idle 290.370 s, busy 23.941 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) idle_proc, 5: was idle, 92.3 ms, total idle 290.462 s, busy 23.941 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) SMTP< EHLO roadrunner.southeast-pa.com\r\n
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) switch_to_my_time     480 s, SMTP EHLO received
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP> 250-[127.0.0.1]
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP> 250-VRFY
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP> 250-PIPELINING
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP> 250-SIZE
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP> 250-ENHANCEDSTATUSCODES
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP> 250-8BITMIME
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP> 250-DSN
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP> 250 XFORWARD NAME ADDR PROTO HELO
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) switch_to_client_time 480 s, smtp response sent
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) idle_proc, 6: was busy, 3.4 ms, total idle 290.462 s, busy 23.944 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) idle_proc, 5: was idle, 0.3 ms, total idle 290.463 s, busy 23.944 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP< XFORWARD NAME=blu0-omc2-s35.blu0.hotmail.com ADDR=65.55.111.110\r\n
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) switch_to_my_time     480 s, SMTP XFORWARD received
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP> 250 2.5.0 Ok XFORWARD
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) switch_to_client_time 480 s, smtp response sent
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) idle_proc, 6: was busy, 1.5 ms, total idle 290.463 s, busy 23.946 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) idle_proc, 5: was idle, 0.3 ms, total idle 290.463 s, busy 23.946 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP< XFORWARD PROTO=ESMTP HELO=blu0-omc2-s35.blu0.hotmail.com\r\n
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) switch_to_my_time     480 s, SMTP XFORWARD received
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP> 250 2.5.0 Ok XFORWARD
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) switch_to_client_time 480 s, smtp response sent
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) idle_proc, 6: was busy, 1.4 ms, total idle 290.463 s, busy 23.947 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) idle_proc, 5: was idle, 0.3 ms, total idle 290.463 s, busy 23.947 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP< MAIL FROM:<lc_fisher@hotmail.com> SIZE=3314\r\n
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) switch_to_my_time     480 s, SMTP MAIL received
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) check_mail_begin_task: task_count=19
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup_ip_acl (mynetworks): key="65.55.111.110", no match
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (debug_sender) => undef, "lc_fisher@hotmail.com" does not match
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP> 250 2.1.0 Sender <lc_fisher@hotmail.com> OK
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) switch_to_client_time 480 s, smtp response sent
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) idle_proc, 6: was busy, 4.0 ms, total idle 290.463 s, busy 23.951 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) idle_proc, 5: was idle, 0.2 ms, total idle 290.463 s, busy 23.951 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP< RCPT TO:<doug@brownsearch.com> ORCPT=rfc822;doug@brownsearch.com\r\n
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) switch_to_my_time     480 s, SMTP RCPT received
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP> 250 2.1.5 Recipient <doug@brownsearch.com> OK
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) switch_to_client_time 480 s, smtp response sent
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) idle_proc, 6: was busy, 1.7 ms, total idle 290.463 s, busy 23.953 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) idle_proc, 5: was idle, 0.2 ms, total idle 290.464 s, busy 23.953 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP< DATA\r\n
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) switch_to_my_time     480 s, SMTP DATA received
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP::10025 /var/spool/amavisd/tmp/amavis-20100427T082958-01666: <lc_fisher@hotmail.com> -> <doug@brownsearch.com> SIZE=3314 Received: from roadrunner.southeast-pa.com ([127.0.0.1]) by localhost (roadrunner.southeast-pa.com [127.0.0.1]) (amavisd-new, port 10025) with ESMTP for <doug@brownsearch.com>; Tue, 27 Apr 2010 08:35:06 -0400 (EDT)
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP> 354 End data with <CR><LF>.<CR><LF>
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) switch_to_client_time 480 s, smtp response sent
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) switch_to_client_time 480 s, receiving data
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) switch_to_my_time     480 s, data-end received
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP< .<CR><LF>
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) setting body type: 7BIT (h=0, b=0)
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) body hash: 8df004c140fdaa77c93b4113ac5011cf
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) Original mail size: 3314; quota set to: 1657000 bytes
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) Checking: awI7S516WKa9 [65.55.111.110] <lc_fisher@hotmail.com> -> <doug@brownsearch.com>
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) query_keys: doug@brownsearch.com, doug@, brownsearch.com, .brownsearch.com, .com, .
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup_hash(doug@brownsearch.com), no matches
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (bypass_virus_checks) => undef, "doug@brownsearch.com" does not match
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) Extracting mime components
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) Issued a new file name: p001
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) Issued a new file name: p002
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) Issued a new pseudo part: p003
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) p003 1 Content-Type: multipart/alternative
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) Charging 461 bytes to remaining quota 1657000 (out of 1657000, (0%)) - by mime_decode
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) p001 1/1 Content-Type: text/plain, size: 461 B, name: 
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) reparenting p001 from p000 to p003
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) Charging 1396 bytes to remaining quota 1656539 (out of 1657000, (0%)) - by mime_decode
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) p002 1/2 Content-Type: text/html, size: 1396 B, name: 
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) reparenting p002 from p000 to p003
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) prolong_timer mime_decode-1: remaining time = 480 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) decode_parts: level=1, #parts=3 : p001, p002, p003
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) run_command: [2186] /usr/bin/file p001 p002 </dev/null 2>&1
Apr 27 08:35:06 roadrunner amavis[2186]: (01666-19) open_on_specific_fd: target fd0 closing, to become < /dev/null
Apr 27 08:35:06 roadrunner amavis[2186]: (01666-19) open_on_specific_fd: target fd2 closing, to become > &1
Apr 27 08:35:06 roadrunner amavis[2186]: (01666-19) open_on_specific_fd: target fd2 dup2 from fd1 > &1
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) result line from file(1): p001: ASCII English text\n
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup_re("ASCII English text") matches key "(?i-xsm:^(ASCII|text)\b)", result="asc"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (map_full_type_to_short_type) => true,  "ASCII English text" matches, result="asc", matching_key="(?i-xsm:^(ASCII|text)\\b)"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) File-type of p001: ASCII English text; (asc)
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) result line from file(1): p002: HTML document text\n
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup_re("HTML document text") matches key "(?-xism:^HTML document text\b)", result="html"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (map_full_type_to_short_type) => true,  "HTML document text" matches, result="html", matching_key="(?-xism:^HTML document text\\b)"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) File-type of p002: HTML document text; (html)
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) do_ascii: Decoding part p001
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) do_ascii: Setting sigaction handler, was 0
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) timer set to 320 s (was 480 s)
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) do_ascii: Decoding part p001 (0 items), uulib V0.5pl20
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) do_ascii(0): state=0x08, enc=unknown, est.size=0, name=
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) do_ascii: Convert::UUlib info: 0 not decodable, 8
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) prolong_timer do_ascii: timer set to 480 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) decompose_part: p001 - source retained
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) decompose_part: p002 - atomic
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) prolong_timer parts_decode: remaining time = 480 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) query_keys: doug@brownsearch.com, doug@, brownsearch.com, .brownsearch.com, .com, .
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup_hash(doug@brownsearch.com), no matches
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (bypass_header_checks) => undef, "doug@brownsearch.com" does not match
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) check_header: 0, OK
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) query_keys: doug@brownsearch.com, doug@, brownsearch.com, .brownsearch.com, .com, .
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup_hash(doug@brownsearch.com), no matches
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (bypass_header_checks) => undef, "doug@brownsearch.com" does not match
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) Checking for banned types and filenames
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) query_keys: doug@brownsearch.com, doug@, brownsearch.com, .brownsearch.com, .com, .
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup_hash(doug@brownsearch.com), no matches
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (bypass_banned_checks) => undef, "doug@brownsearch.com" does not match
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup: (scalar) matches, result="DEFAULT"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (banned_filename), 1 matches for "doug@brownsearch.com", results: "(constant:DEFAULT)"=>"DEFAULT"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) collect banned table[0]: doug@brownsearch.com, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x1cd7f800)
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) starting banned checks - traversing message structure tree
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) check_for_banned (p003,p001) multipart/alternative | text/plain,.asc
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) doing banned check for doug@brownsearch.com on multipart/alternative | text/plain,.asc
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup_re(["multipart/alternative","text/plain",".asc"]), no matches
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (check_bann:doug@brownsearch.com) => undef, ["multipart/alternative","text/plain",".asc"] does not match
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) p.path doug@brownsearch.com: "P=p003,L=1,M=multipart/alternative | P=p001,L=1/1,M=text/plain,T=asc"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) check_for_banned (p003,p002) multipart/alternative | text/html,.html
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) doing banned check for doug@brownsearch.com on multipart/alternative | text/html,.html
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup_re(["multipart/alternative","text/html",".html"]), no matches
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (check_bann:doug@brownsearch.com) => undef, ["multipart/alternative","text/html",".html"] does not match
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) p.path doug@brownsearch.com: "P=p003,L=1,M=multipart/alternative | P=p002,L=1/2,M=text/html,T=html"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) banned check: any=0, all=N (1)
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup_re("MAIL"), no matches
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (keep_decoded_original) => undef, "MAIL" does not match
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) Using ClamAV-clamd: (built-in interface)
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) timer set to 320 s (was 480 s)
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ask_av (ClamAV-clamd): query template1: CONTSCAN {}\n
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) Using (ClamAV-clamd) on dir: CONTSCAN /var/spool/amavisd/tmp/amavis-20100427T082958-01666/parts\n
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) timer set to 10 s (was 320 s)
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ClamAV-clamd: Connecting to socket  /var/spool/amavisd/clamd.sock
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ClamAV-clamd: Sending CONTSCAN /var/spool/amavisd/tmp/amavis-20100427T082958-01666/parts\n to UNIX socket /var/spool/amavisd/clamd.sock
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) prolong_timer ask_daemon_internal: timer set to 256 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ask_av (ClamAV-clamd) result: /var/spool/amavisd/tmp/amavis-20100427T082958-01666/parts: OK\n
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ask_av (ClamAV-clamd): /var/spool/amavisd/tmp/amavis-20100427T082958-01666/parts CLEAN
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ClamAV-clamd result: clean
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) prolong_timer run_av: timer set to 480 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) query_keys: doug@brownsearch.com, doug@, brownsearch.com, .brownsearch.com, .com, .
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup_hash(doug@brownsearch.com), no matches
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (bypass_virus_checks) => undef, "doug@brownsearch.com" does not match
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) no anti-spam code loaded, skipping spam_scan
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) enqueue: stat is not numeric: ""
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) enqueue: deleting: dcb58e8606c4b654e87ff8df4d9910d8
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) enqueue: stat is not numeric: ""
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup: (scalar) matches, result="2"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (spam_tag_level) => true,  "doug@brownsearch.com" matches, result="2", matching_key="(constant:2)"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup: (scalar) matches, result="6.31"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (spam_tag2_level) => true,  "doug@brownsearch.com" matches, result="6.31", matching_key="(constant:6.31)"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (spam_tag3_level) => undef, "doug@brownsearch.com" does not match
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup: (scalar) matches, result="6.31"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (spam_kill_level) => true,  "doug@brownsearch.com" matches, result="6.31", matching_key="(constant:6.31)"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup: (scalar) matches, result="1"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (bypass_spam_checks) => true,  "doug@brownsearch.com" matches, result="1", matching_key="(constant:1)"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) final_destiny PASS, recip doug@brownsearch.com
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) do_notify_and_quar: ccat=Clean (1,0) ("1":Clean, "0":CatchAll), q_mth=, qar_mth=
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) skip admin notification, no administrators
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) do_notify_and_quarantine - done
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) defang? ccat "0": 
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) header: Received: from roadrunner.southeast-pa.com ([127.0.0.1])\n\tby localhost (roadrunner.southeast-pa.com [127.0.0.1]) (amavisd-new, port 10025)\n\twith ESMTP id awI7S516WKa9 for <doug@brownsearch.com>;\n\tTue, 27 Apr 2010 08:35:06 -0400 (EDT)\n
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup_acl(doug@brownsearch.com), no match
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (local_domains) => undef, "doug@brownsearch.com" does not match
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) headers CLUSTERING: NEW CLUSTER <doug@brownsearch.com>: score=x, tag=0, tag2=0, local=0, bl=, s=
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) header: X-Virus-Scanned: amavisd-new at southeast-pa.com\n
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) headers CLUSTERING: done all 1 recips in one go
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) (about to connect to [127.0.0.1]:10026) FWD via SMTP: <lc_fisher@hotmail.com> -> <doug@brownsearch.com>
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) Remote host presents itself as: roadrunner.southeast-pa.com, handles DSN, no ORCPT
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) prolong_timer fwd-connect: timer set to 480 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) sending XFORWARD ADDR=65.55.111.110 NAME=blu0-omc2-s35.blu0.hotmail.com PROTO=ESMTP HELO=blu0-omc2-s35.blu0.hotmail.com
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) prolong_timer fwd-xforward: remaining time = 480 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) AUTH not needed, user='', MTA offers 'PLAIN LOGIN'
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) prolong_timer fwd-mail-from: remaining time = 480 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) sending RCPT TO:<doug@brownsearch.com> 
Apr 27 08:35:06 roadrunner postfix/smtpd[1626]: 24E48285C8: client=blu0-omc2-s35.blu0.hotmail.com[65.55.111.110]
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) response to RCPT TO for <doug@brownsearch.com>: "250 2.1.5 Ok"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) prolong_timer fwd-rcpt-to: remaining time = 480 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) prolong_timer fwd-data-cmd: remaining time = 480 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) response to DATA: "354 End data with <CR><LF>.<CR><LF>"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) write_header: 0, Amavis::Out::SMTP=HASH(0x1d8bac20)
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) prolong_timer fwd-data-contents: remaining time = 480 s
Apr 27 08:35:06 roadrunner postfix/cleanup[1020]: 24E48285C8: message-id=<BLU139-W17338F5F8E0530E428E2D19C030@phx.gbl>
Apr 27 08:35:06 roadrunner postfix/qmgr[1497]: 24E48285C8: from=<lc_fisher@hotmail.com>, size=3800, nrcpt=1 (queue active)
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) prolong_timer fwd-data-end: remaining time = 480 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) response to data end: "250 2.0.0 Ok: queued as 24E48285C8"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) prolong_timer fwd-rundown-1: remaining time = 480 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) FWD via SMTP: <lc_fisher@hotmail.com> -> <doug@brownsearch.com>, 250 2.6.0 Ok, id=01666-19, from MTA([127.0.0.1]:10026): 250 2.0.0 Ok: queued as 24E48285C8
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) prolong_timer forwarding: remaining time = 480 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) one_response_for_all <lc_fisher@hotmail.com>: success, r=0,b=0,d=0, ndn_needed=0, '250 2.6.0 Ok, id=01666-19, from MTA([127.0.0.1]:10026): 250 2.0.0 Ok: queued as 24E48285C8'
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ndn_needed=0, exit=0, 250 2.6.0 Ok, id=01666-19, from MTA([127.0.0.1]:10026): 250 2.0.0 Ok: queued as 24E48285C8
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup: (scalar) matches, result="10"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup (spam_dsn_cutoff_level_bysender) => true,  "lc_fisher@hotmail.com" matches, result="10", matching_key="(constant:10)"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) dsn: from MTA 250 Clean <lc_fisher@hotmail.com> -> <doug@brownsearch.com>: on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=1
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) DSN: SUCC from MTA 250 Clean, no DSN requested: <lc_fisher@hotmail.com> -> <doug@brownsearch.com>
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) prolong_timer delivery-notification: remaining time = 480 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) parse_received: from = BLU139-W17 ([65.55.111.73]) /BLU139-W17//65.55.111.73
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) parse_received: by = blu0-omc2-s35.blu0.hotmail.com /blu0-omc2-s35.blu0.hotmail.com//
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) parse_received: with = Microsoft SMTPSVC/Microsoft SMTPSVC//
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) parse_received: ; = Tue, 27 Apr 2010 05:32:43 -0700/Tue, 27 Apr 2010 05:32:43 -0700//
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) fish_out_ip_from_received: 65.55.111.73, BLU139-W17 ([65.55.111.73]) 
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) lookup_ip_acl (publicnetworks): key="65.55.111.73" matches "::FFFF:0:0/96", result=1
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) best_try_originator_ip: 65.55.111.73
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) Passed CLEAN, [65.55.111.110] [65.55.111.73] <lc_fisher@hotmail.com> -> <doug@brownsearch.com>, Message-ID: <BLU139-W17338F5F8E0530E428E2D19C030@phx.gbl>, mail_id: awI7S516WKa9, Hits: -, queued_as: 24E48285C8, 758 ms
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) prolong_timer main_log_entry: remaining time = 480 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) updating snmp variables
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) prolong_timer check done: remaining time = 480 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) sending SMTP response: "250 2.6.0 Ok, id=01666-19, from MTA([127.0.0.1]:10026): 250 2.0.0 Ok: queued as 24E48285C8"
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP> 250 2.6.0 Ok, id=01666-19, from MTA([127.0.0.1]:10026): 250 2.0.0 Ok: queued as 24E48285C8
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) switch_to_client_time 480 s, smtp response sent
Apr 27 08:35:06 roadrunner postfix/smtp[807]: 4CC90285C7: to=<doug@brownsearch.com>, relay=127.0.0.1[127.0.0.1]:10025, delay=1.2, delays=0.44/0/0.38/0.39, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=01666-19, from MTA([127.0.0.1]:10026): 250 2.0.0 Ok: queued as 24E48285C8)
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) TempDir::strip: /var/spool/amavisd/tmp/amavis-20100427T082958-01666
Apr 27 08:35:06 roadrunner postfix/qmgr[1497]: 4CC90285C7: removed
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) rmdir_recursively: /var/spool/amavisd/tmp/amavis-20100427T082958-01666/parts, excl=1
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) TIMING [total 765 ms] - SMTP greeting: 283 (37%)37, SMTP EHLO: 94 (12%)49, SMTP pre-MAIL: 7 (1%)50, SMTP pre-DATA-flush: 7 (1%)51, SMTP DATA: 32 (4%)55, check_init: 1 (0%)55, digest_hdr: 1 (0%)55, digest_body: 1 (0%)55, gen_mail_id: 1 (0%)55, mime_decode: 21 (3%)58, get-file-type2: 25 (3%)61, decompose_part: 3 (0%)62, parts_decode: 0 (0%)62, check_header: 4 (1%)62, AV-scan-1: 14 (2%)64, update_cache: 4 (0%)65, decide_mail_destiny: 3 (0%)65, fwd-connect: 11 (1%)67, fwd-xforward: 1 (0%)67, fwd-mail-from: 2 (0%)67, fwd-rcpt-to: 3 (0%)67, fwd-data-cmd: 1 (0%)67, write-header: 2 (0%)68, fwd-data-contents: 1 (0%)68, fwd-data-end: 225 (29%)97, fwd-rundown: 2 (0%)97, prepare-dsn: 2 (0%)98, main_log_entry: 13 (2%)99, update_snmp: 2 (0%)100, SMTP pre-response: 1 (0%)100, SMTP response: 1 (0%)100, unlink-2-files: 1 (0%)100, rundown: 1 (0%)100
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) idle_proc, 6: was busy, 377.6 ms, total idle 290.464 s, busy 24.331 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) idle_proc, 5: was idle, 0.3 ms, total idle 290.464 s, busy 24.331 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP< QUIT\r\n
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) switch_to_my_time     480 s, SMTP QUIT received
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) switch_to_client_time 480 s, smtp response sent
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) SMTP session over, timer stopped
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) exiting process_request
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) post_process_request_hook: timer was not running
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) idle_proc, bye: was busy, 3.3 ms, total idle 290.464 s, busy 24.334 s
Apr 27 08:35:06 roadrunner amavis[1666]: (01666-19) load: 8 %, total idle 290.464 s, busy 24.334 s
Apr 27 08:35:11 roadrunner postfix/local[1641]: 24E48285C8: to=<doug@brownsearch.com>, relay=local, delay=5.2, delays=0.23/0/0/4.9, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail)
Apr 27 08:35:11 roadrunner postfix/qmgr[1497]: 24E48285C8: removed
Apr 27 08:35:15 roadrunner amavis[1666]: (01666-19) Net::Server: 2010/04/27-08:35:15 CONNECT TCP Peer: "127.0.0.1:42909" Local: "127.0.0.1:10025"
Apr 27 08:35:15 roadrunner amavis[1666]: (01666-19) idle_proc, hi : was idle, 8791.6 ms, total idle 299.255 s, busy 24.334 s
Apr 27 08:35:15 roadrunner amavis[1666]: (01666-19) loaded base policy bank
Apr 27 08:35:15 roadrunner amavis[1666]: (01666-19) lookup_ip_acl (inet_acl): key="127.0.0.1" matches "127.0.0.1", result=1
Apr 27 08:35:15 roadrunner amavis[1666]: (01666-19) process_request: fileno sock=11, STDIN=0, STDOUT=1
Apr 27 08:35:15 roadrunner amavis[1666]: (01666-19) switch_to_my_time     480 s, new request
Apr 27 08:35:15 roadrunner amavis[1666]: (01666-19) process_request: suggested_protocol="" on TCP