#2 amavis-logwtach can't handle timing messages

v1.51.03
closed
None
1
2014-08-25
2014-04-30
No

If you increase the amavis loglevel to include timing information, amavis-logwatch generates an extra 25,000 lines of output on my MTA because it doesn't recognize the info:

Unmatched Entries
1 Apr 30 04:58:17 edge01 amavis[32660]: (32660-12) size: 1682, TIMING [total 224 ms, cpu 57 ms] - SMTP greeting: 2.3 (1%)1, SMTP EHLO: 1.0 (0%)1, SMTP pre-MAIL: 0.5 (0%)2, lookup_ldap: 8 (4%)5, SMTP pre-DATA-flush: 0.8 (0%)6, SMTP DATA: 31 (14%)20, check_init: 0.3 (0%)20, digest_hdr: 1.3 (1%)20, digest_body_dkim: 0.2 (0%)20, mime_decode: 10 (5%)25, get-file-type1: 19 (8%)33, decompose_part: 0.9 (0%)34, parts_decode: 0.1 (0%)34, check_header: 1.3 (1%)34, AV-scan-1: 4.7 (2%)36, decide_mail_destiny: 0.7 (0%)37, lookup_ldap: 9 (4%)41, notif-quar: 0.1 (0%)41, fwd-connect: 7 (3%)44, fwd-mail-pip: 16 (7%)51, fwd-rcpt-pip: 0.2 (0%)51, fwd-data-chkpnt: 0.0 (0%)51, write-header: 0.9 (0%)52, fwd-data-contents: 0.1 (0%)52, fwd-end-chkpnt: 83 (37%)89, prepare-dsn: 0.7 (0%)89, main_log_entry: 14 (6%)95, update_snmp: 1.2 (1%)95, SMTP pre-response: 0.2 (0%)95, SMTP response: 7 (3%)99, unlink-2-files: 0.3 (0%)99, rundown: 2.8 (1%)100
1 Apr 30 08:31:38 edge01 amavis[59699]: (59699-03) TIMING-SA [total 3458 ms, cpu 341 ms] - parse: 5 (0.2%), extract_message_metadata: 36 (1.0%), get_uri_detail_list: 3.0 (0.1%), tests_pri_-1000: 49 (1.4%), tests_pri_-950: 1.14 (0.0%), tests_pri_-900: 1.66 (0.0%), tests_pri_-400: 33 (1.0%), check_bayes: 32 (0.9%), b_tokenize: 11 (0.3%), b_tok_get_all: 10 (0.3%), b_comp_prob: 7 (0.2%), b_tok_touch_all: 0.21 (0.0%), b_finish: 0.64 (0.0%), tests_pri_0: 519 (15.0%), check_dkim_adsp: 3.8 (0.1%), check_spf: 23 (0.7%), poll_dns_idle: 2791 (80.7%), check_razor2: 191 (5.5%), check_pyzor: 195 (5.6%), tests_pri_500: 2796 (80.9%), get_report: 0.52 (0.0%)
1 Apr 30 08:18:52 edge01 amavis[53890]: (53890-01) TIMING-SA [total 3481 ms, cpu 419 ms] - parse: 2.1 (0.1%), extract_message_metadata: 46 (1.3%), get_uri_detail_list: 4.5 (0.1%), tests_pri_-1000: 36 (1.0%), tests_pri_-950: 1.14 (0.0%), tests_pri_-900: 1.23 (0.0%), tests_pri_-400: 24 (0.7%), check_bayes: 23 (0.7%), b_tokenize: 9 (0.3%), b_tok_get_all: 6 (0.2%), b_comp_prob: 4.0 (0.1%), b_tok_touch_all: 0.09 (0.0%), b_finish: 0.90 (0.0%), tests_pri_0: 447 (12.9%), check_spf: 56 (1.6%), poll_dns_idle: 2874 (82.6%), check_razor2: 83 (2.4%), check_pyzor: 151 (4.3%), tests_pri_500: 2907 (83.5%), get_report: 0.87 (0.0%)
1 Apr 30 07:06:27 edge01 amavis[1693]: (01693-01) ...TP pre-response: 0.1 (0%)99, SMTP response: 0.5 (0%)99, unlink-4-files: 1.0 (0%)100, rundown: 1.0 (0%)100
1 Apr 30 14:51:56 edge01 amavis[53095]: (53095-09) TIMING-SA [total 3219 ms, cpu 432 ms] - parse: 6 (0.2%), extract_message_metadata: 58 (1.8%), get_uri_detail_list: 6 (0.2%), tests_pri_-1000: 79 (2.5%), tests_pri_-950: 1.15 (0.0%), tests_pri_-900: 1.35 (0.0%), tests_pri_-400: 50 (1.6%), check_bayes: 35 (1.1%), b_tokenize: 16 (0.5%), b_tok_get_all: 10 (0.3%), b_comp_prob: 6 (0.2%), b_tok_touch_all: 0.15 (0.0%), b_finish: 0.62 (0.0%), tests_pri_0: 644 (20.0%), check_dkim_adsp: 161 (5.0%), check_spf: 81 (2.5%), poll_dns_idle: 2391 (74.3%), check_razor2: 141 (4.4%), check_pyzor: 151 (4.7%), tests_pri_500: 2359 (73.3%), get_report: 0.94 (0.0%)
1 Apr 30 12:52:23 edge01 amavis[40529]: (40529-14) size: 6862, RUSAGE minflt=11693+3119, majflt=0+0, nswap=0+0, inblock=0+0, oublock=1736+24, msgsnd=0+0, msgrcv=0+0, nsignals=0+0, nvcsw=64+4, nivcsw=213+22, maxrss=110296+106160, ixrss=0+0, idrss=0+0, isrss=0+0, utime=0.365+0.022, stime=0.033+0.013
1 Apr 30 13:56:15 edge01 amavis[23971]: (23971-08) TIMING-SA [total 578 ms, cpu 327 ms] - parse: 2.8 (0.5%), extract_message_metadata: 31 (5.4%), get_uri_detail_list: 6 (1.0%), tests_pri_-1000: 56 (9.7%), tests_pri_-950: 1.47 (0.3%), tests_pri_-900: 1.21 (0.2%), tests_pri_-400: 25 (4.2%), check_bayes: 23 (4.1%), b_tokenize: 8 (1.4%), b_tok_get_all: 7 (1.1%), b_comp_prob: 6 (1.0%), b_tok_touch_all: 0.22 (0.0%), b_finish: 0.59 (0.1%), tests_pri_0: 405 (70.1%), check_spf: 0.47 (0.1%), check_razor2: 153 (26.4%), check_pyzor: 143 (24.8%), tests_pri_500: 3.9 (0.7%), learn: 44 (7.6%), b_learn: 39 (6.8%), b_count_change: 18 (3.1%), get_report: 1.36 (0.2%)
1 Apr 30 13:20:16 edge01 amavis[60382]: (60382-15) size: 221162, TIMING [total 359 ms, cpu 98 ms] - SMTP greeting: 1.5 (0%)0, SMTP EHLO: 0.5 (0%)1, SMTP pre-MAIL: 0.4 (0%)1, lookup_ldap: 3.3 (1%)2, lookup_ldap: 2.1 (1%)2, lookup_ldap: 4.0 (1%)3, SMTP pre-DATA-flush: 0.6 (0%)3, SMTP DATA: 34 (9%)13, check_init: 0.2 (0%)13, digest_hdr: 1.0 (0%)13, digest_body_dkim: 1.1 (0%)13, mime_decode: 36 (10%)24, get-file-type3: 16 (4%)28, decompose_part: 1.6 (0%)28, parts_decode: 0.1 (0%)28, check_header: 0.8 (0%)29, AV-scan-1: 124 (35%)63, decide_mail_destiny: 0.7 (0%)63, lookup_ldap: 6 (2%)65, notif-quar: 0.0 (0%)65, fwd-connect: 4.0 (1%)66, fwd-mail-pip: 16 (4%)71, fwd-rcpt-pip: 0.3 (0%)71, fwd-data-chkpnt: 0.0 (0%)71, write-header: 0.5 (0%)71, fwd-data-contents: 7 (2%)73, fwd-end-chkpnt: 87 (24%)97, prepare-dsn: 0.6 (0%)97, main_log_entry: 6 (2%)99, update_snmp: 1.7 (0%)99, SMTP pre-response: 1.2 (0%)100, SMTP response: 0.4 (0%)100, unlink-4-files: 0.4 (0%)100, rundown: 1.0 (0%)100
1 Apr 30 14:34:24 edge01 amavis[38682]: (38682-19) size: 111580, TIMING [total 1688 ms, cpu 1261 ms, AM-cpu 77 ms, SA-cpu 1184 ms] - SMTP greeting: 1.7 (0%)0, SMTP EHLO: 0.4 (0%)0, SMTP pre-MAIL: 0.5 (0%)0, lookup_ldap: 3.4 (0%)0, SMTP pre-DATA-flush: 2.2 (0%)0, SMTP DATA: 36 (2%)3, check_init: 0.7 (0%)3, digest_hdr: 3.5 (0%)3, digest_body_dkim: 10 (1%)3, mime_decode: 22 (1%)5, get-file-type3: 14 (1%)6, decompose_part: 1.0 (0%)6, parts_decode: 0.1 (0%)6, check_header: 0.7 (0%)6, spam-wb-list: 2.1 (0%)6, SA msg read: 0.6 (0%)6, SA parse: 11 (1%)7, SA check: 1501 (89%)95, decide_mail_destiny: 9 (1%)96, notif-quar: 0.4 (0%)96, fwd-connect: 3.3 (0%)96, fwd-mail-pip: 7 (0%)97, fwd-rcpt-pip: 0.1 (0%)97, fwd-data-chkpnt: 0.0 (0%)97, write-header: 0.6 (0%)97, fwd-data-contents: 3.0 (0%)97, fwd-end-chkpnt: 46 (3%)100, prepare-dsn: 0.5 (0%)100, main_log_entry: 4.2 (0%)100, update_snmp: 0.5 (0%)100, SMTP pre-response: 0.8 (0%)100, SMTP response: 0.3 (0%)100, unlink-3-files: 0.3 (0%)100, rundown: 1.1 (0%)100
1 Apr 30 05:23:21 edge01 amavis[55132]: (55132-18) ...s: 0.3 (0%)100, rundown: 0.9 (0%)100

(etc)

Discussion

  • MrC
    MrC
    2014-04-30

    Replied via email. This is already fixed in the code, but have not pushed out a release. I'll get you a release to test if you're willing.

     
    • status: open --> pending
    • assigned_to: MrC --> Quanah Gibson-Mount
     
    • Group: v1.0_(example) --> v1.51.03
     
    • status: pending --> closed