Program crashes when trying to parse message

[fribse]

Hi there My DMARC has stopped, and I just found out that it runs as it should, but a mail is making it crash.

The log shows:

dmarc            | 2022-11-04 10:18:58,588 - dmarc2logstash - INFO - Starting DMARC to Logstash service; sleepSec=300; jsonOutputFile=/dmarclogs/dmarc.log; shouldDelete=1
dmarc            | 2022-11-04 10:18:58,588 - dmarc2logstash - INFO - Connecting to POP3 server; server=bounce.onead.dk; username=dmarc@helpdesk.onemarketing.dk; debugLevel=0
dmarc            | 2022-11-04 10:18:58,687 - dmarc2logstash - INFO - Connected to POP3 server; newMessages=1735
dmarc            | 2022-11-04 10:18:58,699 - dmarc2logstash - INFO - Reading message; messageIdx=1; messageSubject="testmail"; messageSender="Kenneth Fribert <fribse@gmail.com>"
dmarc            | 2022-11-04 10:18:58,700 - dmarc2logstash - INFO - Preserving email message since it is not a DMARC report; messageIdx=1; messageSubject="testmail"; messageSender="Kenneth Fribert <fribse@gmail.com>"
dmarc            | 2022-11-04 10:18:58,703 - dmarc2logstash - INFO - Reading message; messageIdx=2; messageSubject="Report Domain: info.viaplay.com Submitter: wp.pl Report-ID: 1666741620.188104143"; messageSender="dmarc-support@wp.pl"
dmarc            | 2022-11-04 10:18:58,704 - dmarc2logstash - INFO - Decompressing zip data
dmarc            | 2022-11-04 10:18:58,708 - dmarc2logstash - WARNING - Unable to parse attachment; name="wp.pl!info.viaplay.com!1666648800!1666735200.xml"; reason="gethostbyaddr() argument 1 must be str, bytes or bytearray, not None"
dmarc            | 2022-11-04 10:18:58,708 - dmarc2logstash - INFO - Preserving email message since it is not a DMARC report; messageIdx=2; messageSubject="Report Domain: info.viaplay.com Submitter: wp.pl Report-ID: 1666741620.188104143"; messageSender="dmarc-support@wp.pl"
dmarc            | 2022-11-04 10:18:58,710 - dmarc2logstash - INFO - Reading message; messageIdx=3; messageSubject="Report Domain: mailinfo.tryg.dk Submitter: wp.pl Report-ID: 1666743423.877004693"; messageSender="dmarc-support@wp.pl"
dmarc            | 2022-11-04 10:18:58,711 - dmarc2logstash - INFO - Decompressing zip data
dmarc            | 2022-11-04 10:18:58,712 - dmarc2logstash - WARNING - Unable to parse attachment; name="wp.pl!mailinfo.tryg.dk!1666648800!1666735200.xml"; reason="gethostbyaddr() argument 1 must be str, bytes or bytearray, not None"
dmarc            | 2022-11-04 10:18:58,712 - dmarc2logstash - INFO - Preserving email message since it is not a DMARC report; messageIdx=3; messageSubject="Report Domain: mailinfo.tryg.dk Submitter: wp.pl Report-ID: 1666743423.877004693"; messageSender="dmarc-support@wp.pl"
dmarc            | Traceback (most recent call last):
dmarc            |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 219, in <module>
dmarc            |     sys.exit(main())
dmarc            |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 216, in main
dmarc            |     start(server, username, password, int(sleepSec), jsonOutputFile, float(timeout), int(shouldDelete))
dmarc            |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 179, in start
dmarc            |     download(server, username, password, jsonOutputFile, timeout, shouldDelete)
dmarc            |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 49, in download
dmarc            |     raw = raw + txt[j].decode() + "\n"
dmarc            | UnicodeDecodeError: 'utf-8' codec can't decode byte 0xd1 in position 2: invalid continuation byte

I can probably make it go again, by deleting this specific mail, but I would rather have it handle it :-) In the docker-compose.yml I have these settings set up:

  dmarc:
    image: jertel/dmarc2logstash
    container_name: dmarc
    mem_limit: 1073741824
    volumes:
      - ./dmarc/logs:/logs
      - ./dmarc/dmarc2logstash.json:/opt/dmarc2logstash/dmarc2logstash.json
      - ./dmarc/dmarclogs:/dmarclogs
    environment:
      - POP3_SERVER=server
      - POP3_USERNAME=email
      - POP3_PASSWORD=pw
      - DELETE_MESSAGES=1
      - JSON_OUTPUT_FILE=/dmarclogs/dmarc.log
      - DELETE_FAILURES=1
    restart: always

I'm a bit unsure of the logfile saying: Preserving email message since it is not a DMARC report; As I've set up 'DELETE_FAILURES=1?

I've put the zipfile here: https://drive.google.com/file/d/1nZkxzBchc1sW0Yey9YmNAbkiUx8dPV07/view?usp=sharing

[jertel]

I suspect it's actually the next message that's triggering the failure, before it was able to output the first log line about it. I've pushed a small change that captures the decode error and flags the message as a failure. Please give it a shot and see if it addresses the issue.

[fribse]

Hi @jertel I'm still working with this on and off, now I've tried deleting a lot of mails, but I still see errors, I could of course delete them all :-) Now I see this message:

dmarc            | 2022-12-20 14:29:07,556 - dmarc2logstash - INFO - Starting DMARC to Logstash service; sleepSec=300; jsonOutputFile=/dmarclogs/dmarc.log; shouldDelete=1
dmarc            | 2022-12-20 14:29:07,556 - dmarc2logstash - INFO - Connecting to POP3 server; server=bounce.onead.dk; username=dmarc@helpdesk.onemarketing.dk; debugLevel=0
dmarc            | 2022-12-20 14:29:07,777 - dmarc2logstash - INFO - Connected to POP3 server; newMessages=15209
dmarc            | Traceback (most recent call last):
dmarc            |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 219, in <module>
dmarc            |     sys.exit(main())
dmarc            |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 216, in main
dmarc            |     start(server, username, password, int(sleepSec), jsonOutputFile, float(timeout), int(shouldDelete))
dmarc            |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 179, in start
dmarc            |     download(server, username, password, jsonOutputFile, timeout, shouldDelete)
dmarc            |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 49, in download
dmarc            |     raw = raw + txt[j].decode() + "\n"
dmarc            | UnicodeDecodeError: 'utf-8' codec can't decode byte 0xd1 in position 2: invalid continuation byte

[jertel]

It looks like you are not using the "latest" image tag. Try pulling latest and re-run it. If you are using Kubernetes you will need to change the deployment image pull policy to always pull latest.

[jertel]

Ignore that previous comment -- I just noticed that I did do a release (1.5.3) after I made the decode fix. Are you sure you have upgraded to that newer version? The line numbers in your error stack align with the older version.

[fribse]

I just made a rebuild 10 mins ago of the image with

image: jertel/dmarc2logstash:latest

Is that not updated?

[fribse]

Hi again I just deleted the container and image, to force it to rebuild, but I still see error messages:

dmarc            | 2022-12-20 15:00:37,190 - dmarc2logstash - INFO - Starting DMARC to Logstash service; sleepSec=300; jsonOutputFile=/dmarclogs/dmarc.log; shouldDelete=1
dmarc            | 2022-12-20 15:00:37,190 - dmarc2logstash - INFO - Connecting to POP3 server; server=bounce.onead.dk; username=dmarc@helpdesk.onemarketing.dk; debugLevel=0
dmarc            | 2022-12-20 15:00:37,394 - dmarc2logstash - INFO - Connected to POP3 server; newMessages=15230
dmarc            | Traceback (most recent call last):
dmarc            |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 219, in <module>
dmarc            |     sys.exit(main())
dmarc            |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 216, in main
dmarc            |     start(server, username, password, int(sleepSec), jsonOutputFile, float(timeout), int(shouldDelete))
dmarc            |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 179, in start
dmarc            |     download(server, username, password, jsonOutputFile, timeout, shouldDelete)
dmarc            |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 49, in download
dmarc            |     raw = raw + txt[j].decode() + "\n"
dmarc            | UnicodeDecodeError: 'utf-8' codec can't decode byte 0xd1 in position 2: invalid continuation byte

[jertel]

I had tagged the new release as 1.5.3, but not as latest. So it was up there since Nov 4, but you would have had to specify 1.5.3 in order to get it.

I just now corrected that. Try clearing and re-pulling again.

[fribse]

Ahaaa :-) That explains it of course, I just assumed that latest was 1.5.3, but of course if it was in a testing phase that won't do :-) Assumptions are the mother of all fu..-ups :-D

Now I see a new error :-)

dmarc            |     log.info("Starting DMARC to Logstash service; sleepSec=%d; jsonOutputFile=%s; shouldDelete=%d; shouldDeleteFailures=%d" % (sleepSec, jsonOutputFile, shouldDelete, shouldDeleteFailures))
dmarc            | TypeError: %d format: a real number is required, not str
dmarc            | Traceback (most recent call last):
dmarc            |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 235, in <module>
dmarc            |     sys.exit(main())
dmarc            |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 232, in main
dmarc            |     start(server, username, password, int(sleepSec), jsonOutputFile, float(timeout), shouldDelete, shouldDeleteFailures)
dmarc            |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 192, in start
dmarc            |     log.info("Starting DMARC to Logstash service; sleepSec=%d; jsonOutputFile=%s; shouldDelete=%d; shouldDeleteFailures=%d" % (sleepSec, jsonOutputFile, shouldDelete, shouldDeleteFailures))
dmarc            | TypeError: %d format: a real number is required, not str

[jertel]

The README file suggests specifying numeric values (1 or 0) for the delete_messages and delete_failures config parameters. Are you using Strings, such as "True"?

[fribse]

Hmm, no, but mine is written in upper case:

  dmarc2filebeat:
    image: jertel/dmarc2logstash:latest
    container_name: dmarc2filebeat
    mem_limit: 1073741824
    volumes:
      - ./dmarc/logs:/logs
      - ./dmarc/dmarc2logstash.json:/opt/dmarc2logstash/dmarc2logstash.json
      - ./dmarc/dmarclogs:/dmarclogs
    environment:
      - POP3_SERVER=server
      - POP3_USERNAME=email
      - POP3_PASSWORD=pw
      - DELETE_MESSAGES=1
      - JSON_OUTPUT_FILE=/dmarclogs/dmarc.log
      - DELETE_FAILURES=1
    restart: always

[jertel]

I see you are using env variables, rather than the config file. If you specify those DELETE settings in the JSON file then you should be able to run it. I'll have to push a change to support env var settings.

[jertel]

I just now pushed a new docker image (latest tag) to support those DELETE_* settings as env vars.

[fribse]

Hi @jertel

Well, now I see a new message, good with progresss ;-)

\"%s\"" % (i, msg.get('subject'), msg.get('from')))
dmarc2filebeat        | UnboundLocalError: local variable 'msg' referenced before assignment
dmarc2filebeat        | 2022-12-21 15:46:00,625 - dmarc2logstash - INFO - Starting DMARC to Logstash service; sleepSec=300; jsonOutputFile=/dmarclogs/dmarc.log; shouldDelete=1; shouldDeleteFailures=1
dmarc2filebeat        | 2022-12-21 15:46:00,625 - dmarc2logstash - INFO - Connecting to POP3 server; server=server; username=email; debugLevel=0
dmarc2filebeat        | 2022-12-21 15:46:00,817 - dmarc2logstash - INFO - Connected to POP3 server; newMessages=15647
dmarc2filebeat        | 2022-12-21 15:46:00,844 - dmarc2logstash - WARNING - Unable to decode entry; reason="'utf-8' codec can't decode byte 0xd1 in position 2: invalid continuation byte"
dmarc2filebeat        | Traceback (most recent call last):
dmarc2filebeat        |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 235, in <module>
dmarc2filebeat        |     sys.exit(main())
dmarc2filebeat        |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 232, in main
dmarc2filebeat        |     start(server, username, password, int(sleepSec), jsonOutputFile, float(timeout), shouldDelete, shouldDeleteFailures)
dmarc2filebeat        |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 194, in start
dmarc2filebeat        |     download(server, username, password, jsonOutputFile, timeout, shouldDelete, shouldDeleteFailures)
dmarc2filebeat        |   File "/opt/dmarc2logstash/dmarc2logstash.py", line 74, in download
dmarc2filebeat        |     log.info("Preserving failed email message; it is not a DMARC report; messageIdx=%d; messageSubject=\"%s\"; messageSender=\"%s\"" % (i, msg.get('subject'), msg.get('from')))
dmarc2filebeat        | UnboundLocalError: local variable 'msg' referenced before assignment

[jertel]

Good! I just pushed another image that should correct the "unbound local error" bug. Try this new one and see if it improves.

[fribse]

HEY, IT'S WORKING 🤣 😂 It's chugging away at the 15000 messages :-)

[fribse]

Wow, that was nice to get running again, thankyou very much for the great work! Now I'm crossing fingers for it to keep running and not encounter more weird messages 😅 I'll close the case, thankyou again!