Skip to content

Instantly share code, notes, and snippets.

@mmalmeida

mmalmeida/amavis.log Secret

Created September 17, 2018 18:46
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save mmalmeida/b3523d9ec2fbab5d4aac3fed28961bf1 to your computer and use it in GitHub Desktop.
Save mmalmeida/b3523d9ec2fbab5d4aac3fed28961bf1 to your computer and use it in GitHub Desktop.
Download ZIP
Log of delivery to virtual domain
Raw
amavis.log
Sep 17 19:26:58 mailserver amavis[14054]: (14054-01) SpamControl: calling spam scanner SpamAssassin
Sep 17 19:26:58 mailserver amavis[14054]: (14054-01) get_deadline spam_scan_sa_pre - deadline in 479.7 s, set to 476.000 s
Sep 17 19:26:58 mailserver amavis[14054]: (14054-01) prolong_timer spam_scan_sa_pre: timer 476, was 288, deadline in 479.7 s
Sep 17 19:26:58 mailserver amavis[14054]: (14054-01) SA user config: "", username: "amavis", 0, (0)info@bbv.com
Sep 17 19:26:58 mailserver amavis[14054]: (14054-01) calling SA parse (0), SA vers 3.4.1, 3.004001, data as STRING_REF, recips_ind [0], user: "amavis"
Sep 17 19:26:58 mailserver amavis[14054]: (14054-01) get_deadline SA check - deadline in 479.7 s, set to 475.000 s
Sep 17 19:26:58 mailserver amavis[14054]: (14054-01) CALLING SA check (0)
Sep 17 19:26:58 mailserver amavis[14054]: (14054-01) _WARN: bayes: cannot open bayes databases /var/lib/amavis/.spamassassin/bayes_* R/O: tie failed: Permission denied
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) _WARN: bayes: cannot open bayes databases /var/lib/amavis/.spamassassin/bayes_* R/W: tie failed: Permission denied
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) DONE SA check (0)
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) get_deadline spam_scan_sa - deadline in 477.9 s, set to 287.000 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) prolong_timer spam_scan_sa: timer 287, was 475, deadline in 477.9 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) spam_scan: score=-0.099 autolearn=unavailable autolearn_force=no tests=[DKIM_SIGNED=0.1,DKIM_VALID=-0.1,DKIM_VALID_AU=-0.1,FREEMAIL_FROM=0.001,HTML_M
ESSAGE=0.001,RCVD_IN_DNSWL_NONE=-0.0001,SPF_PASS=-0.001] recips=0
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) get_deadline spam_scan - deadline in 477.9 s, set to 287.000 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) prolong_timer spam_scan: timer 287, was 287, deadline in 477.9 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) lookup => undef, "@gmail.com", no lookup tables
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) lookup: (scalar) matches, result="-20"
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) lookup [spam_tag_level] => true, "info@bbv.com" matches, result="-20", matching_key="(constant:-20)"
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) lookup: (scalar) matches, result="5"
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) lookup [spam_tag2_level] => true, "info@bbv.com"qes not match
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) lookup: (scalar) matches, result="5"
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) lookup [spam_kill_level] => true, "info@bbv.com" matches, result="5", matching_key="(constant:5)"
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) final_destiny (ccat=0) is PASS, recip info@bbv.com
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) final_destiny PASS, recip info@bbv.com
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) do_notify_and_quar: ccat=CleanTag (1,1) ("1,1":CleanTag, "1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) do_notify_and_quarantine: not quarantining, q_method off
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) skip admin notification, no administrators
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) do_notify_and_quarantine - done
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) lookup [forward_method] => true, "info@bbv.com" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) delivery method is 1, recips: info@bbv.com
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) lookup: (scalar) matches, result="-20"
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) lookup [spam_tag_level] => true, "info@bbv.com" matches, result="-20", matching_key="(constant:-20)"
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) lookup: (scalar) matches, result="5"
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) lookup [spam_tag2_level] => true, "info@bbv.com" matches, result="5", matching_key="(constant:5)"
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) headers CLUSTERING: NEW CLUSTER <info@bbv.com>: score=-0.099, tag=1, tag2=0, local=0, bl=, s=, mangle=
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) header encoded (all-ASCII): X-Virus-Scanned: Debian amavisd-new at itc.com
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) header: X-Virus-Scanned: Debian amavisd-new at itc.com\n
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) header encoded (all-ASCII): Received: from mailserver.itc.com ([127.0.0.1])\n by localhost (mail.itc.com [127.0.0.1]) (amavisd-new, port 10024)\n with ESMTP\n id E2w_rPHD-Qeu\n for <info@bbv.com>;\n Mon, 17 Sep 2018 19:26:58 +0100 (WEST)
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) header: Received: from mailserver.itc.com ([127.0.0.1])\n\tby localhost (mail.itc.com [127.0.0.1]) (amavisd-new, port 10024)\n\twith ESMTP id E2w_rPHD-Qeu for <info@bbv.com>;\n\tMon, 17 Sep 2018 19:26:58 +0100 (WEST)\n
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) headers CLUSTERING: done all 1 recips in one go
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) about to connect to smtp:[127.0.0.1]:10025, E2w_rPHD-Qeu FWD from <mma@gmail.com> -> <info@bbv.com>
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) get_deadline fwd_init - deadline in 477.8 s, set to 478.000 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) smtp session: setting up a new session
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) establish_or_refresh, state: down
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) new socket using IO::Socket::IP to [127.0.0.1]:10025, timeout 35
Sep 17 19:27:00 mailserver postfix/smtpd[14008]: connect from localhost[127.0.0.1]
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) connected to [127.0.0.1]:10025 successfully
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop: needline=1, flush=0, wr=0, timeout=35
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop: receiving
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop read 58 chars< 220 mailserver.itc.com ESMTP Postfix (Ubuntu)\r\n
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) smtp greeting: 220 mailserver.itc.com ESMTP Postfix (Ubuntu), dt: 5.4 ms
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) smtp cmd> EHLO localhost
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop: needline=0, flush=1, wr=1, timeout=300
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop: sending 16 chars
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop sent 16> EHLO localhost\r\n
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop: receiving
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop read 188 chars< 250-mailserver.itc.com\r\n250-PIPELINING\r\n250-SIZE 40480000\r\n250-ETRN\r\n250-STARTTLS\r\n250-AUTH PLAIN\r\n250-AUTH=PLAIN\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250-DSN\r\n250 SMTPUTF8\r\n
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) smtp resp to EHLO: 250 mailserver.itc.com\nPIPELINING\nSIZE 40480000\nETRN\nSTARTTLS\nAUTH PLAIN\nAUTH=PLAIN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN\nSMTPUTF8
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) tls active=0, capable=1, sec_level=0
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) Remote host presents itself as: mailserver.itc.com, handles DSN, PIPELINING, 8BITMIME, SMTPUTF8
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) AUTH not needed, user='', MTA offers 'PLAIN'
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) smtp cmd> MAIL FROM:<mma@gmail.com> BODY=7BIT
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) orcpt_encode rfc822, info@bbv.com, encode_for_smtp
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) smtp cmd> RCPT TO:<info@bbv.com> ORCPT=rfc822;info@bbv.com
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) smtp cmd> DATA
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop: needline=0, flush=1, wr=1, timeout=120
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop: sending 129 chars
Sep 17 19:27:00 mailserver postfix/smtpd[14008]: 91481507564: client=localhost[127.0.0.1]
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop sent 129> MAIL FROM:<mma@gmail.com> BODY=7BIT\r\nRCPT TO:<info@bbv.com> ORCPT=rfc822;info@bbv.com\r\nDATA\r\n
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop: receiving
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop read 65 chars< 250 2.1.0 Ok\r\n250 2.1.5 Ok\r\n354 End data with <CR><LF>.<CR><LF>\r\n
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) smtp resp to MAIL (pip): 250 2.1.0 Ok
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) smtp resp to RCPT (pip) (<info@bbv.com>): 250 2.1.5 Ok
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) write_header: 1, Amavis::Out::SMTP::Protocol=HASH(0x8f4f4f8)
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop: needline=1, flush=0, wr=1, timeout=477.974
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop: sending 5842 chars
Sep 17 19:27:00 mailserver postfix/cleanup[14061]: 91481507564: message-id=<CA+AeW30mFwdx3RBPB-5_3C50ZTKgjLXRZDd7X-H1osUi0SjrYQ@mail.gmail.com>
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop sent 5842> X-Virus-Scanned: Debian amavisd-new at itc.com\r\nReceived: from mailserver.itc.com ([127.0.0.1])\r\n\tby localhost (mail.itc.com [127.0.0.1]) (amavisd-new, port 10024)\r\n\twith ESMT [...]
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop: needline=1, flush=0, wr=0, timeout=477.974
Sep 17 19:27:00 mailserver postfix/qmgr[18272]: 91481507564: from=<mma@gmail.com>, size=6034, nrcpt=3 (queue active)
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop: receiving
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) rw_loop read 37 chars< 250 2.0.0 Ok: queued as 91481507564\r\n
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) smtp resp to data-dot (<info@bbv.com>): 250 2.0.0 Ok: queued as 91481507564, dt: 114.1 ms
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) Amavis::Out::SMTP::Session close, keeping connection
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) get_deadline fwd-end-chkpnt - deadline in 477.7 s, set to 287.000 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) prolong_timer fwd-end-chkpnt: timer 287, was 0, deadline in 477.7 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) E2w_rPHD-Qeu FWD from <mma@gmail.com> -> <info@bbv.com>, BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 91481507564
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) get_deadline forwarding - deadline in 477.7 s, set to 287.000 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) prolong_timer forwarding: timer 287, was 287, deadline in 477.7 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) DSN: sender is credible (dkim), SA: -0.099, <mma@gmail.com>
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) lookup [spam_crediblefrom_dsn_cutoff_level_bysender] => undef, "mma@gmail.com" does not match
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) dsn: from MTA 250 NonBlocking:CleanTag <mma@gmail.com> -> <info@bbv.com>: on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=1, destiny=1, mta_resp: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 91481507564"
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) DSN: SUCC from MTA 250 NonBlocking:CleanTag, no DSN requested: <mma@gmail.com> -> <info@bbv.com>
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) delivery_status_notification: notif 0 bytes, suppressed: no
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) one_response_for_all, per_recip_capable: N, suppressed: N
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) one_response_for_all <mma@gmail.com>: success, r=0,b=0,d=0, ndn_needed=0, '250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 91481507564'
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) notif=N, suppressed=0, ndn_needed=0, exit=0, 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 91481507564
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) Amavis::Out::SMTP::Session close, keeping connection
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) get_deadline fwd-end-chkpnt - deadline in 477.7 s, set to 287.000 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) prolong_timer fwd-end-chkpnt: timer 287, was 0, deadline in 477.7 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) E2w_rPHD-Qeu FWD from <mma@gmail.com> -> <info@bbv.com>, BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 91481507564
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) get_deadline forwarding - deadline in 477.7 s, set to 287.000 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) prolong_timer forwarding: timer 287, was 287, deadline in 477.7 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) DSN: sender is credible (dkim), SA: -0.099, <mma@gmail.com>
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) lookup [spam_crediblefrom_dsn_cutoff_level_bysender] => undef, "mma@gmail.com" does not match
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) dsn: from MTA 250 NonBlocking:CleanTag <mma@gmail.com> -> <info@bbv.com>: on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=1, destiny=1, mta_resp: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 91481507564"
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) DSN: SUCC from MTA 250 NonBlocking:CleanTag, no DSN requested: <mma@gmail.com> -> <info@bbv.com>
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) delivery_status_notification: notif 0 bytes, suppressed: no
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) one_response_for_all, per_recip_capable: N, suppressed: N
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) one_response_for_all <mma@gmail.com>: success, r=0,b=0,d=0, ndn_needed=0, '250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 91481507564'
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) notif=N, suppressed=0, ndn_needed=0, exit=0, 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 91481507564
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) get_deadline delivery-notification - deadline in 477.7 s, set to 287.000 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) prolong_timer delivery-notification: timer 287, was 287, deadline in 477.7 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedOpenRelay}
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) get_deadline snmp-counters - deadline in 477.7 s, set to 287.000 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) prolong_timer snmp-counters: timer 287, was 287, deadline in 477.7 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) orcpt_encode rfc822, info@bbv.com, smtputf8
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) oldest_public_ip_addr_from_received: 209.85.208.173
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) Passed CLEAN {RelayedOpenRelay}, [209.85.208.173]:45670 [209.85.208.173] <mma@gmail.com> -> <info@bbv.com>, Queue-ID: 0F163507555, Message-ID: <CA+AeW30mFwdx3RBPB-5_3C50ZTKgjLXRZDd7X-H1osUi0SjrYQ@mail.gmail.com>, mail_id: E2w_rPHD-Qeu, Hits: -0.099, size: 5547, queued_as: 91481507564, dkim_sd=20161025:gmail.com, 2405 ms
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) get_deadline main_log_entry - deadline in 477.7 s, set to 287.000 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) prolong_timer main_log_entry: timer 287, was 287, deadline in 477.7 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) TIMING-SA total 1799 ms - parse: 6 (0.4%), extract_message_metadata: 14 (0.8%), get_uri_detail_list: 2.4 (0.1%), tests_pri_-1000: 4.4 (0.2%), tests_pri_-950: 1.32 (0.1%), tests_pri_-900: 1.45 (0.1%), tests_pri_-400: 2.4 (0.1%), tests_pri_0: 1726 (96.0%), check_spf: 64 (3.5%), poll_dns_idle: 37 (2.0%), check_razor2: 1518 (84.4%), check_pyzor: 50 (2.8%), tests_pri_500: 5.0 (0.3%), learn: 7 (0.4%), b_learn: 2.9 (0.2%), get_report: 0.92 (0.1%)
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) updating snmp variables in BDB
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) get_deadline check done - deadline in 477.7 s, set to 287.000 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) prolong_timer check done: timer 287, was 287, deadline in 477.7 s
Sep 17 19:27:00 mailserver amavis[14054]: (14054-01) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 91481507564"
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment