[GH-ISSUE #24] No DSN data parsed #17

Closed
opened 2026-05-05 14:59:11 -06:00 by gitea-mirror · 5 comments
Owner

Originally created by @DocLowy on GitHub (Oct 5, 2014).
Original GitHub issue: https://github.com/darold/sendmailanalyzer/issues/24

No DSN records are parsed on my system.

Debug info from sendmailanalyzer

root:~# /usr/local/sendmailanalyzer/sendmailanalyzer -f -b -d
Running in verbose mode...
    sendmailanalyzer v9.0. (c) 2002-2014 - Gilles Darold <gilles@darold.net>
DEBUG: Detach from terminal with pid: 17041
DEBUG: Entering main loop...
DEBUG: Parsing full /var/log/mail.log
DEBUG: Flushing data to disk...
DEBUG: Writing sender data to disk...
DEBUG:  Wrote 276 sender objects
DEBUG: Writing reject data to disk...
DEBUG:  Wrote 392 reject object.
DEBUG: Writing DSN data to disk...
*DEBUG:     Wrote 0 DSN object.*
DEBUG: Writing recipient data to disk...
DEBUG:  Wrote 263 recipient object.
DEBUG: Writing Spam data to disk...
DEBUG:  Wrote 8 spam object.
DEBUG: Writing Spam detail data to disk...
DEBUG: Writing Spam detail for amavis into [...]/2014/10/05/amavis.dat
DEBUG: Writing Spam detail for dnsbl into [...]/2014/10/05/dnsbl.dat
DEBUG:  Wrote 8 spam detail object.
DEBUG: Writing Postgrey detail data to disk...
DEBUG:  Wrote 8 postgrey object.
DEBUG: Writing Virus data to disk...
DEBUG:  Wrote 0 virus object.
DEBUG: Writing syserr data to disk...
DEBUG:  Wrote 911 syserr object.
DEBUG: Writing warning message data to disk...
DEBUG:  Wrote 6 warning message object.
DEBUG: Writing warning auth data to disk...
DEBUG:  Wrote 7 auth object.
DEBUG: Writing last parsed line...

A "grep" on mail.log shows 532 deliveries

root:~# grep 'status=sent' /var/log/mail.log |wc -l
532

Inbound traffic example

Oct  5 19:30:48 xxxxxx postfix/smtpd[16932]: connect from st11p05mm-asmtp002.mac.com[17.172.108.250]
Oct  5 19:30:49 xxxxxx postfwd2/policy[11195]: [DNSBL] 17.172.108.250 listed on rbl:list.dnswl.org (answer: 127.0.5.2, time: 0.01s, ttl: 43200s, 'mac.com http://dnswl.org/s?s=1776')
Oct  5 19:30:49 xxxxxx postfwd2/policy[11195]: [RULES] rule=0, id=OK_DNSWL, client=st11p05mm-asmtp002.mac.com[17.172.108.250], sender=<aaa@bbb.com>, recipient=<xxx@yyy.de>, helo=<st11p05mm-asmtp002.mac.com>, proto=ESMTP, state=RCPT, delay=0.02s, hits=OK_DNSWL, action=OK
Oct  5 19:30:49 xxxxxx postfix/smtpd[16932]: 0CB3413C018D: client=st11p05mm-asmtp002.mac.com[17.172.108.250]
Oct  5 19:30:49 xxxxxx postfix/cleanup[21999]: 0CB3413C018D: message-id=<D4A7FFF1-29DA-4EAF-B029-BCD8E5389747@me.com>
Oct  5 19:30:49 xxxxxx postfix/qmgr[10619]: 0CB3413C018D: from=<aaa@bbb.com>, size=1337, nrcpt=1 (queue active)
Oct  5 19:30:49 xxxxxx postfix/smtpd[16932]: disconnect from st11p05mm-asmtp002.mac.com[17.172.108.250]
Oct  5 19:30:49 xxxxxx postfix/smtpd[22003]: connect from localhost.localdomain[127.0.0.1]
Oct  5 19:30:49 xxxxxx postfix/smtpd[22003]: 79A3A13C0578: client=localhost.localdomain[127.0.0.1]
Oct  5 19:30:49 xxxxxx postfix/cleanup[21999]: 79A3A13C0578: message-id=<D4A7FFF1-29DA-4EAF-B029-BCD8E5389747@me.com>
Oct  5 19:30:49 xxxxxx postfix/smtpd[22003]: disconnect from localhost.localdomain[127.0.0.1]
Oct  5 19:30:49 xxxxxx postfix/qmgr[10619]: 79A3A13C0578: from=<aaa@bbb.com>, size=1791, nrcpt=1 (queue active)
Oct  5 19:30:49 xxxxxx amavis[19981]: (19981-07) Passed CLEAN {RelayedInbound}, [17.172.108.250]:37214 [88.134.138.69] <aaa@bbb.com> -> <xxx@yyy.de>, Queue-ID: 0CB3413C018D, Message-ID: <D4A7FFF1-29DA-4EAF-B029-BCD8E5389747@me.com>, mail_id: CZzPtLQlvLe1, Hits: -1.9, size: 1337, queued_as: 79A3A13C0578, 352 ms
Oct  5 19:30:49 xxxxxx postfix/smtp[22000]: 0CB3413C018D: to=<xxx@yyy.de>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.58, delays=0.21/0.01/0/0.35, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 79A3A13C0578)
Oct  5 19:30:49 xxxxxx postfix/qmgr[10619]: 0CB3413C018D: removed
Oct  5 19:30:49 xxxxxx dovecot: lda(xxx@yyy.de): sieve: msgid=<D4A7FFF1-29DA-4EAF-B029-BCD8E5389747@me.com>: stored mail into mailbox 'INBOX'
Oct  5 19:30:49 xxxxxx postfix/pipe[22004]: 79A3A13C0578: to=<xxx@yyy.de>, relay=dovecot, delay=0.25, delays=0.09/0.01/0/0.15, dsn=2.0.0, status=sent (delivered via dovecot service)
Oct  5 19:30:49 xxxxxx postfix/qmgr[10619]: 79A3A13C0578: removed

Outbound traffic example

Oct  5 19:44:09 xxxxxx postfix/smtpd[23496]: connect from unknown[11.22.33.44]
Oct  5 19:44:09 xxxxxx postfix/smtpd[23496]: 9476813C015D: client=unknown[11.22.33.44], sasl_method=PLAIN, sasl_username=xxx@yyy.de
Oct  5 19:44:09 xxxxxx postfix/cleanup[23498]: 9476813C015D: message-id=<54318369.6070507@yyy.de>
Oct  5 19:44:09 xxxxxx postfix/qmgr[10619]: 9476813C015D: from=<xxx@yyy.de>, size=4658, nrcpt=1 (queue active)
Oct  5 19:44:09 xxxxxx postfix/smtpd[23496]: disconnect from unknown[11.22.33.44]
Oct  5 19:44:10 xxxxxx postfix/smtpd[23502]: connect from localhost.localdomain[127.0.0.1]
Oct  5 19:44:10 xxxxxx postfix/smtpd[23502]: 147D813C018D: client=localhost.localdomain[127.0.0.1]
Oct  5 19:44:10 xxxxxx postfix/cleanup[23498]: 147D813C018D: message-id=<54318369.6070507@yyy.de>
Oct  5 19:44:10 xxxxxx postfix/qmgr[10619]: 147D813C018D: from=<xxx@yyy.de>, size=5120, nrcpt=1 (queue active)
Oct  5 19:44:10 xxxxxx postfix/smtpd[23502]: disconnect from localhost.localdomain[127.0.0.1]
Oct  5 19:44:10 xxxxxx amavis[19981]: (19981-14) Passed CLEAN {RelayedOpenRelay}, [11.22.33.44]:62460 [11.22.33.44] <xxx@yyy.de> -> <aaa@bbb@com>, Queue-ID: 9476813C015D, Message-ID: <54318369.6070507@yyy.de>, mail_id: tza8DTSKUjpO, Hits: -2.9, size: 4657, queued_as: 147D813C018D, 404 ms
Oct  5 19:44:10 xxxxxx postfix/smtp[23499]: 9476813C015D: to=<aaa@bbb@com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.57, delays=0.15/0.01/0/0.4, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 147D813C018D)
Oct  5 19:44:10 xxxxxx postfix/qmgr[10619]: 9476813C015D: removed
Oct  5 19:44:15 xxxxxx postfix/smtp[23503]: 147D813C018D: to=<aaa@bbb@com>, relay=mx5.mail.icloud.com[17.172.34.68]:25, delay=4.9, delays=0.05/0.01/2.8/2, dsn=2.5.0, status=sent (250 2.5.0 Ok, envelope id 0NCZ00FDUFXP3XK0@st11p00mm-smtpin016.mac.com)
Oct  5 19:44:15 xxxxxx postfix/qmgr[10619]: 147D813C018D: removed
Oct  5 19:44:18 xxxxxx dovecot: imap-login: Login: user=<xxx@yyy.de>, method=PLAIN, rip=11.22.33.44, lip=99.88.77.66, mpid=23505, TLS, session=<7Rb2g7AEAwBYhopF>
Oct  5 19:44:27 xxxxxx postfix/smtpd[18410]: connect from localhost.localdomain[127.0.0.1]
Oct  5 19:44:27 xxxxxx postfix/smtpd[18410]: disconnect from localhost.localdomain[127.0.0.1]

Any ideas?

KR, Wolfgang

Originally created by @DocLowy on GitHub (Oct 5, 2014). Original GitHub issue: https://github.com/darold/sendmailanalyzer/issues/24 No DSN records are parsed on my system. ### Debug info from sendmailanalyzer ``` root:~# /usr/local/sendmailanalyzer/sendmailanalyzer -f -b -d Running in verbose mode... sendmailanalyzer v9.0. (c) 2002-2014 - Gilles Darold <gilles@darold.net> DEBUG: Detach from terminal with pid: 17041 DEBUG: Entering main loop... DEBUG: Parsing full /var/log/mail.log DEBUG: Flushing data to disk... DEBUG: Writing sender data to disk... DEBUG: Wrote 276 sender objects DEBUG: Writing reject data to disk... DEBUG: Wrote 392 reject object. DEBUG: Writing DSN data to disk... *DEBUG: Wrote 0 DSN object.* DEBUG: Writing recipient data to disk... DEBUG: Wrote 263 recipient object. DEBUG: Writing Spam data to disk... DEBUG: Wrote 8 spam object. DEBUG: Writing Spam detail data to disk... DEBUG: Writing Spam detail for amavis into [...]/2014/10/05/amavis.dat DEBUG: Writing Spam detail for dnsbl into [...]/2014/10/05/dnsbl.dat DEBUG: Wrote 8 spam detail object. DEBUG: Writing Postgrey detail data to disk... DEBUG: Wrote 8 postgrey object. DEBUG: Writing Virus data to disk... DEBUG: Wrote 0 virus object. DEBUG: Writing syserr data to disk... DEBUG: Wrote 911 syserr object. DEBUG: Writing warning message data to disk... DEBUG: Wrote 6 warning message object. DEBUG: Writing warning auth data to disk... DEBUG: Wrote 7 auth object. DEBUG: Writing last parsed line... ``` A "grep" on mail.log shows 532 deliveries ``` root:~# grep 'status=sent' /var/log/mail.log |wc -l 532 ``` ### Inbound traffic example ``` Oct 5 19:30:48 xxxxxx postfix/smtpd[16932]: connect from st11p05mm-asmtp002.mac.com[17.172.108.250] Oct 5 19:30:49 xxxxxx postfwd2/policy[11195]: [DNSBL] 17.172.108.250 listed on rbl:list.dnswl.org (answer: 127.0.5.2, time: 0.01s, ttl: 43200s, 'mac.com http://dnswl.org/s?s=1776') Oct 5 19:30:49 xxxxxx postfwd2/policy[11195]: [RULES] rule=0, id=OK_DNSWL, client=st11p05mm-asmtp002.mac.com[17.172.108.250], sender=<aaa@bbb.com>, recipient=<xxx@yyy.de>, helo=<st11p05mm-asmtp002.mac.com>, proto=ESMTP, state=RCPT, delay=0.02s, hits=OK_DNSWL, action=OK Oct 5 19:30:49 xxxxxx postfix/smtpd[16932]: 0CB3413C018D: client=st11p05mm-asmtp002.mac.com[17.172.108.250] Oct 5 19:30:49 xxxxxx postfix/cleanup[21999]: 0CB3413C018D: message-id=<D4A7FFF1-29DA-4EAF-B029-BCD8E5389747@me.com> Oct 5 19:30:49 xxxxxx postfix/qmgr[10619]: 0CB3413C018D: from=<aaa@bbb.com>, size=1337, nrcpt=1 (queue active) Oct 5 19:30:49 xxxxxx postfix/smtpd[16932]: disconnect from st11p05mm-asmtp002.mac.com[17.172.108.250] Oct 5 19:30:49 xxxxxx postfix/smtpd[22003]: connect from localhost.localdomain[127.0.0.1] Oct 5 19:30:49 xxxxxx postfix/smtpd[22003]: 79A3A13C0578: client=localhost.localdomain[127.0.0.1] Oct 5 19:30:49 xxxxxx postfix/cleanup[21999]: 79A3A13C0578: message-id=<D4A7FFF1-29DA-4EAF-B029-BCD8E5389747@me.com> Oct 5 19:30:49 xxxxxx postfix/smtpd[22003]: disconnect from localhost.localdomain[127.0.0.1] Oct 5 19:30:49 xxxxxx postfix/qmgr[10619]: 79A3A13C0578: from=<aaa@bbb.com>, size=1791, nrcpt=1 (queue active) Oct 5 19:30:49 xxxxxx amavis[19981]: (19981-07) Passed CLEAN {RelayedInbound}, [17.172.108.250]:37214 [88.134.138.69] <aaa@bbb.com> -> <xxx@yyy.de>, Queue-ID: 0CB3413C018D, Message-ID: <D4A7FFF1-29DA-4EAF-B029-BCD8E5389747@me.com>, mail_id: CZzPtLQlvLe1, Hits: -1.9, size: 1337, queued_as: 79A3A13C0578, 352 ms Oct 5 19:30:49 xxxxxx postfix/smtp[22000]: 0CB3413C018D: to=<xxx@yyy.de>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.58, delays=0.21/0.01/0/0.35, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 79A3A13C0578) Oct 5 19:30:49 xxxxxx postfix/qmgr[10619]: 0CB3413C018D: removed Oct 5 19:30:49 xxxxxx dovecot: lda(xxx@yyy.de): sieve: msgid=<D4A7FFF1-29DA-4EAF-B029-BCD8E5389747@me.com>: stored mail into mailbox 'INBOX' Oct 5 19:30:49 xxxxxx postfix/pipe[22004]: 79A3A13C0578: to=<xxx@yyy.de>, relay=dovecot, delay=0.25, delays=0.09/0.01/0/0.15, dsn=2.0.0, status=sent (delivered via dovecot service) Oct 5 19:30:49 xxxxxx postfix/qmgr[10619]: 79A3A13C0578: removed ``` ### Outbound traffic example ``` Oct 5 19:44:09 xxxxxx postfix/smtpd[23496]: connect from unknown[11.22.33.44] Oct 5 19:44:09 xxxxxx postfix/smtpd[23496]: 9476813C015D: client=unknown[11.22.33.44], sasl_method=PLAIN, sasl_username=xxx@yyy.de Oct 5 19:44:09 xxxxxx postfix/cleanup[23498]: 9476813C015D: message-id=<54318369.6070507@yyy.de> Oct 5 19:44:09 xxxxxx postfix/qmgr[10619]: 9476813C015D: from=<xxx@yyy.de>, size=4658, nrcpt=1 (queue active) Oct 5 19:44:09 xxxxxx postfix/smtpd[23496]: disconnect from unknown[11.22.33.44] Oct 5 19:44:10 xxxxxx postfix/smtpd[23502]: connect from localhost.localdomain[127.0.0.1] Oct 5 19:44:10 xxxxxx postfix/smtpd[23502]: 147D813C018D: client=localhost.localdomain[127.0.0.1] Oct 5 19:44:10 xxxxxx postfix/cleanup[23498]: 147D813C018D: message-id=<54318369.6070507@yyy.de> Oct 5 19:44:10 xxxxxx postfix/qmgr[10619]: 147D813C018D: from=<xxx@yyy.de>, size=5120, nrcpt=1 (queue active) Oct 5 19:44:10 xxxxxx postfix/smtpd[23502]: disconnect from localhost.localdomain[127.0.0.1] Oct 5 19:44:10 xxxxxx amavis[19981]: (19981-14) Passed CLEAN {RelayedOpenRelay}, [11.22.33.44]:62460 [11.22.33.44] <xxx@yyy.de> -> <aaa@bbb@com>, Queue-ID: 9476813C015D, Message-ID: <54318369.6070507@yyy.de>, mail_id: tza8DTSKUjpO, Hits: -2.9, size: 4657, queued_as: 147D813C018D, 404 ms Oct 5 19:44:10 xxxxxx postfix/smtp[23499]: 9476813C015D: to=<aaa@bbb@com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.57, delays=0.15/0.01/0/0.4, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 147D813C018D) Oct 5 19:44:10 xxxxxx postfix/qmgr[10619]: 9476813C015D: removed Oct 5 19:44:15 xxxxxx postfix/smtp[23503]: 147D813C018D: to=<aaa@bbb@com>, relay=mx5.mail.icloud.com[17.172.34.68]:25, delay=4.9, delays=0.05/0.01/2.8/2, dsn=2.5.0, status=sent (250 2.5.0 Ok, envelope id 0NCZ00FDUFXP3XK0@st11p00mm-smtpin016.mac.com) Oct 5 19:44:15 xxxxxx postfix/qmgr[10619]: 147D813C018D: removed Oct 5 19:44:18 xxxxxx dovecot: imap-login: Login: user=<xxx@yyy.de>, method=PLAIN, rip=11.22.33.44, lip=99.88.77.66, mpid=23505, TLS, session=<7Rb2g7AEAwBYhopF> Oct 5 19:44:27 xxxxxx postfix/smtpd[18410]: connect from localhost.localdomain[127.0.0.1] Oct 5 19:44:27 xxxxxx postfix/smtpd[18410]: disconnect from localhost.localdomain[127.0.0.1] ``` Any ideas? KR, Wolfgang
Author
Owner

@darold commented on GitHub (Oct 6, 2014):

Hi Wolfgang,

DSN are only available for sendmail logs. They are clearly identified and retrieved with the following regex:

$str =~ m#^([^:\s]+): ([^:\s]+): (DSN|return to sender|sender notify|postmaster notify): (.*)#

Posfix does not have such log entry, so it is impossible to detect.

<!-- gh-comment-id:57979773 --> @darold commented on GitHub (Oct 6, 2014): Hi Wolfgang, DSN are only available for sendmail logs. They are clearly identified and retrieved with the following regex: ``` $str =~ m#^([^:\s]+): ([^:\s]+): (DSN|return to sender|sender notify|postmaster notify): (.*)# ``` Posfix does not have such log entry, so it is impossible to detect.
Author
Owner

@DocLowy commented on GitHub (Oct 6, 2014):

ok, make sense. 😁
would it make sense to hide this menu entry from from menu on postfix systems, means "do not make a menu entry if no dsn.dat exist"!?

BTW... I sent you a private mail 3 days ago, requesting a parsing for postfwd2 spam system. Maybe it got lost. Should I make a new issue for that on GitHub?

Kind regards, Wolfgang

<!-- gh-comment-id:58058266 --> @DocLowy commented on GitHub (Oct 6, 2014): ok, make sense. :grin: would it make sense to hide this menu entry from from menu on postfix systems, means "do not make a menu entry if no dsn.dat exist"!? BTW... I sent you a private mail 3 days ago, requesting a parsing for postfwd2 spam system. Maybe it got lost. Should I make a new issue for that on GitHub? Kind regards, Wolfgang
Author
Owner

@darold commented on GitHub (Oct 6, 2014):

I will see to remove that menu with postfix log unless someone knwo how to identify them on pstfix logs.

Yes I received your log and they have been put in my fifo (feature in feature out) :-) I will work on it as soon as I found enough spare time to work on it. Thanks for your help to build a better project.

Regards

<!-- gh-comment-id:58080041 --> @darold commented on GitHub (Oct 6, 2014): I will see to remove that menu with postfix log unless someone knwo how to identify them on pstfix logs. Yes I received your log and they have been put in my fifo (feature in feature out) :-) I will work on it as soon as I found enough spare time to work on it. Thanks for your help to build a better project. Regards
Author
Owner

@DocLowy commented on GitHub (Oct 6, 2014):

maybe this code is helpful to parse dsn on postfix log?
https://github.com/etsy/logster/blob/master/logster/parsers/PostfixLogster.py

<!-- gh-comment-id:58092718 --> @DocLowy commented on GitHub (Oct 6, 2014): maybe this code is helpful to parse dsn on postfix log? https://github.com/etsy/logster/blob/master/logster/parsers/PostfixLogster.py
Author
Owner

@darold commented on GitHub (Feb 18, 2015):

Latest commit 9cd91ee should add this feature.

Thanks again for the report.

<!-- gh-comment-id:74861923 --> @darold commented on GitHub (Feb 18, 2015): Latest commit 9cd91ee should add this feature. Thanks again for the report.
Sign in to join this conversation.
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference: github-starred/sendmailanalyzer#17
No description provided.