Hardening for 11.2.2: attempts file, parse timeout, worker handling, three fixes (#945)

* Wrap the failure-report duplicate search in the output error

The aggregate and SMTP TLS saves turn a failed duplicate-check search
into ElasticsearchError or OpenSearchError; the failure-report saves
let the search library's exception escape instead.

Co-Authored-By: Claude Sonnet 5.5 <noreply@anthropic.com>

* Refuse date strings too long to be dates

human_timestamp_to_datetime() had no length limit; a digit run of a
million characters took 12 s in dateutil. Add a 128 character limit
(ValueError) and map it to the matching Invalid*Report at the failure
Arrival-Date, the message Date header and the failure-report sample
Date in the Elasticsearch and OpenSearch saves.

Co-Authored-By: Claude Sonnet 5.5 <noreply@anthropic.com>

* Skip failure sample headers with an empty name

The Elasticsearch and OpenSearch failure saves normalise each header
name; a name that is empty after that is not a valid field name, so
leave the header out and save the rest.

Co-Authored-By: Claude Sonnet 5.5 <noreply@anthropic.com>

* Add a persisted store of unfinished parse attempts

A message whose parse kills the process (the out-of-memory killer, a
container memory cap) is never moved out of the reports folder, so every
later run parses it and dies again. parsedmarc.attempts keeps a small
JSON file counting, per message, the parse attempts that started but
never finished, so the mailbox loop can set such a message aside after
MAX_PARSE_ATTEMPTS. The key hashes the first 64 KiB of the message
because mailsuite's IMAP backend does not expose UIDVALIDITY, so a
reused UID must not inherit an old count. Writes are atomic and owner
only, and a failed write turns the store off instead of stopping a run.

Refs GHSA-qcc2-4x3v-v4g7, GHSA-q7gm-8cj9-94hr, GHSA-4272-4r8g-6c5h

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Set aside mailbox messages that keep killing the parse

A message whose parse ends the process stays in the reports folder, so
every one-shot run or service restart parsed it again and died before
reaching the reports behind it. The new [mailbox] attempts_file option
records each message in an AttemptStore before it is parsed and clears
the entry once the parse returns a report or raises ParserError, so an
entry left behind marks a parse that never finished; a message with
MAX_PARSE_ATTEMPTS of them is disposed of as invalid without parsing.
The entry is cleared before the save, so a failed save is never counted
as a crash, and only after a successful move, so a failed move is
retried.

With n_procs > 1 a dead run had a whole submission window in flight, so
counting every message submitted beside the culprit would set innocent
reports aside on the third run. A message with one unfinished attempt is
therefore parsed alone in the calling process after the rest of the
batch, and a second death counts against it only.

PARSEDMARC_MAILBOX_ATTEMPTS_FILE names the file directly, so the key
joins _DIRECT_FILE_KEYS; without it the variable was read as a
Docker-secret reference.

Refs GHSA-qcc2-4x3v-v4g7, GHSA-q7gm-8cj9-94hr, GHSA-4272-4r8g-6c5h

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Stop a parallel_map job that runs past a timeout

The parse limits added for GHSA-qcc2-4x3v-v4g7 bound every input known
to parse slowly, but nothing bounds a parse they do not cover: with
n_procs = 1 the rest of the mailbox waits behind it. parallel_map() now
takes parse_timeout and timeout_result. A job that runs that long gets
timeout_result(job, parse_timeout) in its place; since a
ProcessPoolExecutor cannot stop one job, every worker is killed, a new
pool is started and the other unfinished jobs are resubmitted.

A job's clock starts when its worker reports that it began, through a
queue the pool initializer hands each worker. Future.running() is not
enough: the executor marks one job more than it has workers as running,
so a job queued behind a slow neighbour would be charged for the wait.

ParseTimeoutError subclasses InvalidDMARCReport so the mbox and mailbox
loops treat a timed-out message as invalid without changes.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Add parse_timeout to the mbox, mailbox and watch functions

get_dmarc_reports_from_mbox(), get_dmarc_reports_from_mailbox() and
watch_inbox() take parse_timeout and pass it to parallel_map() with the
email job's timeout value. A timeout set with n_procs = 1 also takes the
parallel_map() branch, since only a parse in a worker process can be
stopped. The mailbox function and watch_inbox() reject an invalid value
before fetching or watching, as they do for max_unsaved_retries: raised
inside a watch check, the error would be retried on every check.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Add the [general] parse_timeout option

The CLI reads parse_timeout as seconds, rejects a negative or
non-numeric value as a ConfigurationError, defaults it to 0 (no limit),
and passes it to the report-file, mbox, mailbox and watch calls. The
watch call reads it from opts, so a SIGHUP reload takes a new value.
The default stays 0 because the parse limits already bound the known
inputs and a timeout routes every n_procs = 1 run through a worker
process; the documentation suggests 300 seconds.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Document the attempts_file option

Describe [mailbox] attempts_file in the option list and in a new usage
section on messages that crash parsedmarc, say in the Unsaved note that
the failed-save counts are the in-memory ones, keep the file in a state
directory in the systemd example and in a named volume in the Docker
Compose example, and add the Security changelog entry for the
retry-loop backstop the three advisories deferred.

Refs GHSA-qcc2-4x3v-v4g7, GHSA-q7gm-8cj9-94hr, GHSA-4272-4r8g-6c5h

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* List parse_timeout and attempts_file as orchestration options

ParserConfig's docstring and the usage page's ParserConfig notes name the
keyword arguments that stay outside the dataclass. The two new options
are such arguments, so a library caller looking for them on ParserConfig
is told where they go.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Bound a suspect message's parse by parse_timeout

With an attempts file, a message that was being parsed when an earlier
run died is parsed alone after the rest of its batch, so that a second
death is charged to it and not to the messages parsed beside it. That
parse ran in the main process, where parse_timeout cannot stop it, so the
one message most likely to be slow or fatal was the one the timeout did
not cover. With a timeout set, each suspect now gets a worker pool of its
own, one message per pool so a crash is still attributed to it alone,
and its result is taken the same way as the batch's. Without a timeout
the suspect is still parsed in this process.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Restore default signal handlers in parsing workers

Under the fork start method a worker inherits the parent's signal
handlers, and the CLI installs SIGTERM and SIGINT handlers that only set
a flag. When a worker dies, ProcessPoolExecutor terminates the others
with SIGTERM and joins them; a worker running the inherited handler
ignores that signal, so the teardown waited forever and the run hung
instead of failing. The pool initializer now resets both signals to
their defaults. The logging tests that call the initializer in the test
process put the process's own handlers back afterwards.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Order the Unreleased changelog and tie its entries together

The three branches each added to the Unreleased entry. The GHSA-q7gm
bullet still promised a follow-up for a persisted failed-attempt marker,
which the attempts_file option now is, so it names the option. The
attempts_file bullet now says that a suspect message is parsed in a
worker of its own when parse_timeout is set, matching the code. The
#942 fix moves up beside the other fix already on master, and the
worker signal-handler fix gets its own line.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Ignore SIGINT in workers and end the batch when one dies

Resetting SIGINT to its default in the workers made a Ctrl-C, which
the terminal sends to the whole process group, kill every worker, so
the run ended in BrokenProcessPool where the CLI's handler meant to
let the batch finish. Workers now ignore SIGINT and keep the default
SIGTERM action, which ProcessPoolExecutor needs to tear down a broken
pool.

A worker that dies for another reason (the out-of-memory killer, a
crash) raised BrokenProcessPool out of parallel_map, which no caller
handled: the file and mbox paths ended in a traceback. parallel_map
now kills the remaining workers, closes the start queue and raises
ParserError from it, and the CLI file and mbox paths log it and exit 1
as the mailbox paths already did. The in-flight messages keep their
attempts-file entries, so the next run parses each alone.

The systemd example gains KillMode=mixed so stopping the service
signals only the main process and the batch in progress finishes.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* State the parse_timeout bounds the code actually gives

A slow job running beside another that expires loses its partial run
and starts again, so P slow jobs cost one more round of
parse_timeout than the docstring said, plus the bounded joins of the
killed workers, during which no heartbeat is sent. The clocks are
also checked only while the parent waits for a result, so "at most
one second past the timeout" was not true while the caller is busy
between results; the docstring, usage.md and the changelog now say a
parse is stopped within one wait slice of the parent next waiting.

ParseTimeoutError's docstring says it is the value for every timed-out
input, SMTP TLS and unrecognised ones included. A new test closes the
results iterator mid-run and checks the workers are killed and the
start queue closed; the zero-timeout test now observes which pool ran
the job instead of patching _DeadlinePool.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Correct the attempts-file wording and test the parallel test mode

Suspect isolation happens whenever the mailbox takes the parallel path,
which parse_timeout selects even with n_procs = 1; the docstring,
comment, usage.md and changelog now say so. The set-aside log said a
message "has crashed parsedmarc {count-1} time(s)", which overstates
the crashes once a failed move has added attempts; it now reports the
unfinished attempts against the cap.

usage.md lists attempts_file among the _file keys read directly from
the environment and among the settings a SIGHUP reloads, and says that
a failed write clearing an entry after a good parse can lead to a
healthy message being set aside after two such failures. The test-mode
set-aside test now runs the parallel path too.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Measure a date's length after its comments are removed

The length guard in human_timestamp_to_datetime() ran before the
RFC 5322 comments were stripped. RFC 5322 section 3.2.2 puts no limit
on a comment's length, so a valid Date header with a long comment was
refused, and through the sample Date path the whole report email with
it. The check now runs on the stripped value, which is linear to
produce; a long digit run survives stripping, so it is still refused
before dateutil sees it.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Save parsed reports before exiting on a dead worker

A ParserError from parallel_map (a worker process that died) or from an
mbox made the CLI exit at once, discarding every report parsed so far;
report files already moved under archive_directory were then saved
nowhere. The CLI now stops reading input, saves what it gathered, and
exits with status 1.

Workers ignore SIGINT, so the plain pool path's executor shutdown on an
early exit (KeyboardInterrupt, closing the generator) waited for the
whole submission window. Any early exit now kills the workers, as the
timed path already did.

The Ctrl-C test ran under fork only, where a worker inherits the test's
own harmless handler, so it passed without the SIGINT line. It now runs
under every available start method and signals each worker once it has
started a job.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Stop counting a message that is already set aside

A message at the attempt limit that stayed in the folder (a failed move,
test mode) was recorded again on every later run, so the logged count
grew without bound. It is now set aside without being recorded, and the
log names the stored count and the limit.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Describe worker death per mode and the systemd stop window

A dead worker ends a one-shot run with status 1 after saving, but in
watch mode the IMAP and Maildir watchers log it and check again, while
Graph and Gmail exit. KillMode=mixed lets the batch finish only within
TimeoutStopSec. Also say that queued messages keep attempt entries too,
and re-wrap a parse_timeout note line.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Clear the seen report IDs around the worker-death CLI tests

The new save-before-exit test parses a sample in the parent, which
records it in the shared dedup set, so a later test of the same sample
saw it as a duplicate and sent no results email.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Save file reports when a mailbox fetch ends in a ParserError

A worker that died during the one-shot mailbox fetch reached the
ParserError handler, which exited before the reports from report files
and mbox inputs were saved; files already moved under archive_directory
were then kept nowhere. The handler now saves them first. A second test
covers the input-error path: no mailbox is opened and the parsed file
stays under archive_directory.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Say what a mailbox run keeps when a worker dies

Earlier batches are saved and the batch in progress stays in the
mailbox. Also say that a set-aside message is not recorded again, so its
entry ages out after 30 days, and rewrap two paragraphs.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Say which set-aside entries age out of the attempts file

The 30-day drop applies only to an entry that stays: a failed move, or
a message left in place in test mode. The sentence read as if every
set-aside message kept an entry, contradicting the line before it.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>

* Carry the test attempts path in the message, not the environment

test_parallel_path_records_each_attempt_before_submitting_it passed the
attempts file's path to its worker job through os.environ. A forkserver
worker forks from a server started before the patch, so it never saw the
variable and the job raised KeyError (Python 3.14's Linux default). The
path now travels in a header line of the message itself, which reaches
the worker under every start method.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Test the worker-side helpers and the save-failure exits

Codecov listed added lines no test reached: the timed pool's initializer
and job wrapper, which run only in workers; _kill_workers on an executor
without _processes; the plain path's heartbeat; the CLI's progress bar;
the mbox loop's stop after a file worker dies; and a failed save before
exiting, on the file/mbox path and the mailbox path.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Read start tokens every round, not only while waiting

With parse_timeout set, the parent read the workers' start tokens only
inside its wait loop. When results were already done at harvest time it
never waited, so each finished job stayed in the pool's token map with
its whole input, and the map grew with the run past the submission
window. The tokens are now read at the top of every round, and close()
clears the map.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Kill the parsing workers on a second Ctrl-C

The second Ctrl-C ends parsedmarc with os._exit(130), which skips the
process pool's cleanup. Workers now ignore SIGINT, so under every start
method a running worker survived as an orphan and kept parsing, without
end when parse_timeout is off. The handler now kills the active child
processes first; Python runs it in the main thread between bytecodes,
so active_children() and Process.kill() are safe there.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Hand timed results back through files, not the pool's pipe

With parse_timeout set, a timeout kills every worker, possibly one that
is sending a large result. The executor's management thread then waits
for the rest of that message forever; the bounded join returns with the
thread alive, and because it is not a daemon the interpreter hangs at
exit. Reproduced under fork, forkserver and spawn with a 256-400 MiB
result. Workers of the timed pool now pickle each outcome, error values
included, to a file in a private directory the pool owns and return
None; every message left on a pipe is far below PIPE_BUF, which POSIX
writes atomically. The pool without a timeout never kills a running
worker and is unchanged.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Report an unwritable temporary directory as a ParserError

With parse_timeout set the results travel through a temporary
directory. If it could not be created, or a worker could not write its
result file, a raw OSError escaped parallel_map, which the CLI does not
handle. The pool now raises ParserError naming the cause; a worker that
cannot write its file returns the error text through the executor, still
a small message, and the parent raises the same ParserError.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Keep every hand-back failure a short ParserError

A result the worker could not pickle (PicklingError, TypeError,
RecursionError, MemoryError) escaped through the executor with a
traceback of any size, breaking the short-message guarantee the timed
pool relies on, and a result file that did not unpickle raised a raw
exception in the parent. The worker now catches any failure to write
its outcome and returns a short marker, its text cut to 200 characters
so the message stays below the 512-byte minimum PIPE_BUF; the parent
turns it, and any failure to load a result file, into a ParserError.
Also corrects the PIPE_BUF figure in the module docstring, names the
temporary directory as TMPDIR, and avoids a second 128 MiB object in a
test.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* Cap the hand-back error text in bytes and survive a failing __str__

The pipe's atomic-write bound is in bytes, so a 200-character text of
multibyte characters could exceed it; the cap now applies to the UTF-8
encoding. An exception whose __str__ raises is named by its type alone,
so nothing in the worker's error path can raise through the executor. A
failed write's .tmp file is removed with the pool's result directory;
the docstring says so.

Refs GHSA-qcc2-4x3v-v4g7

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>

* Match the pickler's message across Python versions in a test

The unpicklable-result test asserted "Can't get local object", which is
the wording of Python 3.12 and 3.13 only; 3.10, 3.11 and 3.14 say
"Can't pickle local object". Assert the part they share.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>

* Cover the worker-side hand-back failures in the test process

The three failure branches of _run_timed_job and _take_outcome run in
worker processes in the pool tests, where coverage cannot see them;
call them directly here with an unwritable directory, an unpicklable
result and an unreadable result file.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>

* Assert the unreadable-result message by its text, and format

The temporary-directory error carries the OSError's text, not its
class name, so the test asserts "Is a directory"; one long test line
is wrapped as ruff format wants.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>

* Narrow the marker before unpacking it in two tests

pyright cannot narrow Optional through assertIsNotNone; a plain assert
does.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>

---------

Co-authored-by: Claude Sonnet 5.5 <noreply@anthropic.com>
This commit is contained in:
Sean WhalenandClaude Fable 5.1 authored and GitHub committed 2026-11-09 20:54:27 -05:00
1 parent 1c7f2785e5
commit e8292bef70
17 files changed
+4050 -128

No files matched your search

+242
View File
@@ -0,0 +1,242 @@
"""Tests for parsedmarc.attempts"""
import json
import os
import stat
import sys
import unittest
from datetime import datetime, timedelta, timezone
from shutil import rmtree
from tempfile import mkdtemp
from unittest.mock import patch
from parsedmarc.attempts import (
FILE_VERSION,
PRUNE_AFTER,
AttemptStore,
attempt_key,
)
class TestAttemptKey(unittest.TestCase):
"""The key names the folder and message and hashes the content, so a
reused UID with new content is a new message."""
def test_same_uid_with_different_content_gets_a_different_key(self):
first = attempt_key("INBOX", 7, "Subject: one\n\nbody\n")
second = attempt_key("INBOX", 7, "Subject: two\n\nbody\n")
self.assertNotEqual(first, second)
self.assertTrue(first.startswith("INBOX\x1f7\x1f"))
def test_same_message_gets_the_same_key_as_str_or_bytes(self):
text = "Subject: one\n\nbody\n"
self.assertEqual(
attempt_key("INBOX", "a", text),
attempt_key("INBOX", "a", text.encode("utf-8")),
)
def test_folder_and_id_are_part_of_the_key(self):
content = "Subject: one\n\nbody\n"
self.assertNotEqual(
attempt_key("INBOX", 1, content), attempt_key("Reports", 1, content)
)
self.assertNotEqual(
attempt_key("INBOX", 1, content), attempt_key("INBOX", 2, content)
)
def test_only_the_first_64_kib_is_hashed(self):
prefix = "x" * 65536
self.assertEqual(
attempt_key("INBOX", 1, prefix + "tail one"),
attempt_key("INBOX", 1, prefix + "tail two"),
)
def test_a_lone_surrogate_does_not_raise(self):
# A str decoded with surrogateescape holds lone surrogates.
key = attempt_key("INBOX", 1, "Subject: \udcff\n\n")
self.assertNotEqual(key, attempt_key("INBOX", 1, "Subject: \n\n"))
class TestAttemptStore(unittest.TestCase):
"""The store on a real file in a temporary directory."""
def setUp(self):
self._tmp = mkdtemp()
self.addCleanup(rmtree, self._tmp, ignore_errors=True)
self.path = os.path.join(self._tmp, "attempts.json")
def _read(self):
with open(self.path, encoding="utf-8") as attempts_file:
return json.load(attempts_file)
def _write(self, document):
with open(self.path, "w", encoding="utf-8") as attempts_file:
json.dump(document, attempts_file)
def test_missing_file_is_an_empty_store_and_is_not_created_by_loading(self):
store = AttemptStore(self.path)
self.assertEqual(store.count("k"), 0)
self.assertFalse(os.path.exists(self.path))
def test_record_increments_and_persists(self):
store = AttemptStore(self.path)
self.assertEqual(store.record("k"), 1)
self.assertEqual(store.record("k"), 2)
document = self._read()
self.assertEqual(document["version"], FILE_VERSION)
self.assertEqual(document["attempts"]["k"]["count"], 2)
last = datetime.fromisoformat(document["attempts"]["k"]["last"])
self.assertLess(datetime.now(timezone.utc) - last, timedelta(minutes=1))
reloaded = AttemptStore(self.path)
self.assertEqual(reloaded.count("k"), 2)
self.assertEqual(reloaded.record("k"), 3)
def test_clear_rewrites_the_file_without_the_entry(self):
store = AttemptStore(self.path)
store.record("k")
store.record("other")
store.clear("k")
self.assertEqual(list(self._read()["attempts"]), ["other"])
self.assertEqual(AttemptStore(self.path).count("k"), 0)
def test_clear_of_an_unknown_key_does_not_write(self):
store = AttemptStore(self.path)
store.clear("k")
self.assertFalse(os.path.exists(self.path))
def test_corrupt_file_warns_and_starts_empty(self):
cases = {
"not json": b"{not json",
"not utf-8": b"\xff\xfe\x00",
"a list": b"[]",
"wrong version": json.dumps({"version": 2, "attempts": {}}).encode(),
"attempts not a dict": json.dumps({"version": 1, "attempts": []}).encode(),
"entry not a dict": json.dumps(
{"version": 1, "attempts": {"k": 1}}
).encode(),
"count a bool": json.dumps(
{
"version": 1,
"attempts": {
"k": {"count": True, "last": "2026-11-09T00:00:00+00:00"}
},
}
).encode(),
"count zero": json.dumps(
{
"version": 1,
"attempts": {
"k": {"count": 0, "last": "2026-11-09T00:00:00+00:00"}
},
}
).encode(),
"last not a str": json.dumps(
{"version": 1, "attempts": {"k": {"count": 1, "last": 5}}}
).encode(),
"last not a date": json.dumps(
{"version": 1, "attempts": {"k": {"count": 1, "last": "soon"}}}
).encode(),
"last without a zone": json.dumps(
{
"version": 1,
"attempts": {"k": {"count": 1, "last": "2026-11-09T00:00:00"}},
}
).encode(),
}
for name, raw in cases.items():
with self.subTest(name):
with open(self.path, "wb") as attempts_file:
attempts_file.write(raw)
with self.assertLogs("parsedmarc.log", level="WARNING") as cm:
store = AttemptStore(self.path)
self.assertEqual(store.count("k"), 0)
self.assertIn(f"Attempts file {self.path}", cm.output[0])
# The next write replaces the corrupt file with a valid one.
self.assertEqual(store.record("k"), 1)
self.assertEqual(self._read()["attempts"]["k"]["count"], 1)
def test_unreadable_file_warns_and_starts_empty(self):
with self.assertLogs("parsedmarc.log", level="WARNING") as cm:
# A directory cannot be opened as a file on any platform.
store = AttemptStore(self._tmp)
self.assertEqual(store.count("k"), 0)
self.assertIn(f"Could not read attempts file {self._tmp}", cm.output[0])
def test_entries_older_than_the_prune_age_are_dropped_on_load(self):
now = datetime.now(timezone.utc)
self._write(
{
"version": 1,
"attempts": {
"old": {
"count": 2,
"last": (now - PRUNE_AFTER - timedelta(hours=1)).isoformat(),
},
"recent": {
"count": 1,
"last": (now - PRUNE_AFTER + timedelta(hours=1)).isoformat(),
},
},
}
)
store = AttemptStore(self.path)
self.assertEqual(store.count("old"), 0)
self.assertEqual(store.count("recent"), 1)
store.record("new")
self.assertEqual(sorted(self._read()["attempts"]), ["new", "recent"])
def test_failed_replace_keeps_the_old_file_and_disables_the_store(self):
store = AttemptStore(self.path)
store.record("k")
before = self._read()
with patch("parsedmarc.attempts.os.replace", side_effect=OSError("disk full")):
with self.assertLogs("parsedmarc.log", level="ERROR") as cm:
self.assertEqual(store.record("k"), 0)
self.assertEqual(self._read(), before)
self.assertIn(
f"Could not write attempts file {self.path}: disk full; "
"crashed-message protection is disabled",
cm.output[0],
)
# No temporary file is left beside the attempts file.
self.assertEqual(os.listdir(self._tmp), ["attempts.json"])
# Off for the rest of the batch: nothing more is counted or written.
self.assertFalse(store.enabled)
self.assertEqual(store.record("other"), 0)
store.clear("k")
self.assertEqual(self._read(), before)
def test_unwritable_directory_disables_the_store_without_raising(self):
# A regular file where the parent directory should be.
blocker = os.path.join(self._tmp, "blocker")
with open(blocker, "w", encoding="utf-8"):
pass
store = AttemptStore(os.path.join(blocker, "attempts.json"))
with self.assertLogs("parsedmarc.log", level="ERROR"):
self.assertEqual(store.record("k"), 0)
self.assertFalse(store.enabled)
def test_missing_parent_directories_are_created(self):
path = os.path.join(self._tmp, "state", "parsedmarc", "attempts.json")
store = AttemptStore(path)
self.assertEqual(store.record("k"), 1)
self.assertTrue(os.path.isfile(path))
@unittest.skipIf(sys.platform == "win32", "POSIX file modes")
def test_file_is_readable_by_its_owner_only(self):
old_umask = os.umask(0)
try:
store = AttemptStore(self.path)
store.record("k")
self.assertEqual(stat.S_IMODE(os.stat(self.path).st_mode), 0o600)
store.clear("k")
self.assertEqual(stat.S_IMODE(os.stat(self.path).st_mode), 0o600)
finally:
os.umask(old_umask)
if __name__ == "__main__":
unittest.main(verbosity=2)
+549 -1
View File
@@ -10,12 +10,15 @@ import importlib.util
import json
import logging
import mailbox
import multiprocessing
import os
import shutil
import signal
import stat
import subprocess
import sys
import tempfile
import time
import traceback
import unittest
import zipfile
@@ -997,10 +1000,14 @@ hosts = localhost
"PARSEDMARC_GMAIL_API_CREDENTIALS_FILE": "/etc/parsedmarc/gmail.json",
"PARSEDMARC_GMAIL_API_TOKEN_FILE": "/etc/parsedmarc/gmail.token",
"PARSEDMARC_MSGRAPH_TOKEN_FILE": "/etc/parsedmarc/msgraph.token",
"PARSEDMARC_MAILBOX_ATTEMPTS_FILE": "/var/lib/parsedmarc/attempts.json",
}
with patch.dict(os.environ, env, clear=False):
_apply_env_overrides(config)
self.assertEqual(config.get("general", "log_file"), "/var/log/parsedmarc.log")
self.assertEqual(
config.get("mailbox", "attempts_file"), "/var/lib/parsedmarc/attempts.json"
)
self.assertEqual(
config.get("gmail_api", "credentials_file"),
"/etc/parsedmarc/gmail.json",
@@ -5399,13 +5406,22 @@ watch = true
mock_watch.side_effect = watch_side_effect
cfg_path = self._write_config()
with patch("parsedmarc.cli.os._exit", side_effect=fake_exit) as mock_exit:
workers = [MagicMock(), MagicMock()]
with (
patch("parsedmarc.cli.os._exit", side_effect=fake_exit) as mock_exit,
patch(
"parsedmarc.cli.multiprocessing.active_children", return_value=workers
),
):
with patch.object(sys, "argv", ["parsedmarc", "-c", cfg_path]):
with self.assertRaises(SystemExit) as cm:
parsedmarc.cli._main()
self.assertIs(cm.exception, sentinel)
mock_exit.assert_called_once_with(130)
# Workers ignore SIGINT, and os._exit skips the pool's cleanup.
for worker in workers:
worker.kill.assert_called_once_with()
@patch("parsedmarc.cli.get_dmarc_reports_from_mbox")
@patch("parsedmarc.cli.is_mbox", side_effect=lambda p: p.endswith(".mbox"))
@@ -7247,6 +7263,52 @@ max_unsaved_retries = 7
self.assertEqual(single_shot_kwargs.get("max_unsaved_retries"), 7)
self.assertEqual(watch_kwargs.get("max_unsaved_retries"), 7)
@patch("parsedmarc.cli.get_dmarc_reports_from_mailbox")
@patch("parsedmarc.cli.watch_inbox")
@patch("parsedmarc.cli.IMAPConnection")
def testAttemptsFileReachesBothCallSitesExpanded(
self, mock_imap_connection, mock_watch_inbox, mock_get_reports
):
"""[mailbox] attempts_file reaches the one-shot fetch and the
watcher, with ``$VAR`` expanded like every other file path; without
it both get None and keep no record."""
mock_imap_connection.return_value = object()
mock_get_reports.return_value = {
"aggregate_reports": [],
"failure_reports": [],
"smtp_tls_reports": [],
}
mock_watch_inbox.side_effect = FileExistsError("stop-watch-loop")
base = """[general]
silent = true
[imap]
host = imap.example.com
user = user
password = pass
[mailbox]
watch = true
"""
for extra, expected in (
("attempts_file = $STATE_DIR/attempts.json\n", "/srv/state/attempts.json"),
("", None),
):
with self.subTest(expected=expected):
config_path = self._write_config(base + extra)
with patch.dict(os.environ, {"STATE_DIR": "/srv/state"}):
with patch.object(sys, "argv", ["parsedmarc", "-c", config_path]):
with self.assertRaises(SystemExit):
parsedmarc.cli._main()
self.assertEqual(
mock_get_reports.call_args.kwargs.get("attempts_file", "unset"),
expected,
)
self.assertEqual(
mock_watch_inbox.call_args.kwargs.get("attempts_file", "unset"),
expected,
)
@patch("parsedmarc.cli.get_dmarc_reports_from_mailbox")
@patch("parsedmarc.cli.IMAPConnection")
def testFileOutputFailureIsRecordedAndReportsTheBatchUnsaved(
@@ -8013,6 +8075,22 @@ class TestParseConfigMailbox(unittest.TestCase):
_parse_config(config, opts)
self.assertEqual(opts.mailbox_max_unsaved_retries, 0)
def test_mailbox_attempts_file_expands_the_path(self):
from parsedmarc.cli import _parse_config
cp = _config_with("mailbox", {"attempts_file": "$STATE_DIR/attempts.json"})
opts = _opts()
with patch.dict(os.environ, {"STATE_DIR": "/srv/state"}):
_parse_config(cp, opts)
self.assertEqual(opts.mailbox_attempts_file, "/srv/state/attempts.json")
def test_mailbox_attempts_file_absent_is_not_set(self):
from parsedmarc.cli import _parse_config
opts = _opts()
_parse_config(_config_with("mailbox", {"watch": "true"}), opts)
self.assertFalse(hasattr(opts, "mailbox_attempts_file"))
def test_mailbox_absent_per_type_delete_keys_are_not_set(self):
from parsedmarc.cli import _parse_config
@@ -8481,6 +8559,476 @@ class TestParseConfigGeneral(unittest.TestCase):
self.assertFalse(hasattr(opts, "archive_directory"))
class TestParseTimeoutOption(unittest.TestCase):
"""``[general] parse_timeout``: read as seconds, rejected unless it is a
finite number 0 or greater, 0 by default, and passed to every parsing
call _main() makes, including watch_inbox() after a SIGHUP reload."""
def setUp(self):
from parsedmarc.log import logger as _logger
_logger.disabled = True
self.addCleanup(setattr, _logger, "disabled", False)
for stream in ("sys.stdout", "sys.stderr"):
patcher = patch(stream, new_callable=io.StringIO)
patcher.start()
self.addCleanup(patcher.stop)
parsedmarc.SEEN_AGGREGATE_REPORT_IDS.clear()
self.addCleanup(parsedmarc.SEEN_AGGREGATE_REPORT_IDS.clear)
def test_parse_timeout_is_read_as_seconds(self):
from parsedmarc.cli import _parse_config
for value, expected in (("2.5", 2.5), ("300", 300.0), ("0", 0.0)):
with self.subTest(value=value):
opts = _opts()
_parse_config(_config_with("general", {"parse_timeout": value}), opts)
self.assertEqual(opts.parse_timeout, expected)
def test_parse_timeout_rejects_negative_and_non_numeric_values(self):
from parsedmarc.cli import ConfigurationError, _parse_config
for value in ("-1", "abc", "", "nan", "inf"):
with self.subTest(value=value):
config = _config_with("general", {"parse_timeout": value})
with self.assertRaises(ConfigurationError) as ctx:
_parse_config(config, _opts())
self.assertIn("parse_timeout", str(ctx.exception))
def _write_config(self, text):
with tempfile.NamedTemporaryFile("w", suffix=".ini", delete=False) as cfg:
cfg.write(text)
cfg_path = cfg.name
self.addCleanup(lambda: os.path.exists(cfg_path) and os.remove(cfg_path))
return cfg_path
def _one_shot_mailbox_kwargs(self, general_lines):
cfg_path = self._write_config(
"\n".join(["[general]", "silent = true", "offline = true", *general_lines])
+ "\n\n[imap]\nhost = imap.example.com\nuser = user\npassword = pass\n"
)
with (
patch("parsedmarc.cli.get_dmarc_reports_from_mailbox") as mock_get_reports,
patch("parsedmarc.cli.IMAPConnection") as mock_imap,
):
mock_imap.return_value = object()
mock_get_reports.return_value = {
"aggregate_reports": [],
"failure_reports": [],
"smtp_tls_reports": [],
}
with patch.object(sys, "argv", ["parsedmarc", "-c", cfg_path]):
parsedmarc.cli._main()
return mock_get_reports.call_args.kwargs
def test_mailbox_run_gets_zero_by_default_and_the_configured_value(self):
self.assertEqual(self._one_shot_mailbox_kwargs([])["parse_timeout"], 0.0)
kwargs = self._one_shot_mailbox_kwargs(["parse_timeout = 45"])
self.assertEqual(kwargs["parse_timeout"], 45.0)
def test_report_files_and_mbox_are_parsed_with_the_timeout(self):
"""The report file goes through parallel_map's timeout loop (real
worker processes) and is parsed; the mbox call gets the value."""
from parsedmarc.parallel import _file_timeout_result
from parsedmarc.parallel import parallel_map as real_parallel_map
tmp_dir = tempfile.mkdtemp()
self.addCleanup(shutil.rmtree, tmp_dir, ignore_errors=True)
output_dir = os.path.join(tmp_dir, "output")
mbox_path = os.path.join(tmp_dir, "reports.mbox")
box = mailbox.mbox(mbox_path)
with open("samples/aggregate/twilight.eml", "rb") as message:
box.add(mailbox.mboxMessage(message.read()))
box.close()
cfg_path = self._write_config(
"[general]\noffline = True\nsilent = True\n"
f"output = {output_dir}\nparse_timeout = 30\n"
)
sample = "samples/aggregate/!example.com!1538204542!1538463818.xml"
calls = []
def recording_parallel_map(func, jobs, n_procs, **kwargs):
calls.append(kwargs)
return real_parallel_map(func, jobs, n_procs, **kwargs)
with (
patch("parsedmarc.cli.parallel_map", recording_parallel_map),
patch(
"parsedmarc.cli.get_dmarc_reports_from_mbox",
return_value={
"aggregate_reports": [],
"failure_reports": [],
"smtp_tls_reports": [],
},
) as mock_mbox,
patch.object(
sys, "argv", ["parsedmarc", "-c", cfg_path, sample, mbox_path]
),
):
parsedmarc.cli._main()
self.assertEqual(len(calls), 1)
self.assertEqual(calls[0]["parse_timeout"], 30.0)
self.assertIs(calls[0]["timeout_result"], _file_timeout_result)
self.assertEqual(mock_mbox.call_args.kwargs["parse_timeout"], 30.0)
with open(os.path.join(output_dir, "aggregate.json")) as f:
self.assertEqual(len(json.load(f)), 1)
@unittest.skipUnless(
hasattr(signal, "SIGHUP"),
"SIGHUP not available on this platform",
)
def test_watch_gets_the_reloaded_value_after_sighup(self):
def config(parse_timeout):
parser = ConfigParser()
parser.read_string(
"[general]\nsilent = true\noffline = true\n"
f"parse_timeout = {parse_timeout}\n\n"
"[imap]\nhost = imap.example.com\nuser = user\npassword = pass\n\n"
"[mailbox]\nwatch = true\n"
)
return parser
cfg_path = self._write_config("[general]\n")
seen = []
def watch_side_effect(**kwargs):
seen.append(kwargs["parse_timeout"])
if len(seen) == 1:
os.kill(os.getpid(), signal.SIGHUP)
return
raise FileExistsError("stop-watch-loop")
with (
patch("parsedmarc.cli._load_config", side_effect=[config(5), config(7.5)]),
patch("parsedmarc.cli._init_output_clients", return_value={}),
patch("parsedmarc.cli.IMAPConnection", return_value=object()),
patch(
"parsedmarc.cli.get_dmarc_reports_from_mailbox",
return_value={
"aggregate_reports": [],
"failure_reports": [],
"smtp_tls_reports": [],
},
),
patch("parsedmarc.cli.watch_inbox", side_effect=watch_side_effect),
patch.object(sys, "argv", ["parsedmarc", "-c", cfg_path]),
):
with self.assertRaises(SystemExit):
parsedmarc.cli._main()
self.assertEqual(seen, [5.0, 7.5])
def _dying_parse_job(job, *, config):
"""Stand-in parse job that ends its worker process at once, as the
out-of-memory killer would. Module-level so it pickles."""
os._exit(1)
class TestWorkerDeathEndsTheRun(unittest.TestCase):
"""A parsing worker process that dies makes ``parallel_map`` raise
``ParserError``. For report files and mbox files _main() logs it, saves
the reports parsed before it, and exits with status 1, instead of
ending in a traceback. The workers really die here, under the default
start method."""
def setUp(self):
# The run records the reports it parses in the shared dedup set;
# leaving them there would make later runs skip the same samples.
parsedmarc.SEEN_AGGREGATE_REPORT_IDS.clear()
self.addCleanup(parsedmarc.SEEN_AGGREGATE_REPORT_IDS.clear)
for stream in ("sys.stdout", "sys.stderr"):
patcher = patch(stream, new_callable=io.StringIO)
patcher.start()
self.addCleanup(patcher.stop)
tmp_dir = tempfile.mkdtemp()
self.addCleanup(shutil.rmtree, tmp_dir, ignore_errors=True)
self.tmp_dir = tmp_dir
self.cfg_path = os.path.join(tmp_dir, "parsedmarc.ini")
with open(self.cfg_path, "w") as cfg:
cfg.write("[general]\nsilent = true\noffline = true\nn_procs = 2\n")
def _run_main(self, *inputs):
from parsedmarc.log import logger as _logger
self.addCleanup(setattr, _logger, "disabled", _logger.disabled)
_logger.disabled = False
with (
patch.object(sys, "argv", ["parsedmarc", "-c", self.cfg_path, *inputs]),
self.assertLogs("parsedmarc.log", level="ERROR") as logs,
self.assertRaises(SystemExit) as system_exit,
):
parsedmarc.cli._main()
self.assertEqual(system_exit.exception.code, 1)
self.assertTrue(
any("worker process died" in line for line in logs.output), logs.output
)
return logs.output
def test_report_files(self):
sample = "samples/aggregate/!example.com!1538204542!1538463818.xml"
other = "samples/aggregate/example.net!example.com!1529366400!1529452799.xml"
with patch("parsedmarc.cli._parse_report_file_job", _dying_parse_job):
self._run_main(sample, other)
def test_mbox(self):
mbox_path = os.path.join(self.tmp_dir, "reports.mbox")
box = mailbox.mbox(mbox_path)
with open("samples/aggregate/twilight.eml", "rb") as message:
content = message.read()
for _ in range(2):
box.add(mailbox.mboxMessage(content))
box.close()
with patch("parsedmarc.parallel._parse_report_email_job", _dying_parse_job):
self._run_main(mbox_path)
def test_reports_parsed_before_the_death_are_saved(self):
"""Report files are parsed before mbox files; a worker that dies on
the mbox must not discard the file's report, which with
archive_directory set has already been moved out of the input."""
output_dir = os.path.join(self.tmp_dir, "output")
with open(self.cfg_path, "a") as cfg:
cfg.write(f"output = {output_dir}\n")
mbox_path = os.path.join(self.tmp_dir, "reports.mbox")
box = mailbox.mbox(mbox_path)
with open("samples/aggregate/twilight.eml", "rb") as message:
content = message.read()
for _ in range(2):
box.add(mailbox.mboxMessage(content))
box.close()
sample = "samples/aggregate/!example.com!1538204542!1538463818.xml"
with patch("parsedmarc.parallel._parse_report_email_job", _dying_parse_job):
self._run_main(sample, mbox_path)
with open(os.path.join(output_dir, "aggregate.json")) as saved:
reports = json.load(saved)
self.assertEqual(
[r["report_metadata"]["report_id"] for r in reports],
["example.com:1538463741"],
)
def _write_twilight(self, box):
with open("samples/aggregate/twilight.eml", "rb") as message:
content = message.read()
for _ in range(2):
box.add(content)
def test_file_reports_are_saved_when_a_worker_dies_in_the_mailbox(self):
"""A worker that dies while a mailbox batch is parsed leaves that
batch in the mailbox, but the report file parsed before the
mailbox was opened is still saved."""
output_dir = os.path.join(self.tmp_dir, "output")
maildir_path = os.path.join(self.tmp_dir, "maildir")
with open(self.cfg_path, "a") as cfg:
cfg.write(f"output = {output_dir}\n")
cfg.write(f"[maildir]\npath = {maildir_path}\ncreate = true\n")
self._write_twilight(mailbox.Maildir(maildir_path, create=True))
sample = "samples/aggregate/!example.com!1538204542!1538463818.xml"
with patch("parsedmarc.parallel._parse_report_email_job", _dying_parse_job):
self._run_main(sample)
with open(os.path.join(output_dir, "aggregate.json")) as saved:
reports = json.load(saved)
self.assertEqual(
[r["report_metadata"]["report_id"] for r in reports],
["example.com:1538463741"],
)
self.assertEqual(len(mailbox.Maildir(maildir_path)), 2)
def test_input_error_opens_no_mailbox_and_keeps_the_archived_file(self):
"""After a worker dies on an mbox, the run opens no mailbox, and the
report file parsed before it stays under archive_directory."""
archive_dir = os.path.join(self.tmp_dir, "archive")
with open(self.cfg_path, "a") as cfg:
cfg.write(f"archive_directory = {archive_dir}\n")
cfg.write(f"[maildir]\npath = {self.tmp_dir}/maildir\ncreate = true\n")
report_name = "!example.com!1538204542!1538463818.xml"
report_path = os.path.join(self.tmp_dir, report_name)
shutil.copy(os.path.join("samples/aggregate", report_name), report_path)
mbox_path = os.path.join(self.tmp_dir, "reports.mbox")
box = mailbox.mbox(mbox_path)
self._write_twilight(box)
box.close()
with (
patch("parsedmarc.parallel._parse_report_email_job", _dying_parse_job),
patch("parsedmarc.cli.MaildirConnection") as maildir_connection,
):
self._run_main(report_path, mbox_path)
maildir_connection.assert_not_called()
self.assertFalse(os.path.exists(report_path))
archived = [name for _, _, names in os.walk(archive_dir) for name in names]
self.assertEqual(archived, [report_name])
def test_dying_file_worker_leaves_the_mbox_unread(self):
"""With one report file the file loop's death is certain; the mbox
after it is never read."""
mbox_path = os.path.join(self.tmp_dir, "reports.mbox")
box = mailbox.mbox(mbox_path)
self._write_twilight(box)
box.close()
sample = "samples/aggregate/!example.com!1538204542!1538463818.xml"
with (
patch("parsedmarc.cli._parse_report_file_job", _dying_parse_job),
patch("parsedmarc.cli.get_dmarc_reports_from_mbox") as read_mbox,
):
self._run_main(sample, mbox_path)
read_mbox.assert_not_called()
def _fail_file_output(self):
"""Point ``output`` at a regular file, so saving there fails, and
make that failure a ``ParserError`` with fail_on_output_error."""
not_a_directory = os.path.join(self.tmp_dir, "not-a-directory")
with open(not_a_directory, "w"):
pass
with open(self.cfg_path, "a") as cfg:
cfg.write(f"output = {not_a_directory}\nfail_on_output_error = true\n")
def _assert_both_errors_logged(self, logs):
joined = "\n".join(logs)
self.assertIn("worker process died", joined)
self.assertIn("Output destination failures detected", joined)
def test_failed_save_after_an_input_error_is_logged(self):
"""The save before exiting can fail too: both errors are logged and
the run still exits with status 1."""
self._fail_file_output()
mbox_path = os.path.join(self.tmp_dir, "reports.mbox")
box = mailbox.mbox(mbox_path)
self._write_twilight(box)
box.close()
sample = "samples/aggregate/!example.com!1538204542!1538463818.xml"
with patch("parsedmarc.parallel._parse_report_email_job", _dying_parse_job):
logs = self._run_main(sample, mbox_path)
self._assert_both_errors_logged(logs)
def test_failed_save_after_a_mailbox_worker_death_is_logged(self):
self._fail_file_output()
maildir_path = os.path.join(self.tmp_dir, "maildir")
with open(self.cfg_path, "a") as cfg:
cfg.write(f"[maildir]\npath = {maildir_path}\ncreate = true\n")
self._write_twilight(mailbox.Maildir(maildir_path, create=True))
sample = "samples/aggregate/!example.com!1538204542!1538463818.xml"
with patch("parsedmarc.parallel._parse_report_email_job", _dying_parse_job):
logs = self._run_main(sample)
self._assert_both_errors_logged(logs)
def test_report_files_with_the_progress_bar(self):
"""On a terminal the file loop drives a progress bar; the files are
still parsed and saved."""
output_dir = os.path.join(self.tmp_dir, "output")
with open(self.cfg_path, "a") as cfg:
cfg.write(f"output = {output_dir}\n")
samples = [
"samples/aggregate/!example.com!1538204542!1538463818.xml",
"samples/aggregate/example.net!example.com!1529366400!1529452799.xml",
]
with (
patch.object(sys.stderr, "isatty", return_value=True),
patch.object(sys, "argv", ["parsedmarc", "-c", self.cfg_path, *samples]),
patch("parsedmarc.cli.tqdm", wraps=parsedmarc.cli.tqdm) as progress,
):
parsedmarc.cli._main()
progress.assert_called_once_with(total=2)
with open(os.path.join(output_dir, "aggregate.json")) as saved:
self.assertEqual(len(json.load(saved)), 2)
_PID_DIR_VARIABLE = "TEST_PARSEDMARC_WORKER_PID_DIR"
# Run in a child interpreter by TestSecondCtrlCKillsTheWorkers: _main()
# parses the files named on its command line with the sleeping job below.
# The start method is the first argument.
_SLEEPING_CLI_SCRIPT = """
import multiprocessing
import sys
from unittest.mock import patch
import parsedmarc.cli
from tests.test_cli import _pid_marking_sleeping_file_job
if __name__ == "__main__":
multiprocessing.set_start_method(sys.argv[1], force=True)
with patch(
"parsedmarc.cli._parse_report_file_job", _pid_marking_sleeping_file_job
):
sys.argv = ["parsedmarc", *sys.argv[2:]]
parsedmarc.cli._main()
"""
def _pid_marking_sleeping_file_job(file_path, *, config):
"""Stand-in parse job that writes its worker's pid as a file name under
the directory ``_PID_DIR_VARIABLE`` names, then sleeps for a minute.
Module-level so it pickles; the variable is set before the child
interpreter starts, so every worker sees it."""
with open(os.path.join(os.environ[_PID_DIR_VARIABLE], str(os.getpid())), "w"):
pass
time.sleep(60)
return file_path, parsedmarc.ParserError("not parsed")
def _process_exists(pid):
try:
os.kill(pid, 0)
except ProcessLookupError:
return False
return True
class TestSecondCtrlCKillsTheWorkers(unittest.TestCase):
"""A second Ctrl-C ends parsedmarc with os._exit(130), which skips the
process pool's cleanup, and parsing workers ignore SIGINT; without the
handler killing them first they ran on as orphans. A real parsedmarc
process with two sleeping workers gets two SIGINTs here."""
def test_second_sigint_leaves_no_worker_running(self):
if not hasattr(signal, "SIGINT") or os.name != "posix":
self.skipTest("needs POSIX signals")
for method in multiprocessing.get_all_start_methods():
with self.subTest(start_method=method):
self._interrupt_twice(method)
def _interrupt_twice(self, method):
tmp_dir = tempfile.mkdtemp()
self.addCleanup(shutil.rmtree, tmp_dir, ignore_errors=True)
pid_dir = os.path.join(tmp_dir, "pids")
os.mkdir(pid_dir)
cfg_path = os.path.join(tmp_dir, "parsedmarc.ini")
with open(cfg_path, "w") as cfg:
cfg.write("[general]\nsilent = true\noffline = true\nn_procs = 2\n")
samples = [
"samples/aggregate/!example.com!1538204542!1538463818.xml",
"samples/aggregate/example.net!example.com!1529366400!1529452799.xml",
]
command = [sys.executable, "-c", _SLEEPING_CLI_SCRIPT, method]
child = subprocess.Popen(
[*command, "-c", cfg_path, *samples],
env={**os.environ, _PID_DIR_VARIABLE: pid_dir},
stdout=subprocess.DEVNULL,
stderr=subprocess.DEVNULL,
)
self.addCleanup(lambda: child.poll() is None and child.kill())
deadline = time.monotonic() + 30.0
while len(os.listdir(pid_dir)) < 2 and time.monotonic() < deadline:
time.sleep(0.05)
worker_pids = [int(name) for name in os.listdir(pid_dir)]
self.assertEqual(len(worker_pids), 2)
for pid in worker_pids:
self.addCleanup(
lambda pid=pid: _process_exists(pid) and os.kill(pid, signal.SIGKILL)
)
child.send_signal(signal.SIGINT)
# Apart, so the kernel cannot merge the two presses into one.
time.sleep(0.5)
child.send_signal(signal.SIGINT)
self.assertEqual(child.wait(timeout=30), 130)
deadline = time.monotonic() + 10.0
while any(map(_process_exists, worker_pids)) and time.monotonic() < deadline:
time.sleep(0.05)
self.assertEqual([pid for pid in worker_pids if _process_exists(pid)], [])
class TestParseConfigElasticsearch(unittest.TestCase):
def test_elasticsearch_basic(self):
from parsedmarc.cli import _parse_config
+51
View File
@@ -1115,6 +1115,57 @@ class TestSaveFailureReport(unittest.TestCase):
save_failure_report_to_elasticsearch(_failure_report())
self.assertIn("disk", str(ctx.exception))
def test_search_exception_wraps_to_elasticsearch_error(self):
"""The duplicate check's search failing is a ElasticsearchError, as it is for
the aggregate and SMTP TLS saves, not the search library's own error."""
bad_search = MagicMock()
bad_search.execute.side_effect = RuntimeError("network")
with (
patch("parsedmarc.elastic.Search", return_value=bad_search),
patch("parsedmarc.elastic.Index"),
patch.object(elastic_module._FailureReportDoc, "save") as mock_save,
):
with self.assertRaises(ElasticsearchError) as ctx:
save_failure_report_to_elasticsearch(_failure_report())
self.assertIn("network", str(ctx.exception))
mock_save.assert_not_called()
def test_overlong_sample_date_is_invalid_failure_report(self):
"""A sample Date too long to be a date is an InvalidFailureReport,
raised before the duplicate search, not a bare ValueError"""
report = _failure_report()
report["parsed_sample"]["date"] = "1" * 200
search = MagicMock()
with (
patch("parsedmarc.elastic.Search", return_value=search),
patch("parsedmarc.elastic.Index"),
patch.object(elastic_module._FailureReportDoc, "save") as mock_save,
):
with self.assertRaises(InvalidFailureReport):
save_failure_report_to_elasticsearch(report)
search.execute.assert_not_called()
mock_save.assert_not_called()
def test_header_with_empty_name_is_left_out(self):
"""An empty header name is not a valid field name, so the header is
skipped and the others are still saved. mail-parser drops a header
line that starts with ":" before it reaches the sample, so the
parsed sample is built directly."""
report = _failure_report()
report["parsed_sample"]["headers"][""] = "orphan value"
with (
patch("parsedmarc.elastic.Search", return_value=_empty_search()),
patch("parsedmarc.elastic.Index"),
patch.object(
elastic_module._FailureReportDoc, "save", autospec=True
) as mock_save,
):
save_failure_report_to_elasticsearch(report)
mock_save.assert_called_once()
headers = mock_save.call_args.args[0].sample.headers
self.assertNotIn("", headers)
self.assertEqual(headers["subject"], "Test")
def test_keyerror_wraps_to_invalid_failure_report(self):
"""A malformed failure report (missing a required field) is
surfaced as InvalidFailureReport so the caller can route it
+640
View File
@@ -42,7 +42,9 @@ from lxml import etree # type: ignore[import-untyped]
import parsedmarc
import parsedmarc.constants as constants
from parsedmarc.attempts import MAX_PARSE_ATTEMPTS, attempt_key
from parsedmarc.mail import IMAPConnection, MaildirConnection, MSGraphConnection
from parsedmarc.parallel import _parse_report_email_job
from parsedmarc.types import (
AggregateReport,
FailureReport,
@@ -3500,6 +3502,14 @@ This is not a DMARC report."""
parsedmarc.parse_report_email(email_str, offline=True)
self.assertIn("not-a-real-date", str(ctx.exception))
def testOverlongDateHeaderIsInvalidDMARCReport(self):
"""A Date header too long to be a date is an InvalidDMARCReport
naming the header, where it was a bare ParserError"""
email_str = "From: a@b.c\nDate: " + "1" * 200 + "\nSubject: x\n\nbody"
with self.assertRaises(parsedmarc.InvalidDMARCReport) as ctx:
parsedmarc.parse_report_email(email_str, offline=True)
self.assertIn("Date header", str(ctx.exception))
def testFailureTextReportParses(self):
"""A valid legacy text/plain failure report parses to a failure
report (the success path that builds the synthetic feedback report
@@ -3768,6 +3778,21 @@ Test body"""
)
self.assertIsNone(report["version"])
def testOverlongArrivalDateIsInvalidFailureReport(self):
"""An Arrival-Date too long to be a date is an InvalidFailureReport
naming the field, not an "Unexpected error" from the date parser"""
report_str = self._make_feedback_report().replace(
"Arrival-Date: Thu, 1 Jan 2024 00:00:00 +0000",
"Arrival-Date: " + "1" * 200,
)
self.assertIn("Arrival-Date: 111", report_str)
with self.assertRaises(parsedmarc.InvalidFailureReport) as ctx:
parsedmarc.parse_failure_report(
report_str, self._make_sample(), self._default_msg_date(), offline=True
)
self.assertIn("Arrival-Date", str(ctx.exception))
self.assertNotIn("Unexpected error", str(ctx.exception))
def testMissingUserAgent(self):
"""Missing user_agent defaults to None"""
report_str = self._make_feedback_report()
@@ -4478,6 +4503,27 @@ class TestGetDmarcReportsFromMailboxValidation(unittest.TestCase):
self.assertIn("max_unsaved_retries", str(ctx.exception))
conn.watch.assert_not_called()
def test_invalid_parse_timeout_raises_before_fetching_or_watching(self):
"""Like max_unsaved_retries: raised inside a watch check, the
ValueError would be swallowed and retried on every check."""
for parse_timeout in (-1.0, float("nan"), float("inf")):
with self.subTest(parse_timeout=parse_timeout):
conn = MagicMock()
with self.assertRaises(ValueError) as ctx:
parsedmarc.get_dmarc_reports_from_mailbox(
connection=conn, parse_timeout=parse_timeout
)
self.assertIn("parse_timeout", str(ctx.exception))
conn.fetch_messages.assert_not_called()
with self.assertRaises(ValueError) as ctx:
parsedmarc.watch_inbox(
mailbox_connection=conn,
callback=lambda batch: None,
parse_timeout=parse_timeout,
)
self.assertIn("parse_timeout", str(ctx.exception))
conn.watch.assert_not_called()
class TestMigrateForensicArchiveFolderErrorHandling(unittest.TestCase):
"""The one migration scenario a real on-disk Maildir can't reproduce: a
@@ -4758,6 +4804,116 @@ class TestGetDmarcReportsFromMailboxContentErrors(unittest.TestCase):
self.assertGreater(exercised, 0)
_SLOW_MESSAGE = (
"From: reporter@example.net\r\nTo: dmarc@example.com\r\n"
"Subject: slow to parse\r\nX-Test-Slow: yes\r\n\r\nbody\r\n"
)
def _parallel_map_timing_out(calls):
"""An in-process stand-in for ``parsedmarc.parallel.parallel_map`` that
runs the real job function on every message except the one carrying
``X-Test-Slow``, for which it yields ``timeout_result``, as the real
``parallel_map`` does for a job that ran past ``parse_timeout``. Each
call's keyword arguments and ``n_procs`` are appended to ``calls``."""
def fake_parallel_map(func, jobs, n_procs, **kwargs):
calls.append(dict(kwargs, n_procs=n_procs))
for job in jobs:
content = job if isinstance(job, bytes) else job.encode()
if b"X-Test-Slow: yes" in content:
yield kwargs["timeout_result"](job, kwargs["parse_timeout"])
else:
yield func(job)
return fake_parallel_map
class TestParseTimeoutDisposal(unittest.TestCase):
"""A message whose parse ran past ``parse_timeout`` is handled like any
other invalid message: moved to the invalid folder by the mailbox loop,
skipped with a warning by the mbox loop. With a timeout set, ``n_procs``
1 takes the ``parallel_map`` branch, since only a worker process can be
stopped. ``parallel_map`` is replaced by a stand-in that times out the
marked message, because a real parse that slow needs an input the parse
limits do not already reject; the timeout itself is tested in
``tests/test_parallel.py``."""
def setUp(self):
parsedmarc.SEEN_AGGREGATE_REPORT_IDS.clear()
self.addCleanup(parsedmarc.SEEN_AGGREGATE_REPORT_IDS.clear)
with open("samples/aggregate/twilight.eml", encoding="utf-8") as f:
self.aggregate = f.read()
def test_mailbox_message_that_times_out_moves_to_invalid(self):
calls = []
conn = _InMemoryIMAPConnection({1: _SLOW_MESSAGE, 2: self.aggregate})
with (
patch("parsedmarc.parallel.parallel_map", _parallel_map_timing_out(calls)),
self.assertLogs("parsedmarc.log", level="WARNING") as logs,
):
result = parsedmarc.get_dmarc_reports_from_mailbox(
connection=conn, offline=True, n_procs=1, parse_timeout=1.0
)
self.assertEqual(len(result["aggregate_reports"]), 1)
self.assertEqual(conn.folders["INBOX"], {})
self.assertEqual(list(conn.folders["Archive/Invalid"]), [1])
self.assertEqual(list(conn.folders["Archive/Aggregate"]), [2])
self.assertTrue(
any(
"longer than parse_timeout (1 seconds)" in line for line in logs.output
),
logs.output,
)
self.assertEqual(len(calls), 1)
self.assertEqual(calls[0]["n_procs"], 1)
self.assertEqual(calls[0]["parse_timeout"], 1.0)
self.assertEqual(calls[0]["heartbeat"], conn.keepalive)
def test_mailbox_without_timeout_and_one_process_parses_in_process(self):
calls = []
conn = _InMemoryIMAPConnection({2: self.aggregate})
with patch("parsedmarc.parallel.parallel_map", _parallel_map_timing_out(calls)):
result = parsedmarc.get_dmarc_reports_from_mailbox(
connection=conn, offline=True, n_procs=1
)
self.assertEqual(len(result["aggregate_reports"]), 1)
self.assertEqual(calls, [])
def test_mbox_message_that_times_out_is_skipped_with_a_warning(self):
tmp = mkdtemp()
self.addCleanup(rmtree, tmp, ignore_errors=True)
path = os.path.join(tmp, "reports.mbox")
box = mailbox.mbox(path)
box.lock()
try:
box.add(mailbox.mboxMessage(_SLOW_MESSAGE))
box.add(mailbox.mboxMessage(self.aggregate))
box.flush()
finally:
box.unlock()
box.close()
calls = []
with (
patch("parsedmarc.parallel.parallel_map", _parallel_map_timing_out(calls)),
self.assertLogs("parsedmarc.log", level="WARNING") as logs,
):
result = parsedmarc.get_dmarc_reports_from_mbox(
path, offline=True, n_procs=1, parse_timeout=1.0
)
self.assertEqual(len(result["aggregate_reports"]), 1)
self.assertTrue(
any(
"longer than parse_timeout (1 seconds)" in line for line in logs.output
),
logs.output,
)
self.assertEqual(len(calls), 1)
self.assertEqual(calls[0]["n_procs"], 1)
self.assertEqual(calls[0]["parse_timeout"], 1.0)
class _FailingFetchMaildirConnection(MaildirConnection):
"""A MaildirConnection whose every fetch fails like a dropped network
connection would."""
@@ -5696,6 +5852,490 @@ class TestGetDmarcReportsFromMailboxMaildirSaveCallback(unittest.TestCase):
self.assertEqual(len(conn.fetch_messages("Archive/Aggregate")), 1)
# Read by the worker job below, which runs in another process and so
# cannot be handed the test's temporary path any other way.
# The header that carries the attempts file's path to the worker job inside
# the message itself, the one input that reaches a worker under every start
# method (a spawned or forkserver worker inherits no environment changes or
# patches made in the test process). The parser ignores an unknown header.
_ATTEMPTS_FILE_HEADER = "X-Test-Attempts-File"
def _with_attempts_file_header(content, path):
"""Return ``content`` with the ``_ATTEMPTS_FILE_HEADER`` line before it."""
return f"{_ATTEMPTS_FILE_HEADER}: {path}\n{content}"
def _job_requiring_recorded_attempt(msg_content, *, config):
"""A parallel parse job that parses only a message whose attempt is
already in the attempts file its ``_ATTEMPTS_FILE_HEADER`` names, and
rejects any other as invalid.
Module level so a process pool can pickle it under every start method.
"""
text = msg_content if isinstance(msg_content, str) else msg_content.decode()
first_line = text.split("\n", 1)[0]
path = first_line.removeprefix(f"{_ATTEMPTS_FILE_HEADER}: ")
with open(path, encoding="utf-8") as f:
attempts = json.load(f)["attempts"]
digest = attempt_key("", "", msg_content).rsplit("\x1f", 1)[1]
if not any(
key.endswith("\x1f" + digest) and entry["count"] == 1
for key, entry in attempts.items()
):
return parsedmarc.InvalidDMARCReport("no attempt recorded before the job")
return _parse_report_email_job(msg_content, config=config)
class _FailingInvalidMoveIMAPConnection(_InMemoryIMAPConnection):
"""The in-memory IMAP backend, refusing every move to the Invalid
folder."""
def move_message(self, message_id, folder_name):
if folder_name.endswith("/Invalid"):
raise RuntimeError("server said no")
super().move_message(message_id, folder_name)
class _ArrivalIMAPConnection(_InMemoryIMAPConnection):
"""The in-memory IMAP backend, delivering one more message right after
its first fetch_messages() call, so batch_size=0 recurses once."""
def __init__(self, messages, extra_id, extra_content):
super().__init__(messages)
self._extra = (extra_id, extra_content)
def fetch_messages(self, reports_folder, **kwargs):
result = super().fetch_messages(reports_folder, **kwargs)
if self._extra is not None:
extra_id, extra_content = self._extra
self._extra = None
self.folders["INBOX"][extra_id] = extra_content
return result
class _SingleCheckIMAPConnection(_InMemoryIMAPConnection):
"""The in-memory IMAP backend, whose watch() runs one check."""
def watch(self, check_callback, check_timeout, config_reloading=None):
del check_timeout, config_reloading
check_callback(self)
class TestCrashedMessageAttempts(unittest.TestCase):
"""attempts_file: a message whose parse never finished (the process
died) is counted in a JSON file, and once it has died
MAX_PARSE_ATTEMPTS times it is set aside as invalid without being
parsed again, so a one-shot run no longer dies on it forever
(GHSA-qcc2-4x3v-v4g7, GHSA-q7gm-8cj9-94hr, GHSA-4272-4r8g-6c5h). The
file is read and written for real; the process deaths are simulated by
seeding the file with the count earlier runs would have left."""
AGGREGATE = "samples/aggregate/twilight.eml"
SMTP_TLS = "samples/smtp_tls/google.com_smtp_tls_report.eml"
FAILURE = "samples/failure/dmarc_ruf_report_linkedin.eml"
def setUp(self):
self._tmp = mkdtemp()
self.addCleanup(rmtree, self._tmp, ignore_errors=True)
parsedmarc.SEEN_AGGREGATE_REPORT_IDS.clear()
parsedmarc._FAILED_SAVE_ATTEMPTS.clear()
self.addCleanup(parsedmarc._FAILED_SAVE_ATTEMPTS.clear)
self.path = os.path.join(self._tmp, "attempts.json")
self.samples = {}
for name in (self.AGGREGATE, self.SMTP_TLS, self.FAILURE):
with open(name, encoding="utf-8") as sample:
self.samples[name] = sample.read()
def _seed(self, message_id, content, count):
with open(self.path, "w", encoding="utf-8") as attempts_file:
json.dump(
{
"version": 1,
"attempts": {
attempt_key("INBOX", message_id, content): {
"count": count,
"last": datetime.now(timezone.utc).isoformat(),
}
},
},
attempts_file,
)
def _attempts(self):
with open(self.path, encoding="utf-8") as attempts_file:
return json.load(attempts_file)["attempts"]
def _run(self, conn, **kwargs):
parsedmarc.SEEN_AGGREGATE_REPORT_IDS.clear()
return parsedmarc.get_dmarc_reports_from_mailbox(
connection=conn, offline=True, attempts_file=self.path, **kwargs
)
def test_attempt_is_recorded_before_the_parse_and_cleared_after(self):
content = self.samples[self.AGGREGATE]
key = attempt_key("INBOX", 1, content)
seen_during_parse = []
real_parse = parsedmarc.parse_report_email
def parse_and_look(*args, **kwargs):
seen_during_parse.append(self._attempts().get(key))
return real_parse(*args, **kwargs)
conn = _InMemoryIMAPConnection({1: content})
with patch("parsedmarc.parse_report_email", parse_and_look):
result = self._run(conn)
self.assertEqual(len(result["aggregate_reports"]), 1)
self.assertEqual(len(seen_during_parse), 1)
self.assertIsNotNone(seen_during_parse[0])
self.assertEqual(seen_during_parse[0]["count"], 1)
self.assertEqual(self._attempts(), {})
self.assertEqual(list(conn.folders["Archive/Aggregate"]), [1])
def test_unparseable_message_clears_its_attempt(self):
"""A ParserError is a finished parse: the message goes to Invalid
as before and its attempt is not left behind to count as a crash."""
junk = "From: noise@example.com\nSubject: not a report\n\nplain text\n"
conn = _InMemoryIMAPConnection({1: junk})
with self.assertLogs("parsedmarc.log", level="WARNING"):
self._run(conn)
self.assertEqual(list(conn.folders["Archive/Invalid"]), [1])
self.assertEqual(self._attempts(), {})
def test_message_at_the_cap_is_moved_to_invalid_without_parsing(self):
crashed = self.samples[self.AGGREGATE]
healthy = self.samples[self.SMTP_TLS]
for n_procs in (1, 2):
with self.subTest(n_procs=n_procs):
self._seed(1, crashed, count=2)
parsed = []
real_parse = parsedmarc.parse_report_email
def parse_and_note(content, *args, **kwargs):
parsed.append(content)
return real_parse(content, *args, **kwargs)
conn = _InMemoryIMAPConnection({1: crashed, 2: healthy})
with patch("parsedmarc.parse_report_email", parse_and_note):
with self.assertLogs("parsedmarc.log", level="ERROR") as cm:
result = self._run(conn, n_procs=n_procs)
self.assertEqual(result["aggregate_reports"], [])
self.assertEqual(len(result["smtp_tls_reports"]), 1)
self.assertEqual(conn.folders["INBOX"], {})
self.assertEqual(list(conn.folders["Archive/Invalid"]), [1])
self.assertEqual(list(conn.folders["Archive/SMTP-TLS"]), [2])
self.assertIn(
"Message UID 1 in INBOX has 2 unfinished parse attempts; "
"the limit is 2. Moving it to Archive/Invalid without "
"parsing it",
"\n".join(cm.output),
)
self.assertNotIn(crashed, parsed)
if n_procs == 1:
self.assertEqual(parsed, [healthy])
# Out of the folder, so the entry is gone.
self.assertEqual(self._attempts(), {})
def test_message_below_the_cap_is_parsed_again(self):
"""One unfinished attempt (a crash for any reason) is not enough:
the message is parsed again, and a successful parse clears it."""
content = self.samples[self.AGGREGATE]
self._seed(1, content, count=1)
conn = _InMemoryIMAPConnection({1: content})
result = self._run(conn)
self.assertEqual(len(result["aggregate_reports"]), 1)
self.assertEqual(list(conn.folders["Archive/Aggregate"]), [1])
self.assertEqual(self._attempts(), {})
def test_message_at_the_cap_is_deleted_with_delete_invalid(self):
content = self.samples[self.AGGREGATE]
for n_procs in (1, 2):
with self.subTest(n_procs=n_procs):
self._seed(1, content, count=2)
conn = _InMemoryIMAPConnection(
{1: content, 2: self.samples[self.SMTP_TLS]}
)
with self.assertLogs("parsedmarc.log", level="ERROR") as cm:
self._run(conn, n_procs=n_procs, delete_invalid=True)
self.assertEqual(conn.folders["INBOX"], {})
self.assertEqual(conn.folders["Archive/Invalid"], {})
self.assertEqual(conn.folders["Archive/Aggregate"], {})
self.assertIn(
"has 2 unfinished parse attempts; the limit is 2. "
"Deleting it without parsing it",
"\n".join(cm.output),
)
self.assertEqual(self._attempts(), {})
def test_failed_save_is_not_counted_as_a_crash(self):
"""The attempt is cleared when the parse returns, before the save,
so a batch an output keeps rejecting stays in the folder for the
Unsaved retry logic and is never set aside as a crashed message."""
content = self.samples[self.AGGREGATE]
conn = _InMemoryIMAPConnection({1: content})
for _ in range(MAX_PARSE_ATTEMPTS + 2):
with self.assertLogs("parsedmarc.log", level="ERROR"):
self._run(
conn, save_callback=lambda batch: False, max_unsaved_retries=10
)
self.assertEqual(self._attempts(), {})
self.assertEqual(list(conn.folders["INBOX"]), [1])
self.assertEqual(conn.folders["Archive/Invalid"], {})
def test_test_mode_records_and_clears_but_moves_nothing(self):
"""In the serial path and the parallel one (n_procs 2), the message
at the cap is logged and left in place, not parsed or moved."""
crashed = self.samples[self.AGGREGATE]
healthy = self.samples[self.SMTP_TLS]
junk = "From: noise@example.com\nSubject: not a report\n\nplain text\n"
for n_procs in (1, 2):
with self.subTest(n_procs=n_procs):
self._seed(1, crashed, count=2)
conn = _InMemoryIMAPConnection({1: crashed, 2: healthy, 3: junk})
with self.assertLogs("parsedmarc.log", level="WARNING") as cm:
result = self._run(conn, test=True, n_procs=n_procs)
self.assertEqual(result["aggregate_reports"], [])
self.assertEqual(len(result["smtp_tls_reports"]), 1)
self.assertEqual(sorted(conn.folders["INBOX"]), [1, 2, 3])
self.assertNotIn("Archive/Invalid", conn.folders)
self.assertIn(
"Message UID 1 in INBOX has 2 unfinished parse attempts; "
"the limit is 2. Leaving it in place without parsing it "
"(test mode)",
"\n".join(cm.output),
)
# The set-aside message is still in the folder, so its count
# stays; the parsed and the unparseable ones were recorded
# and cleared.
attempts = self._attempts()
key = attempt_key("INBOX", 1, crashed)
self.assertEqual(list(attempts), [key])
self.assertEqual(attempts[key]["count"], 2)
def test_set_aside_count_does_not_grow_on_later_runs(self):
"""A message left in place at the cap (test mode here, a failed move
likewise) is not recorded again, so every later run logs the same
count instead of one more each time, in both paths."""
crashed = self.samples[self.AGGREGATE]
key = attempt_key("INBOX", 1, crashed)
for n_procs in (1, 2):
with self.subTest(n_procs=n_procs):
self._seed(1, crashed, count=2)
for _ in range(3):
conn = _InMemoryIMAPConnection({1: crashed})
with self.assertLogs("parsedmarc.log", level="ERROR") as cm:
self._run(conn, test=True, n_procs=n_procs)
self.assertIn(
"has 2 unfinished parse attempts; the limit is 2.",
"\n".join(cm.output),
)
self.assertEqual(self._attempts()[key]["count"], 2)
def test_parallel_path_records_each_attempt_before_submitting_it(self):
conn = _InMemoryIMAPConnection(
{
1: _with_attempts_file_header(self.samples[self.AGGREGATE], self.path),
2: _with_attempts_file_header(self.samples[self.SMTP_TLS], self.path),
}
)
with patch(
"parsedmarc.parallel._parse_report_email_job",
_job_requiring_recorded_attempt,
):
result = self._run(conn, n_procs=2)
# The job rejects a message whose attempt was not yet on disk, which
# would have sent it to Invalid.
self.assertEqual(len(result["aggregate_reports"]), 1)
self.assertEqual(len(result["smtp_tls_reports"]), 1)
self.assertNotIn(1, conn.folders["Archive/Invalid"])
self.assertNotIn(2, conn.folders["Archive/Invalid"])
self.assertEqual(self._attempts(), {})
def test_parallel_path_parses_a_suspect_alone_in_this_process(self):
"""With n_procs > 1 a run that died had several messages in flight,
and only one of them killed it. A message with one unfinished
attempt is therefore not submitted to the pool beside others: it is
parsed in this process after them, its attempt recorded first, so a
second death counts against it alone and the messages parsed beside
it the first time are not set aside with it."""
suspect = self.samples[self.AGGREGATE]
others = {2: self.samples[self.SMTP_TLS], 3: self.samples[self.FAILURE]}
self._seed(1, suspect, count=1)
key = attempt_key("INBOX", 1, suspect)
parsed_here = []
real_parse = parsedmarc.parse_report_email
parent = os.getpid()
def parse_and_look(content, *args, **kwargs):
if os.getpid() == parent:
parsed_here.append((content, self._attempts().get(key)))
return real_parse(content, *args, **kwargs)
conn = _InMemoryIMAPConnection({1: suspect, **others})
with patch("parsedmarc.parse_report_email", parse_and_look):
with self.assertLogs("parsedmarc.log", level="WARNING") as cm:
result = self._run(conn, n_procs=2)
self.assertEqual(len(parsed_here), 1)
self.assertEqual(parsed_here[0][0], suspect)
self.assertEqual(parsed_here[0][1]["count"], 2)
self.assertIn(
"Message UID 1 in INBOX was being parsed when parsedmarc last "
"stopped without finishing; parsing it on its own",
"\n".join(cm.output),
)
self.assertEqual(len(result["aggregate_reports"]), 1)
self.assertEqual(len(result["smtp_tls_reports"]), 1)
self.assertEqual(len(result["failure_reports"]), 1)
self.assertEqual(conn.folders["INBOX"], {})
self.assertEqual(self._attempts(), {})
def _recording_parallel_map(self, calls, jobs_seen):
"""``_parallel_map_timing_out`` that also notes each job it is
given, per call, as the call consumes it."""
fake = _parallel_map_timing_out(calls)
def recording(func, jobs, n_procs, **kwargs):
seen = []
jobs_seen.append(seen)
def noted():
for job in jobs:
seen.append(job)
yield job
return fake(func, noted(), n_procs, **kwargs)
return recording
def test_suspect_parse_is_bounded_by_parse_timeout(self):
"""With parse_timeout set, a suspect is parsed alone in a worker
pool of its own rather than in this process, where the timeout
could not stop it; one that times out goes to Invalid like any
other timed-out message and its attempt is cleared."""
others = {2: self.samples[self.AGGREGATE], 3: self.samples[self.SMTP_TLS]}
for n_procs in (1, 2):
with self.subTest(n_procs=n_procs):
self._seed(1, _SLOW_MESSAGE, count=1)
calls = []
jobs_seen = []
conn = _InMemoryIMAPConnection({1: _SLOW_MESSAGE, **others})
with (
patch(
"parsedmarc.parallel.parallel_map",
self._recording_parallel_map(calls, jobs_seen),
),
self.assertLogs("parsedmarc.log", level="WARNING") as cm,
):
result = self._run(conn, n_procs=n_procs, parse_timeout=1.0)
self.assertEqual(len(calls), 2)
self.assertNotIn(_SLOW_MESSAGE, jobs_seen[0])
self.assertEqual(jobs_seen[1], [_SLOW_MESSAGE])
self.assertEqual(calls[1]["n_procs"], 1)
self.assertEqual(calls[1]["parse_timeout"], 1.0)
self.assertEqual(calls[1]["heartbeat"], conn.keepalive)
self.assertIn(
"longer than parse_timeout (1 seconds)", "\n".join(cm.output)
)
self.assertEqual(list(conn.folders["Archive/Invalid"]), [1])
self.assertEqual(len(result["aggregate_reports"]), 1)
self.assertEqual(len(result["smtp_tls_reports"]), 1)
self.assertEqual(conn.folders["INBOX"], {})
self.assertEqual(self._attempts(), {})
def test_suspect_without_parse_timeout_is_parsed_in_this_process(self):
"""Without a timeout nothing would bound a worker any better than
this process, so the suspect is not given to parallel_map."""
suspect = self.samples[self.AGGREGATE]
self._seed(1, suspect, count=1)
calls = []
jobs_seen = []
conn = _InMemoryIMAPConnection({1: suspect, 2: self.samples[self.SMTP_TLS]})
with (
patch(
"parsedmarc.parallel.parallel_map",
self._recording_parallel_map(calls, jobs_seen),
),
self.assertLogs("parsedmarc.log", level="WARNING"),
):
result = self._run(conn, n_procs=2)
self.assertEqual(len(calls), 1)
self.assertNotIn(suspect, jobs_seen[0])
self.assertEqual(len(result["aggregate_reports"]), 1)
self.assertEqual(len(result["smtp_tls_reports"]), 1)
self.assertEqual(conn.folders["INBOX"], {})
self.assertEqual(self._attempts(), {})
def test_failed_disposal_keeps_the_entry(self):
"""The entry is cleared only once the message has left the folder:
a move the server refuses leaves the count in place, so the next
run sets the message aside again instead of parsing it."""
content = self.samples[self.AGGREGATE]
key = attempt_key("INBOX", 1, content)
for n_procs in (1, 2):
with self.subTest(n_procs=n_procs):
self._seed(1, content, count=2)
conn = _FailingInvalidMoveIMAPConnection(
{1: content, 2: self.samples[self.SMTP_TLS]}
)
with self.assertLogs("parsedmarc.log", level="ERROR") as cm:
self._run(conn, n_procs=n_procs)
self.assertEqual(list(conn.folders["INBOX"]), [1])
self.assertEqual(self._attempts()[key]["count"], 2)
self.assertIn(
"Error moving invalid message UID 1", "\n".join(cm.output)
)
def test_batch_size_zero_recursion_forwards_the_attempts_file(self):
"""A message that arrives during the run is processed by the
recursive re-check call, which must use the same attempts file."""
crashed = self.samples[self.SMTP_TLS]
self._seed(2, crashed, count=2)
conn = _ArrivalIMAPConnection(
{1: self.samples[self.AGGREGATE]}, extra_id=2, extra_content=crashed
)
with self.assertLogs("parsedmarc.log", level="ERROR"):
result = self._run(conn, batch_size=0)
self.assertEqual(len(result["aggregate_reports"]), 1)
self.assertEqual(result["smtp_tls_reports"], [])
self.assertEqual(list(conn.folders["Archive/Invalid"]), [2])
def test_watch_inbox_forwards_the_attempts_file(self):
crashed = self.samples[self.AGGREGATE]
self._seed(1, crashed, count=2)
conn = _SingleCheckIMAPConnection({1: crashed})
conn.create_folder("Archive/Invalid")
with self.assertLogs("parsedmarc.log", level="ERROR"):
parsedmarc.watch_inbox(
conn,
lambda batch: None,
offline=True,
attempts_file=self.path,
)
self.assertEqual(list(conn.folders["Archive/Invalid"]), [1])
self.assertEqual(self._attempts(), {})
def test_no_attempts_file_keeps_no_record(self):
content = self.samples[self.AGGREGATE]
self._seed(1, content, count=5)
conn = _InMemoryIMAPConnection({1: content})
parsedmarc.SEEN_AGGREGATE_REPORT_IDS.clear()
result = parsedmarc.get_dmarc_reports_from_mailbox(
connection=conn, offline=True
)
self.assertEqual(len(result["aggregate_reports"]), 1)
self.assertEqual(list(conn.folders["Archive/Aggregate"]), [1])
# The file is neither consulted nor written.
self.assertEqual(self._attempts()[attempt_key("INBOX", 1, content)]["count"], 5)
class _MidRunArrivalMaildirConnection(MaildirConnection):
"""A MaildirConnection that delivers one extra message into the INBOX
right after its first fetch_messages() call returns, simulating mail
+51
View File
@@ -1145,6 +1145,57 @@ class TestSaveFailureReport(unittest.TestCase):
save_failure_report_to_opensearch(_failure_report())
self.assertIn("disk", str(ctx.exception))
def test_search_exception_wraps_to_opensearch_error(self):
"""The duplicate check's search failing is a OpenSearchError, as it is for
the aggregate and SMTP TLS saves, not the search library's own error."""
bad_search = MagicMock()
bad_search.execute.side_effect = RuntimeError("network")
with (
patch("parsedmarc.opensearch.Search", return_value=bad_search),
patch("parsedmarc.opensearch.Index"),
patch.object(opensearch_module._FailureReportDoc, "save") as mock_save,
):
with self.assertRaises(OpenSearchError) as ctx:
save_failure_report_to_opensearch(_failure_report())
self.assertIn("network", str(ctx.exception))
mock_save.assert_not_called()
def test_overlong_sample_date_is_invalid_failure_report(self):
"""A sample Date too long to be a date is an InvalidFailureReport,
raised before the duplicate search, not a bare ValueError"""
report = _failure_report()
report["parsed_sample"]["date"] = "1" * 200
search = MagicMock()
with (
patch("parsedmarc.opensearch.Search", return_value=search),
patch("parsedmarc.opensearch.Index"),
patch.object(opensearch_module._FailureReportDoc, "save") as mock_save,
):
with self.assertRaises(InvalidFailureReport):
save_failure_report_to_opensearch(report)
search.execute.assert_not_called()
mock_save.assert_not_called()
def test_header_with_empty_name_is_left_out(self):
"""An empty header name is not a valid field name, so the header is
skipped and the others are still saved. mail-parser drops a header
line that starts with ":" before it reaches the sample, so the
parsed sample is built directly."""
report = _failure_report()
report["parsed_sample"]["headers"][""] = "orphan value"
with (
patch("parsedmarc.opensearch.Search", return_value=_empty_search()),
patch("parsedmarc.opensearch.Index"),
patch.object(
opensearch_module._FailureReportDoc, "save", autospec=True
) as mock_save,
):
save_failure_report_to_opensearch(report)
mock_save.assert_called_once()
headers = mock_save.call_args.args[0].sample.headers
self.assertNotIn("", headers)
self.assertEqual(headers["subject"], "Test")
def test_keyerror_wraps_to_invalid_failure_report(self):
"""A malformed failure report (missing a required field) is
surfaced as InvalidFailureReport so the caller can route it
+991 -1
View File
File diff suppressed because it is too large. Load diff
+53
View File
@@ -1148,6 +1148,59 @@ class TestTimestampAssumeUtc(unittest.TestCase):
self.assertEqual(int(dt.timestamp()), self.TRUE_EPOCH)
class TestTimestampLengthGuard(unittest.TestCase):
"""``human_timestamp_to_datetime`` refuses a string too long to be a date.
dateutil's time grows with the length of a digit run: on 11.2.1 under
Python 3.12 a digit string of 65,536 characters failed in 0.06 s, one of
262,144 in 0.87 s and one of 1,000,000 in 12.4 s, each as an
``OverflowError``. RFC 5322 dates, comments included, are far shorter
than the limit."""
def testLongDigitRunRaisesValueErrorQuickly(self):
"""262,144 digits took 0.87 s to fail on 11.2.1, as an OverflowError"""
limit = budget(0.2)
start = time.perf_counter()
with self.assertRaises(ValueError) as ctx:
parsedmarc.utils.human_timestamp_to_datetime("1" * 262_144)
elapsed = time.perf_counter() - start
self.assertIn("characters", str(ctx.exception))
self.assertNotIn("1111", str(ctx.exception))
self.assertLess(elapsed, limit)
def testLimitIsInclusive(self):
"""A string at the limit is parsed, one character more is refused.
The padding is inside the date, where stripping leaves it and
dateutil skips it."""
limit = parsedmarc.utils.MAX_TIMESTAMP_LENGTH
at_limit = "2024-01-15" + " " * (limit - 18) + "12:00:00"
self.assertEqual(len(at_limit), limit)
self.assertEqual(
parsedmarc.utils.human_timestamp_to_datetime(at_limit).year, 2024
)
over_limit = "2024-01-15" + " " * (limit - 17) + "12:00:00"
with self.assertRaises(ValueError):
parsedmarc.utils.human_timestamp_to_datetime(over_limit)
def testRfc5322DateWithCommentsStillParses(self):
dt = parsedmarc.utils.human_timestamp_to_datetime(
"Mon, 15 Jan 2024 12:00:00 +0000 (Coordinated Universal Time)"
)
self.assertEqual(dt.hour, 12)
def testLongCommentIsNotCounted(self):
"""RFC 5322 section 3.2.2 puts no limit on a comment's length, so the
limit applies once comments are removed: a valid date with a
300-character comment parses, and 300 digits are still refused."""
dt = parsedmarc.utils.human_timestamp_to_datetime(
"Mon, 15 Jan 2024 12:00:00 +0000 (" + "x" * 300 + ")"
)
self.assertEqual((dt.year, dt.hour), (2024, 12))
with self.assertRaises(ValueError) as ctx:
parsedmarc.utils.human_timestamp_to_datetime("1" * 300)
self.assertIn("characters", str(ctx.exception))
class TestUtilsIpDbPaths(unittest.TestCase):
"""Tests for IP database path validation"""