Error parsing bounce messages

[wedi]

Hi!

I am experiencing errors while importing my logs. Attached you find the output of the cron runner and the log lines corresponding to the mentioned message ids.

It looks like the parser is stumbling on empty envelope senders which frequently occur on bounce messages.

I selected one occurence but I can provide more examples should you need them.

Thank you for looking into this.

postfix-parser /postfix-parser/run.sh cron
Loading .env environment variables...
2020-11-27 17:26:22,225 postfixparser.main INFO     Importing log file
2020-11-27 17:26:22,225 postfixparser.main INFO     Opening log file /log/mail.log
2020-11-27 17:26:22,259 postfixparser.main INFO     Finished parsing log file /log/mail.log
2020-11-27 17:26:22,260 postfixparser.main INFO     Converting log data into list
2020-11-27 17:26:22,264 postfixparser.main INFO     Total of 30 message entries
2020-11-27 17:26:22,264 postfixparser.main INFO     Generating async batch save list
2020-11-27 17:26:22,270 postfixparser.main ERROR    Error while parsing email {'id': 'C0B298000E', 'timestamp': <RqlQuery instance: r.iso8601('2020-11-26T14:24:20+00:00') >, 'queue_id': 'C0B298000E', 'lines': [{'timestamp': <RqlQuery instance: r.iso8601('2020-11-26T14:24:20+00:00') >, 'queue_id': 'C0B298000E', 'message': 'message-id=<[email protected]>'}, {'timestamp': <RqlQuery instance: r.iso8601('2020-11-26T14:24:20+00:00') >, 'queue_id': 'C0B298000E', 'message': 'from=<>, size=3981, nrcpt=1 (queue active)'}, {'timestamp': <RqlQuery instance: r.iso8601('2020-11-26T14:24:21+00:00') >, 'queue_id': 'C0B298000E', 'message': 'to=<[email protected]>, relay=h-49513e282bf700b0b550[112.115.60.48]:25, delay=0.6, delays=0/0/0.06/0.54, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as D4D6321316)'}, {'timestamp': <RqlQuery instance: r.iso8601('2020-11-26T14:24:21+00:00') >, 'queue_id': 'C0B298000E', 'message': 'removed'}], 'mail_to': '[email protected]', 'mail_from': '', 'message_id': '[email protected]', 'status': {'code': 'sent', 'message': '(250 2.0.0 Ok: queued as D4D6321316)'}, 'relay': {'host': 'h-49513e282bf700b0b550', 'ip': '112.115.60.48', 'port': '25'}, 'client': {}, 'first_attempt': <RqlQuery instance: r.iso8601('2020-11-26T14:24:20+00:00') >, 'last_attempt': <RqlQuery instance: r.iso8601('2020-11-26T14:24:21+00:00') >}
Traceback (most recent call last):
  File "/postfix-parser/postfixparser/main.py", line 105, in main
    mfrom_dom, mto_dom = mfrom.split('@')[1], mto.split('@')[1]
IndexError: list index out of range
2020-11-27 17:26:22,272 postfixparser.main INFO     Firing off asyncio.gather(save_list)...
2020-11-27 17:26:22,457 postfixparser.main INFO     Finished!

Nov 26 14:24:20 mailout01 postfix/cleanup[28567]: C0B298000E: message-id=<[email protected]>
Nov 26 14:24:20 mailout01 postfix/qmgr[23708]: C0B298000E: from=<>, size=3981, nrcpt=1 (queue active)
Nov 26 14:24:21 mailout01 postfix/smtp[28575]: C0B298000E: to=<[email protected]>, relay=h-49513e282bf700b0b550[112.115.60.48]:25, delay=0.6, delays=0/0/0.06/0.54, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as D4D6321316)
Nov 26 14:24:21 mailout01 postfix/qmgr[23708]: C0B298000E: removed

[ddevil345]

Loading .env environment variables...
2020-11-28 08:32:35,202 postfixparser.main INFO Importing log file
2020-11-28 08:32:35,202 postfixparser.main INFO Opening log file /var/log/mail.log
2020-11-28 08:32:35,693 postfixparser.main INFO Finished parsing log file /var/log/mail.log
2020-11-28 08:32:35,693 postfixparser.main INFO Converting log data into list
2020-11-28 08:32:35,756 postfixparser.main INFO Total of 27 message entries
2020-11-28 08:32:35,757 postfixparser.main INFO Generating async batch save list
2020-11-28 08:32:35,757 postfixparser.main ERROR Error while parsing email {'id': 'DEE238038F', 'timestamp': <RqlQuery instance: r.iso8601('2020-11-28T06:57:38+00:00') >, 'queue_id': 'DEE238038F', 'lines': [{'timestamp': <RqlQuery instance: r.iso8601('2020-11-28T06:57:38+00:00') >,
'queue_id': 'DEE238038F', 'message': 'message-id=[email protected]'}, {'timestamp': <RqlQuery instance: r.iso8601('2020-11-28T06:57:38+00:00') >, 'queue_id': 'DEE238038F', 'message':
'from=<>, size=3272, nrcpt=1 (queue active)'}, {'timestamp': <RqlQuery instance: r.iso8601('2020-11-28T06:57:38+00:00') >, 'queue_id': 'DEE238038F', 'message': 'to=[email protected], relay=local,
delay=0.02, delays=0.02/0/0/0, dsn=5.3.0, status=bounced
(Command died with status 127: "procmail -a "$EXTENSION"". Command output: sh: 1: procmail: not found )'},
{'timestamp': <RqlQuery instance: r.iso8601('2020-11-28T06:57:38+00:00') >, 'queue_id': 'DEE238038F', 'message': 'removed'}],
'mail_to': '[email protected]', 'mail_from': '', 'message_id': '[email protected]', 'status': {'code': 'bounced', 'message': '(Command died with status 127:
"procmail -a "$EXTENSION"". Command output: sh: 1: procmail: not found )'}, 'relay': {}, 'client': {}, 'first_attempt': <RqlQuery instance: r.iso8601('2020-11-28T06:57:38+00:00') >,
'last_attempt': <RqlQuery instance: r.iso8601('2020-11-28T06:57:38+00:00') >}
Traceback (most recent call last):
File "/home/mailparser/postfix-parser/postfixparser/main.py", line 105, in main
mfrom_dom, mto_dom = mfrom.split('@')[1], mto.split('@')[1]
IndexError: list index out of range
2020-11-28 08:32:35,757 postfixparser.main INFO Firing off asyncio.gather(save_list)...
2020-11-28 08:32:35,993 postfixparser.main INFO Finished!

procmail -v

procmail v3.23pre 2001/09/13
Copyright (c) 1990-2001, Stephen R. van den Berg [email protected]
Copyright (c) 1997-2001, Philip A. Guenther [email protected]

Submit questions/answers to the procmail-related mailinglist by sending to:
[email protected]

And of course, subscription and information requests for this list to:
[email protected]