diff --git a/CHANGELOG.md b/CHANGELOG.md index b93222bb..94c2176b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,16 +4,25 @@ ### Security -- **Crafted email messages no longer take seconds to minutes and hundreds of megabytes to parse** ([GHSA-qcc2-4x3v-v4g7](https://github.com/domainaware/parsedmarc/security/advisories/GHSA-qcc2-4x3v-v4g7), affects 11.2.1 and earlier). `parse_report_email()` (mailbox, mbox and file input) and the failure-sample parser `parsedmarc.utils.parse_email()` gave the whole message to mail-parser and Python's `email` package with no limit on blank lines, header lines, header field size, MIME parts or nested multiparts. Parsing builds one `Message` per blank line after a `message/delivery-status` part (512 KiB of blank lines took 6.1 s and 283 MiB of extra memory on 11.2.1 under Python 3.12) and tests every line against every open boundary of nested multiparts (900 levels around 30,000 parts, 0.3 MB, took 10.9 s); a 4 MiB flood of header lines took 1.4 s, and a 1 MB `To:` address group of 250,000 members took 1.9 s, or 44 s through mailsuite's own `parse_email()`, which parsed the group whole. With `n_procs = 1` the rest of the mailbox waited behind such a message, and a process with a memory cap was killed before the message was moved, so it was parsed again on the next run. Both parsers now call `mailsuite.utils.check_message_limits()`, new in mailsuite 2.3.5 ([GHSA-748w-c9w9-79xp](https://github.com/seanthegeek/mailsuite/security/advisories/GHSA-748w-c9w9-79xp)), before mail-parser sees the message. It parses the message with the `email` package's own feed parser under the `compat32` policy, the parser mail-parser and `email.message_from_string()` use, and stops as soon as the message has more than 10,000 parts (the message itself, its MIME parts, the bodies of `message/*` parts and each block of a `message/delivery-status` body), nests them more than 100 levels deep, or makes the parser test a line against an open boundary more than 20,000,000 times. It also stops when the message's header blocks hold more than 100,000 lines in all (folded lines and lines the parser keeps only as defects included). It then rejects a parsed message with a header field longer than 65,536 characters (name, colon and raw value, folded lines included), or whose `From`, `Sender`, `Reply-To`, `To`, `Cc`, `Bcc` and `Delivered-To` headers hold more than 262,144 characters in all, counted in every part; that limit bounds mail-parser's own address parsing (it parses `From`, `Reply-To`, `To`, `Cc`, `Bcc` and `Delivered-To`), which does work for each malformed address item. When a part lacks its start boundary, mail-parser parses the top-level epilogue again, and that text is checked with the same limits. `parse_report_email()` also no longer renders every part it walks as text: it renders a part only where it reads it, because rendering each level of a deep nesting rendered everything inside it again (98 nested multiparts around a 20 MiB leaf took 26.6 s, a chain of 99 `message/rfc822` parts around a 10 MiB leaf 11.3 s, and a chain of 99 `message/feedback-report` parts around a 10 MiB leaf 11.6 s, all within the limits; each now takes under a second). An over-limit email raises `InvalidDMARCReport("Message rejected: Message exceeds ()")`, which the mailbox loop files under `Invalid`; an over-limit failure-report sample raises `InvalidFailureReport("Sample message rejected: …")`. Each crafted message from the report is now rejected in under half a second (the 4 MiB header flood, the slowest, in 0.2 s). **mailsuite 2.3.5 or later is now required.** The floor applies to the base dependency and to the `msgraph`, `gmail` and `all` extras. mailsuite 2.3.5 also removes RFC 5322 group syntax from address header values over 8 KiB before parsing them, caps the address header value its own `parse_email()` reads at 65,536 characters, and fixes a quadratic `url_regex`; all only affect callers of mailsuite's `parse_email()`, which parsedmarc does not use. A follow-up issue tracks a per-job timeout in `parallel_map()`. **Compatibility:** the limits are fixed; there is no new option. A message with more than 10,000 parts or parts nested more than 100 levels deep is now rejected as invalid instead of being parsed or, when nested past Python's recursion limit, failing with a `ParserError`; in mbox input such a message (the nested message of GHSA-qxwv-2vwj-v828 is one) is now skipped with a warning instead of stopping the run. A `message/rfc822` attached inside a failure report's sample no longer replaces the sample, since a feedback report has one sample ([RFC 6591 §3.1](https://www.rfc-editor.org/rfc/rfc6591#section-3.1)), and only the first `message/feedback-report` part of a message is read, since a feedback report has one ([RFC 6591 §3](https://www.rfc-editor.org/rfc/rfc6591#section-3)). Reported by helixnebulatech. -- **Deeply nested or very wide aggregate report XML no longer exhausts memory** ([GHSA-q7gm-8cj9-94hr](https://github.com/domainaware/parsedmarc/security/advisories/GHSA-q7gm-8cj9-94hr), affects 11.2.1 and earlier). `parse_aggregate_report_xml()` passed the decompressed report, up to the 100 MiB decompression cap, to `xmltodict.parse()` with no limit on nesting depth or element count. xmltodict keeps one stack entry per open element and expat reports missing end tags only at the end of the input, so a gzip attachment of about 30 KB holding 30 MiB of unclosed `` tags needed more than 2 GB of memory (2 MiB of them cost 255 MiB on 11.2.1). The out-of-memory killer ended the process before the message was moved, so every restart parsed it again. A document of millions of sibling elements did the same at a smaller scale, and a document whose first parse failed was parsed again through lxml recovery and a second xmltodict pass. While expat reads the document, before xmltodict adds each element to its tree, parsedmarc now counts nesting depth and nodes (elements plus attributes); a report deeper than 100 levels (`MAX_XML_DEPTH`) or with more than 1,000,000 nodes (`MAX_XML_NODES`) is rejected as `InvalidAggregateReport("Invalid XML: …")` without trying lxml recovery. Before any parser sees the document, a tag longer than 65,536 characters (`MAX_XML_TAG_LENGTH`) is rejected too, because expat and libxml2 build an element's whole attribute list before its attributes can be counted (one element with 900,000 attributes, 9.3 MiB, within the node limit, took 1.1 s and +200 MiB; it is now rejected in under 0.1 s). Because a quoted attribute value may hold a raw `>`, which splits a tag for that scan, a document with more `=` characters than the node limit is rejected first, in one pass (2,000,000 `x=">"` attributes, 23.7 MiB, took 1.4 s and +310 MiB before the node limit rejected them; they are now rejected in under 0.1 s). The decompression cap for a report attachment is lowered from 100 MiB to 32 MiB (`MAX_DECOMPRESSED_REPORT_SIZE`), and an uncompressed report of more than 32 MiB of UTF-8 is rejected the same way, as is a report file of that size, which is no longer tried as a report email: at the node limit a legitimate report is at most about 28 MB, and with that cap a report's text is bounded along with its node count. When the first parse fails and lxml recovery runs, a parser target that builds no tree first counts the document's elements, attributes and namespace declarations against the same node limit (a 22 MiB wide document behind a malformed XML declaration took 5.0 s and 1,532 MiB of extra memory before, 0.57 s and 23 MiB now), and the recovered XML then goes through the same depth and node limits in the second xmltodict pass. A follow-up issue tracks a persisted failed-attempt marker, so that a message that kills the process before it is filed is moved to `Invalid` after a number of runs. **Compatibility:** there is no new option. A real report is fewer than 10 levels deep and the largest sample (909 KB) has 32,019 nodes, so the node limit is a report of about 28 MB of XML; a larger report is now rejected. A report at the size cap needs about 400 MB of memory on the lxml recovery path and about 350 MB otherwise when its text is parsed directly, and about 500 MB and 450 MB through `parse_report_file()`, which also holds the file's bytes, where a report under the old 100 MiB decompression cap could need gigabytes. An aggregate or SMTP TLS report of more than 32 MiB of UTF-8, compressed or not, is now rejected, where 100 MiB was accepted (an uncompressed SMTP TLS report had no cap: 60 MiB of JSON cost +1,505 MiB). `parse_report_file()` no longer tries a file that begins with `<` as SMTP TLS JSON or a report email, nor one that begins with `{` as a report email; its error message is unchanged, and the exception's cause now matches the format the file begins with. It also keeps only each failed attempt's message while it tries the next format, so a file at the size cap on the lxml recovery path takes +500 MiB there, where it took +1,046 MiB. The XML parse step is about 20% slower, and a malformed document that needs lxml recovery is now parsed twice by lxml (once to count, once to build the tree). Reported by helixnebulatech. +- **Crafted email messages no longer take seconds to minutes and hundreds of megabytes to parse** ([GHSA-qcc2-4x3v-v4g7](https://github.com/domainaware/parsedmarc/security/advisories/GHSA-qcc2-4x3v-v4g7), affects 11.2.1 and earlier). `parse_report_email()` (mailbox, mbox and file input) and the failure-sample parser `parsedmarc.utils.parse_email()` gave the whole message to mail-parser and Python's `email` package with no limit on blank lines, header lines, header field size, MIME parts or nested multiparts. Parsing builds one `Message` per blank line after a `message/delivery-status` part (512 KiB of blank lines took 6.1 s and 283 MiB of extra memory on 11.2.1 under Python 3.12) and tests every line against every open boundary of nested multiparts (900 levels around 30,000 parts, 0.3 MB, took 10.9 s); a 4 MiB flood of header lines took 1.4 s, and a 1 MB `To:` address group of 250,000 members took 1.9 s, or 44 s through mailsuite's own `parse_email()`, which parsed the group whole. With `n_procs = 1` the rest of the mailbox waited behind such a message, and a process with a memory cap was killed before the message was moved, so it was parsed again on the next run. Both parsers now call `mailsuite.utils.check_message_limits()`, new in mailsuite 2.3.5 ([GHSA-748w-c9w9-79xp](https://github.com/seanthegeek/mailsuite/security/advisories/GHSA-748w-c9w9-79xp)), before mail-parser sees the message. It parses the message with the `email` package's own feed parser under the `compat32` policy, the parser mail-parser and `email.message_from_string()` use, and stops as soon as the message has more than 10,000 parts (the message itself, its MIME parts, the bodies of `message/*` parts and each block of a `message/delivery-status` body), nests them more than 100 levels deep, or makes the parser test a line against an open boundary more than 20,000,000 times. It also stops when the message's header blocks hold more than 100,000 lines in all (folded lines and lines the parser keeps only as defects included). It then rejects a parsed message with a header field longer than 65,536 characters (name, colon and raw value, folded lines included), or whose `From`, `Sender`, `Reply-To`, `To`, `Cc`, `Bcc` and `Delivered-To` headers hold more than 262,144 characters in all, counted in every part; that limit bounds mail-parser's own address parsing (it parses `From`, `Reply-To`, `To`, `Cc`, `Bcc` and `Delivered-To`), which does work for each malformed address item. When a part lacks its start boundary, mail-parser parses the top-level epilogue again, and that text is checked with the same limits. `parse_report_email()` also no longer renders every part it walks as text: it renders a part only where it reads it, because rendering each level of a deep nesting rendered everything inside it again (98 nested multiparts around a 20 MiB leaf took 26.6 s, a chain of 99 `message/rfc822` parts around a 10 MiB leaf 11.3 s, and a chain of 99 `message/feedback-report` parts around a 10 MiB leaf 11.6 s, all within the limits; each now takes under a second). An over-limit email raises `InvalidDMARCReport("Message rejected: Message exceeds ()")`, which the mailbox loop files under `Invalid`; an over-limit failure-report sample raises `InvalidFailureReport("Sample message rejected: …")`. Each crafted message from the report is now rejected in under half a second (the 4 MiB header flood, the slowest, in 0.2 s). **mailsuite 2.3.5 or later is now required.** The floor applies to the base dependency and to the `msgraph`, `gmail` and `all` extras. mailsuite 2.3.5 also removes RFC 5322 group syntax from address header values over 8 KiB before parsing them, caps the address header value its own `parse_email()` reads at 65,536 characters, and fixes a quadratic `url_regex`; all only affect callers of mailsuite's `parse_email()`, which parsedmarc does not use. A message that still takes too long to parse can now be set aside with the new `parse_timeout` option (see Added). **Compatibility:** the limits are fixed; no option changes them. A message with more than 10,000 parts or parts nested more than 100 levels deep is now rejected as invalid instead of being parsed or, when nested past Python's recursion limit, failing with a `ParserError`; in mbox input such a message (the nested message of GHSA-qxwv-2vwj-v828 is one) is now skipped with a warning instead of stopping the run. A `message/rfc822` attached inside a failure report's sample no longer replaces the sample, since a feedback report has one sample ([RFC 6591 §3.1](https://www.rfc-editor.org/rfc/rfc6591#section-3.1)), and only the first `message/feedback-report` part of a message is read, since a feedback report has one ([RFC 6591 §3](https://www.rfc-editor.org/rfc/rfc6591#section-3)). Reported by helixnebulatech. +- **Deeply nested or very wide aggregate report XML no longer exhausts memory** ([GHSA-q7gm-8cj9-94hr](https://github.com/domainaware/parsedmarc/security/advisories/GHSA-q7gm-8cj9-94hr), affects 11.2.1 and earlier). `parse_aggregate_report_xml()` passed the decompressed report, up to the 100 MiB decompression cap, to `xmltodict.parse()` with no limit on nesting depth or element count. xmltodict keeps one stack entry per open element and expat reports missing end tags only at the end of the input, so a gzip attachment of about 30 KB holding 30 MiB of unclosed `` tags needed more than 2 GB of memory (2 MiB of them cost 255 MiB on 11.2.1). The out-of-memory killer ended the process before the message was moved, so every restart parsed it again. A document of millions of sibling elements did the same at a smaller scale, and a document whose first parse failed was parsed again through lxml recovery and a second xmltodict pass. While expat reads the document, before xmltodict adds each element to its tree, parsedmarc now counts nesting depth and nodes (elements plus attributes); a report deeper than 100 levels (`MAX_XML_DEPTH`) or with more than 1,000,000 nodes (`MAX_XML_NODES`) is rejected as `InvalidAggregateReport("Invalid XML: …")` without trying lxml recovery. Before any parser sees the document, a tag longer than 65,536 characters (`MAX_XML_TAG_LENGTH`) is rejected too, because expat and libxml2 build an element's whole attribute list before its attributes can be counted (one element with 900,000 attributes, 9.3 MiB, within the node limit, took 1.1 s and +200 MiB; it is now rejected in under 0.1 s). Because a quoted attribute value may hold a raw `>`, which splits a tag for that scan, a document with more `=` characters than the node limit is rejected first, in one pass (2,000,000 `x=">"` attributes, 23.7 MiB, took 1.4 s and +310 MiB before the node limit rejected them; they are now rejected in under 0.1 s). The decompression cap for a report attachment is lowered from 100 MiB to 32 MiB (`MAX_DECOMPRESSED_REPORT_SIZE`), and an uncompressed report of more than 32 MiB of UTF-8 is rejected the same way, as is a report file of that size, which is no longer tried as a report email: at the node limit a legitimate report is at most about 28 MB, and with that cap a report's text is bounded along with its node count. When the first parse fails and lxml recovery runs, a parser target that builds no tree first counts the document's elements, attributes and namespace declarations against the same node limit (a 22 MiB wide document behind a malformed XML declaration took 5.0 s and 1,532 MiB of extra memory before, 0.57 s and 23 MiB now), and the recovered XML then goes through the same depth and node limits in the second xmltodict pass. A mailbox message that still kills the process before it is filed can now be set aside after two attempts with the new `[mailbox]` `attempts_file` option (see the last entry in this section). **Compatibility:** there is no new option. A real report is fewer than 10 levels deep and the largest sample (909 KB) has 32,019 nodes, so the node limit is a report of about 28 MB of XML; a larger report is now rejected. A report at the size cap needs about 400 MB of memory on the lxml recovery path and about 350 MB otherwise when its text is parsed directly, and about 500 MB and 450 MB through `parse_report_file()`, which also holds the file's bytes, where a report under the old 100 MiB decompression cap could need gigabytes. An aggregate or SMTP TLS report of more than 32 MiB of UTF-8, compressed or not, is now rejected, where 100 MiB was accepted (an uncompressed SMTP TLS report had no cap: 60 MiB of JSON cost +1,505 MiB). `parse_report_file()` no longer tries a file that begins with `<` as SMTP TLS JSON or a report email, nor one that begins with `{` as a report email; its error message is unchanged, and the exception's cause now matches the format the file begins with. It also keeps only each failed attempt's message while it tries the next format, so a file at the size cap on the lxml recovery path takes +500 MiB there, where it took +1,046 MiB. The XML parse step is about 20% slower, and a malformed document that needs lxml recovery is now parsed twice by lxml (once to count, once to build the tree). Reported by helixnebulatech. - **An aggregate report with a huge date range can no longer expand into millions of records or fill an Elasticsearch or OpenSearch cluster with indexes** ([GHSA-p85v-578x-3wcf](https://github.com/domainaware/parsedmarc/security/advisories/GHSA-p85v-578x-3wcf), affects 11.2.1 and earlier). An aggregate report whose `` was longer than `normalize_timespan_threshold_hours` was split into one record per calendar day, with no limit on the number of days. A report under 2 KB declaring a range of millions of days with a large `` expanded one `` into millions of records (200,000 days gave 200,000 records in 0.8 s; the reporter's 2.9 million days exhausted 2 GB of memory). With Elasticsearch or OpenSearch output each of those days created its own dated index of one shard until the cluster reached `cluster.max_shards_per_node` (1,000 by default), after which it refused every new index for every application using it. A report whose date range is negative or longer than 366 days (`MAX_REPORT_SPAN_DAYS`) is now rejected with `InvalidAggregateReport`. A report whose split would produce more than 250,000 records (records times days, `MAX_NORMALIZED_RECORDS`) is not split: its records are kept whole over the report's own date range, and one warning is logged (10,000 records over 366 days, each with a large ``, produced 3,670,000 records in 13.5 s and 1.7 GB of memory before). In Elasticsearch and OpenSearch a single report creates at most 31 dated indexes (`MAX_INDEXES_PER_REPORT`): any further records are saved to the report's first index with their own dates, and one warning is logged for the report. Dated index names still come from each report's own dates, so reports with many different dates still create one index per date; data streams (`use_data_streams`) are affected by neither. **Compatibility:** a genuine report spanning more than 366 days is now rejected; a report too large to split has `timespan_requires_normalization: false` and records with `normalized_timespan: false`; there is no new option. Reported by helixnebulatech. - **One crafted report can no longer make an output fail and stop every run on the same mailbox** ([GHSA-4272-4r8g-6c5h](https://github.com/domainaware/parsedmarc/security/advisories/GHSA-4272-4r8g-6c5h), affects 11.2.1 and earlier). Some reports made a configured output raise an exception that `process_reports()` did not catch. It escaped the mailbox save callback, parsedmarc logged "Mailbox Error" and exited with status 1, and the batch stayed in the mailbox, so every one-shot run failed on the same message, outputs that do not deduplicate received the batch's legitimate reports again on each attempt, and watch mode finally moved the whole batch to `Unsaved`. The triggers were a failure report whose sample has an empty `From:`, `To:` or `Reply-To:` header (a legitimate `To: undisclosed-recipients:;` too) with Elasticsearch or OpenSearch output (`IndexError`); an SMTP TLS report with a field of the wrong type, such as `"policy-string": [1]` with file output (`TypeError` in the CSV writer) or `"start-datetime": 5` with Elasticsearch, OpenSearch, Splunk HEC or PostgreSQL output; and an aggregate report whose policy override `` has no ``, or a `` with an attribute or given twice, with file output (`KeyError`, `TypeError`). Every output destination in `process_reports()` now records any exception as an output error, as the aggregate Elasticsearch and OpenSearch blocks already did (the failure and SMTP TLS Elasticsearch and OpenSearch blocks, every PostgreSQL and Splunk HEC block and the file output lacked that catch-all), so the batch is reported unsaved and `fail_on_output_error` still applies. SMTP TLS reports are now type-checked against RFC 8460 §4.4 and rejected as `InvalidSMTPTLSReport` otherwise: a string for `organization-name`, `report-id`, `policy-domain`, `policy-type`, `result-type` and the optional failure-detail strings, a string or a list of strings for `contact-info`, a list of strings for `policy-string`, an integer or `null` for each session count (`true` and `false` are rejected), and a list of objects for `failure-details`. `start-datetime` and `end-datetime` must convert with the same functions the outputs use and be at most 64 characters long, because dateutil took 12.4 s to fail on a date of 1,000,000 digits. A string holding a lone surrogate (JSON `"\ud800"`), which I-JSON ([RFC 7493 §2.1](https://www.rfc-editor.org/rfc/rfc7493#section-2.1)) forbids, is rejected too: it passed every type check and made printing the results to standard output raise `UnicodeEncodeError`, which `process_reports()` now also records as an output error; a report that cannot be printed to the console (a non-UTF-8 console, a closed pipe) is now recorded as an output error instead of ending the run. A policy override reason's `type` and `comment` are normalised to a string or `null` (an element with an attribute to its text, a repeated element to null), so the CSV writer and the Elasticsearch and OpenSearch saves no longer fail on them. An address header with no address is left out of the Elasticsearch and OpenSearch failure document and of the duplicate query. The Splunk HEC SMTP TLS save raises `SplunkError` on a date it cannot convert, and the PostgreSQL date helper passes a non-string value through unchanged. **Compatibility:** an SMTP TLS report with a field of the wrong type that used to parse is now invalid and goes to `Invalid`; a `policy-string` that is not a list is now rejected (it was silently dropped), while a `null` one is still accepted as absent. A policy override reason without a `type` now has `type: null` and is written as `none` in CSV; one whose `type` has an attribute is stored as its text, and a repeated one as null. Reported by helixnebulatech. - **One crafted report can no longer change the field types of an Elasticsearch or OpenSearch index and get every later report rejected** ([GHSA-qpcg-29vr-jwm3](https://github.com/domainaware/parsedmarc/security/advisories/GHSA-qpcg-29vr-jwm3), affects the Elasticsearch and OpenSearch outputs in 11.2.1 and earlier, data streams included). Indexes and the data-stream index template were created without field mappings, so the cluster typed each field from the first document that held it, with date detection on, and a dated index is named from the report's own begin date. One crafted report could make `report_id` a `date` field (`2026-11-09`), turn `sample.headers.subject` into an object (with a sample header named `Subject.x`), or use up `index.mapping.total_fields.limit` (1,000 fields) with invented sample header names. Every later legitimate report for that index, or for that data stream until its next rollover, was then rejected with a mapping error, retried and moved to `Unsaved`; this was confirmed against Elasticsearch 8.19.7 and OpenSearch 2.19.3. New indexes and data-stream templates are now created with date detection off and the date fields declared as dates (`@timestamp`, `date_range`, `date_begin` and `date_end`; for failure reports `@timestamp`, `arrival_date` and `sample.date`); when an aggregate report is parsed, every XML attribute is dropped and every field the schema types as a string is stored as a string or null, so a report cannot change a field's type (an element with an attribute or a child element, such as `

none

` or `

1

`, became an object that mapped the field as one). In failure documents `sample.headers` is mapped with `dynamic: false` and indexes only 29 headers, those the shipped dashboards reference plus `cc`; every header stays in `_source` except a `From`, `To` or `Reply-To` header that holds no address (see GHSA-4272-4r8g-6c5h above), and a `.` in a header name is stored as `_`. `create_indexes()` and `create_data_streams()` take a new optional `mappings` argument. **Compatibility:** existing dated indexes are not changed; the protection applies to dated indexes created by 11.2.2 or later, and, because parsedmarc puts the data stream template again in every process, to an existing data stream's next backing index after a rollover. On those, sample headers outside the list are no longer searchable. The new "Field mappings" sections of the Elasticsearch and OpenSearch documentation show how to add one through the `@custom` component template (Elasticsearch data streams), an index template (dated indexes) or the put-mapping API (OpenSearch data streams, repeated after each rollover). For string fields, an aggregate report element with text and a stray child element now yields its text, where it yielded an empty string or an object before: `samples/aggregate/invalid_xml.xml`, whose `bad` lxml recovery turns into mixed content, now gives the header-from domain `bad`. A `` or `` with mixed content is still rejected. This narrows, but does not replace, the explicit mappings proposed in [#782](https://github.com/domainaware/parsedmarc/issues/782). Reported by helixnebulatech. +- **A message that kills parsedmarc while it is being parsed is no longer parsed again on every run** (the retry-loop part of [GHSA-qcc2-4x3v-v4g7](https://github.com/domainaware/parsedmarc/security/advisories/GHSA-qcc2-4x3v-v4g7), [GHSA-q7gm-8cj9-94hr](https://github.com/domainaware/parsedmarc/security/advisories/GHSA-q7gm-8cj9-94hr) and [GHSA-4272-4r8g-6c5h](https://github.com/domainaware/parsedmarc/security/advisories/GHSA-4272-4r8g-6c5h), affects 11.2.1 and earlier). A mailbox message is moved out of the reports folder only after it has been parsed, so a message whose parse ended the process (the out-of-memory killer, a container memory limit) stayed in place, and every later one-shot run or service restart parsed it again and died before reaching the reports behind it. The fixes above reject the messages those advisories describe; the new `[mailbox]` `attempts_file` option is the backstop for any other. When it names a file, parsedmarc records each message in it before parsing it and removes the entry as soon as the parse returns a report or rejects the message, so an entry left behind marks a parse that never finished. A message found with two unfinished attempts (`parsedmarc.attempts.MAX_PARSE_ATTEMPTS`) is logged at error level ("Message UID … in … has 2 unfinished parse attempts; the limit is 2") and moved to `Invalid`, or deleted under `delete_invalid`, without being parsed or counted again; its entry is removed once it has left the folder, and a message left in place (a failed move, `test` mode) keeps the same count. With `n_procs` above 1 or `parse_timeout` set, a message that was being parsed when a run died is parsed alone on the next run, after the rest of its batch, so the messages parsed beside it are not blamed; it is parsed in the main process, or, with `parse_timeout` set (see Added), in a worker process of its own, so the timeout still applies to it. The entry is removed before the batch is saved, so a failed save still follows `max_unsaved_retries` and `Unsaved` and is never counted as a crash. A message is identified by the reports folder, its id and a hash of its first 64 KiB, because mailsuite's IMAP backend does not expose UIDVALIDITY, so a new message that reuses an old UID starts at zero. The file is JSON, written atomically and readable by its owner only, and entries older than 30 days are dropped; a file of another shape is replaced with a warning, and a file that cannot be written logs an error and turns the protection off for the rest of the batch without stopping the run. `PARSEDMARC_MAILBOX_ATTEMPTS_FILE` sets it from the environment (it names the file directly, like `PARSEDMARC_GENERAL_LOG_FILE`, so `PARSEDMARC_MAILBOX_ATTEMPTS_FILE_FILE` is its Docker-secret form). `get_dmarc_reports_from_mailbox()` and `watch_inbox()` take a new `attempts_file` argument. The systemd and Docker Compose examples in the documentation now keep the file in a state directory and a named volume. **Compatibility:** the option is unset by default, which keeps the previous behaviour; there is no option for the number of attempts. + +### Added + +- **`[general] parse_timeout` stops a report file or message that takes too long to parse** ([GHSA-qcc2-4x3v-v4g7](https://github.com/domainaware/parsedmarc/security/advisories/GHSA-qcc2-4x3v-v4g7)). The parse limits above bound every input known to take long, but a message they do not cover could still hold up the rest of the run. With `parse_timeout` set to a number of seconds (`300` is a reasonable value), a parse that runs longer is stopped and the input is treated as invalid: a report file is logged as failed and, with `archive_directory`, moved to `Invalid`; an mbox message is skipped with a warning; a mailbox message is moved to the `Invalid` archive folder, or deleted with `delete_invalid`. A parse can only be stopped by ending the process that runs it, so with a timeout set parsing always runs in worker processes, even with `n_procs = 1`; when one times out, every worker process is stopped and restarted, and the other inputs that were still being parsed start again. parsedmarc checks the time only while it waits for a parse result, so a parse is stopped within one second of parsedmarc next waiting for a result after its time is up, and can run on past the timeout while parsedmarc is busy between results (moving messages, for example); its clock starts only when a worker begins it, not while it waits for one. With a timeout set, workers hand each result back through a file in a private temporary directory (under `TMPDIR`), so that stopping a worker while it returns a large result cannot leave the process pool, or the interpreter at exit, waiting forever; that directory must be writable. `get_dmarc_reports_from_mbox()`, `get_dmarc_reports_from_mailbox()` and `watch_inbox()` take a matching `parse_timeout` keyword argument, and `parsedmarc.parallel.parallel_map()` takes `parse_timeout` and `timeout_result`; a timed-out message is a `ParseTimeoutError`, a subclass of `InvalidDMARCReport`. The setting is reloaded on `SIGHUP`. **Compatibility:** the default, `0`, means no limit, so nothing changes unless it is set. ### Bug fixes - **A failure report's RFC 6591 feedback report and sample can no longer be replaced by legacy report text.** `parse_report_email()` also reads the legacy text format, a `text/plain` part beginning "A message claiming to be from you has failed" that carries the source IP and the sample, and a later such part replaced the `message/feedback-report` part and the sample already read. A `text/plain` part inside the sample, which is the spoofed message's own text, could therefore set the report's Source-IP and sample. Once a `message/feedback-report` part is read, legacy text parts are ignored, and the RFC 6591 part and its sample win over a legacy part that came before it; a legacy part followed by a `message/feedback-report` part with no sample after it (RFC 6591 §3.1 puts the sample after the report part) is now rejected as `InvalidDMARCReport`, where a mix of the two was returned. Parts inside the sample, which are the reported message's own attachments, are no longer read as reports either: an SVG, zipped HTML or `application/json` attachment there made the whole email invalid, and a gzipped aggregate report or SMTP TLS JSON there was returned in place of the failure report. This holds for a second sample part too, which is not read as the sample; a report attached beside the sample, outside it, is still read. - **SMTP TLS reports keep their MX host patterns** ([#942](https://github.com/domainaware/parsedmarc/issues/942)). RFC 8460 §4.4 keys a policy's MX host patterns `mx-host`; `mx-host-pattern` is the name of the value's type ("a JSON array of strings"), and the example in Appendix B gives a plain string. parsedmarc read only `mx-host-pattern`, so every RFC-conformant report lost the field. `mx-host` is now read first, as a list of strings or a plain string (which becomes a one-element list); `mx-host-pattern` is kept as a fallback, and a plain string there is now kept too. The output key `mx_host_patterns` and its PostgreSQL `TEXT[]` column are unchanged, and `samples/smtp_tls/rfc8460.json` now yields `["*.mail.company-y.example"]`. Reported by kowax. +- **A failure report's duplicate check no longer lets a search error escape the Elasticsearch and OpenSearch outputs.** `save_failure_report_to_elasticsearch()` and `save_failure_report_to_opensearch()` called the duplicate-check search without the handler the aggregate and SMTP TLS saves have, so a connection or query failure raised the search library's own exception. It is now an `ElasticsearchError` or `OpenSearchError`, which `process_reports()` records as an output error. +- **A date string of hundreds of thousands of digits no longer takes seconds to fail.** `human_timestamp_to_datetime()` had no length limit, so a failure report's `Arrival-Date`, a message's or failure sample's `Date` header, or any other date it converted went to dateutil whole (a digit string of 262,144 characters took 0.87 s to fail and one of 1,000,000 characters 12.4 s). Only SMTP TLS dates had a limit (64 characters). The function now raises `ValueError` for a string longer than 128 characters once comments are removed (`parsedmarc.utils.MAX_TIMESTAMP_LENGTH`, above any RFC 5322 date; a comment has no length limit and is not counted), and each caller turns that, and any other date that does not convert, into the matching error: `InvalidFailureReport("Invalid Arrival-Date: ...")` for a failure report, `InvalidDMARCReport("Invalid Date header: ...")` in `parse_report_email()`, and `InvalidFailureReport` from the Elasticsearch and OpenSearch failure report saves for the sample's `Date`. An unparseable `Arrival-Date` was reported as "Unexpected error" and an unparseable `Date` header as a plain `ParserError`. +- **A failure sample header with an empty name is left out of the Elasticsearch and OpenSearch failure document.** The save lower-cases each sample header name and replaces `.` with `_`; a header whose name was empty after that became a field with an empty name, which the cluster rejects. The header is now skipped and the sample's other headers are saved. +- **A parsing worker process that dies, or a Ctrl-C, no longer leaves the run hanging or ends it in a traceback.** With `n_procs` above 1 (or `parse_timeout` set) on a Python whose default start method is `fork` (Linux before Python 3.14), each worker inherited the SIGTERM and SIGINT handlers the CLI installs, which only note the signal. When a worker died, the process pool stopped the others with SIGTERM and waited for them, and they ignored it, so the run hung instead of failing; under the other start methods the pool's `BrokenProcessPool` ended the run in a traceback. Workers now take the default action on SIGTERM and ignore SIGINT, which the parent process handles: a Ctrl-C lets the batch in progress finish, as it does with one process. A worker that dies (the out-of-memory killer, a crash) now ends the batch with a logged error: `parallel_map()` raises `ParserError("A parsing worker process died ...")` after stopping the other workers. A one-shot run then exits with status 1, from report files, mbox files and mailboxes alike, after saving the reports parsed from report files and mbox files before the error; for a mailbox, earlier batches are saved and the batch in progress stays in the mailbox; in watch mode the IMAP and Maildir watchers log it as a warning and check the mailbox again, and the Microsoft Graph and Gmail watchers exit with status 1. A report file or mbox error (a worker that died, a missing mbox) no longer discards the reports already parsed from earlier files, which with `archive_directory` set had already been moved out of the input. Without `parse_timeout`, a library caller that stops reading `parallel_map()` early, or is interrupted, no longer waits for the jobs in progress: the workers are stopped. The systemd example in the documentation now sets `KillMode=mixed`, so stopping the service signals only the main process and lets the batch finish within `TimeoutStopSec`. ## 11.2.1 diff --git a/docs/source/usage.md b/docs/source/usage.md index c7f2b718..a8836535 100644 --- a/docs/source/usage.md +++ b/docs/source/usage.md @@ -247,6 +247,34 @@ The full set of configuration options is: cache. ::: + - `parse_timeout` - float: Stop parsing a report file or message + after this many seconds, and treat it as invalid: a report file + is logged as failed (and moved to `Invalid` under + `archive_directory`), an mbox message is skipped with a warning, + and a mailbox message is moved to the `Invalid` archive folder + (or deleted with `delete_invalid`). `0` means no limit + (Default: `0`, suggested: `300`) + + :::{note} + With a timeout set, parsing always runs in worker processes, even + with `n_procs = 1`, because a parse can only be stopped by ending + the process that runs it. When a parse times out, every worker + process is stopped and new ones are started, and the other + messages or files that were still being parsed start again from + the beginning. parsedmarc checks the time only while it waits for + a parse result, so a parse is stopped within one second of + parsedmarc next waiting for a result after its time is up; while + parsedmarc is busy between results (moving messages, for example) + a parse can run on past the timeout. Choose a value well above the + time your largest legitimate reports take, including DNS lookups, + each of which can take up to `dns_timeout` seconds per try. With a + timeout set, the worker processes hand each parsed report back + through a file in a directory readable only by the parsedmarc user, + inside the temporary directory (`TMPDIR`), which must therefore be + writable; the files are removed as they are read, and their + directory once the batch has been parsed or the workers stopped. + ::: + - `mailbox` - `reports_folder` - str: The mailbox folder (or label for Gmail) where the incoming reports can be found @@ -298,6 +326,16 @@ The full set of configuration options is: runs. See [Mailbox messages are only archived once the reports are saved](#mailbox-messages-are-only-archived-once-the-reports-are-saved) below. + - `attempts_file` - str: Path to a JSON file in which parsedmarc + counts the messages whose parsing never finished because the + process died, so that a message that keeps killing parsedmarc is + moved to the `Invalid` archive subfolder (or deleted, per + `delete_invalid`) after two such attempts instead of being parsed + on every run. The directory must be writable by the user running + parsedmarc; the file is created on first use. Unset by default + (no record is kept). See + [Messages that crash parsedmarc are not retried forever](#messages-that-crash-parsedmarc-are-not-retried-forever) + below. - `since` - str: Search for messages since a certain time. (Examples: `5m|3h|2d|1w`) Acceptable units - {"m":"minutes", "h":"hours", "d":"days", "w":"weeks"}. Defaults to `1d` if an incorrect value is provided. @@ -1150,14 +1188,17 @@ from `Archive/Unsaved` back into the reports folder, or run parsedmarc once with `reports_folder = Archive/Unsaved`. :::{note} -The failure counts live in memory, so they are counted per parsedmarc -process. In watch mode — a long-running process that checks the mailbox -repeatedly — the cap works as described across checks. A one-shot run -(`cron`, `systemd` timers) attempts each message exactly once and then -exits, so its counts start over every time and the default cap is never -reached: messages simply keep being retried on every run, which is the -safe direction. Set `max_unsaved_retries = 0` if you want one-shot runs to -move unsavable messages to `Unsaved` immediately instead. +The failed-save counts live in memory, so they are counted per +parsedmarc process. In watch mode — a long-running process that checks +the mailbox repeatedly — the cap works as described across checks. A +one-shot run (`cron`, `systemd` timers) attempts each message exactly once +and then exits, so its counts start over every time and the default cap is +never reached: messages simply keep being retried on every run, which is +the safe direction. Set `max_unsaved_retries = 0` if you want one-shot +runs to move unsavable messages to `Unsaved` immediately instead. A +message that crashes parsedmarc while it is being parsed is a different +case, counted on disk by `attempts_file`; see +[Messages that crash parsedmarc are not retried forever](#messages-that-crash-parsedmarc-are-not-retried-forever). ::: :::{warning} @@ -1195,6 +1236,77 @@ reports folder until it is processed by a run with a wider (or no) `since` window. ::: +### Messages that crash parsedmarc are not retried forever + +A message is only moved out of the reports folder after it has been +parsed. If parsing a message kills the parsedmarc process — the +out-of-memory killer, a container memory limit, a crash in a library — +the message stays where it is, and every later run, or every restart of +the service, fetches it again and dies on it again, so the reports behind +it in the mailbox are never processed. parsedmarc rejects the message shapes known to +do this, but cannot rule out new ones. + +Set `[mailbox]` `attempts_file` to a path to guard against that loop: + +```ini +[mailbox] +attempts_file = /var/lib/parsedmarc/attempts.json +``` + +parsedmarc then writes an entry to that file before it parses each +message, and removes the entry as soon as the parse returns, whether it +found a report or rejected the message as invalid. An entry that is still +there on a later run belongs to a message whose parse never finished. Once +a message has two such unfinished attempts, the next run logs an error +naming the folder, the message and the count, and moves the message to +`/Invalid` without parsing it (or deletes it, if +`delete_invalid` is set). Its entry is removed once the message has been +moved, so moving it back into the reports folder tries it again from the +start; if the move fails, the entry stays and the next run tries the move +again. A set-aside message whose move failed, or one left in place in +`test` mode, is not recorded again, so its entry is not refreshed and is +dropped after 30 days, after which the message is parsed up to twice more +before it is set aside again. Two attempts are allowed +so that one crash for an unrelated reason (a reboot, a deployment) never +sets a message aside. With `n_procs` above 1, or with `parse_timeout` set +(which parses in worker processes even with `n_procs = 1`), several +messages are parsed at once, so every message that was being parsed or +waiting for a worker when a run died has an entry; on the next run each of +them is parsed on its own after the rest of its batch, so a second crash +counts against the one message that caused it. It is parsed in the main +process, or, when `parse_timeout` is set, in a worker process of its own, +so the timeout still applies to it. If a worker process dies while it +parses (the out-of-memory killer can end a worker without ending +parsedmarc), the batch ends with a logged error. A one-shot run saves the +reports parsed from report files and mbox files before it and exits with +status 1; for a mailbox, earlier batches are saved and the batch in +progress stays in the mailbox. In watch mode the IMAP and Maildir watchers +log it as a warning and check the mailbox again, so the process keeps +running, while the Microsoft Graph and Gmail watchers exit with status 1. +Either way the entries of the messages that were being parsed or waiting +for a worker stay in the file, so the next run or check parses each of +them on its own in the same way. + +This count is separate from the in-memory failed-save counts of +`max_unsaved_retries` above: an entry is removed when the parse +returns, before the reports are saved, so a message whose batch could not +be saved is retried and moved to `Unsaved` as described above, never to +`Invalid`. A message is identified by the reports folder, its id and a +hash of its beginning, so a new message that reuses an old id starts with +no attempts. + +Use one file per configuration (per mailbox and reports folder): two +parsedmarc processes writing one file overwrite each other's entries. The +file is written atomically, readable by its owner only, and entries older +than 30 days are dropped. A file that is not a valid attempts file is +logged as a warning and replaced. If the file cannot be written, an error +is logged and the protection is off for the rest of that batch; reports are +still processed. If the write that removes an entry after a successful +parse is the one that fails, the entry stays (and the protection is off +for the rest of that batch), so a healthy message can be set aside as +invalid after two such failures; the write error is logged each time. In +`test` mode messages are recorded and set aside as usual but never moved. + ## Environment variable configuration Any configuration option can be set via environment variables using the @@ -1257,11 +1369,24 @@ services: PARSEDMARC_IMAP_USER: dmarc@example.com PARSEDMARC_IMAP_PASSWORD: ${IMAP_PASSWORD} PARSEDMARC_MAILBOX_WATCH: "true" + PARSEDMARC_MAILBOX_ATTEMPTS_FILE: /home/parsedmarc/attempts.json PARSEDMARC_ELASTICSEARCH_HOSTS: http://elasticsearch:9200 PARSEDMARC_GENERAL_SAVE_AGGREGATE: "true" PARSEDMARC_GENERAL_SAVE_FAILURE: "true" + volumes: + - parsedmarc-state:/home/parsedmarc + +volumes: + parsedmarc-state: ``` +The `parsedmarc-state` volume keeps the +[attempts file](#messages-that-crash-parsedmarc-are-not-retried-forever) +when the container is recreated, as it is on an image upgrade. It is +mounted on the home directory of the image's `parsedmarc` user because +Docker gives a new named volume the owner of the directory it is mounted +on, and that directory is one the user can write. + ### Docker secrets (`_FILE` suffix) Any `PARSEDMARC_{SECTION}_{KEY}` environment variable can also be supplied @@ -1300,7 +1425,8 @@ services: Note that a small set of config keys whose own names already end in `_file` (`[general] log_file`, `[msgraph] token_file`, -`[gmail_api] credentials_file`, `[gmail_api] token_file`) keep their +`[gmail_api] credentials_file`, `[gmail_api] token_file`, +`[mailbox] attempts_file`) keep their pre-existing meaning when set via `PARSEDMARC_..._FILE` — that env var is the path itself, not a wrapper around a file containing the path. To pass *those* paths via a Docker secret, double up the suffix @@ -1372,9 +1498,10 @@ A few things to keep in mind: (IP address info, seen aggregate report IDs, and the reverse DNS map). Omitting `config=` falls back to the process-wide caches shared by every call that doesn't pass one. -- `keep_alive` and `n_procs` are not part of `ParserConfig` — they control - process/worker orchestration rather than parsing or enrichment behavior, - so they are always passed as separate keyword arguments. +- `keep_alive`, `n_procs`, `parse_timeout` and `attempts_file` are not part + of `ParserConfig` — they control process/worker or mailbox orchestration + rather than parsing or enrichment behavior, so they are always passed as + separate keyword arguments. ## Performance tuning @@ -1392,6 +1519,9 @@ imports more predictable: trade-off is memory and DNS load: at most roughly `2 * n_procs` messages are held in flight at once, each worker process keeps its own DNS/GeoIP cache, and DNS query volume can multiply by up to `n_procs`. +- Set `parse_timeout` (for example to `300`) so that one message or file that + takes far too long to parse is set aside as invalid instead of holding up + the rest of the run. - Use `mailbox.since` to process reports in smaller time windows such as `1d`, `7d`, or another interval that fits the backlog. This makes it easier to catch up incrementally instead of loading an entire mailbox history in one run. @@ -1466,9 +1596,11 @@ After=network.target network-online.target elasticsearch.service ExecStart=/opt/parsedmarc/venv/bin/parsedmarc -c /etc/parsedmarc.ini ExecReload=/bin/kill -HUP $MAINPID KillSignal=SIGTERM +KillMode=mixed TimeoutStopSec=60 User=parsedmarc Group=parsedmarc +StateDirectory=parsedmarc Restart=always RestartSec=5m @@ -1476,6 +1608,23 @@ RestartSec=5m WantedBy=multi-user.target ``` +`KillMode=mixed` sends the stop signal to the main parsedmarc process +only, so the batch in progress can finish before it exits, within +`TimeoutStopSec`, after which systemd kills the whole group; the default +control-group mode would also stop its parsing worker processes at once +and abandon the batch. + +`StateDirectory=parsedmarc` makes systemd create `/var/lib/parsedmarc`, +owned by the `parsedmarc` user, before the service starts. Point the +[attempts file](#messages-that-crash-parsedmarc-are-not-retried-forever) +there in `/etc/parsedmarc.ini`, so a message that kills the service is +not parsed again on every restart: + +```ini +[mailbox] +attempts_file = /var/lib/parsedmarc/attempts.json +``` + Then, enable the service ```bash @@ -1533,7 +1682,7 @@ for that batch have completed. The following settings are reloaded: - DNS and GeoIP settings (`nameservers`, `dns_timeout`, `ip_db_path`, `ipinfo_url`, `offline`, etc.) - Processing flags (`strip_attachment_payloads`, `batch_size`, - `check_timeout`, etc.) + `check_timeout`, `parse_timeout`, `attempts_file`, etc.) - Log level (`debug`, `verbose`, `warnings`, `silent`) Mailbox connection settings (IMAP host/credentials, Microsoft Graph, diff --git a/parsedmarc/__init__.py b/parsedmarc/__init__.py index c4132be6..ef59c3e1 100644 --- a/parsedmarc/__init__.py +++ b/parsedmarc/__init__.py @@ -42,6 +42,7 @@ from mailsuite.smtp import send_email from mailsuite.utils import MessageLimitExceeded, check_message_limits from tqdm import tqdm +from parsedmarc.attempts import MAX_PARSE_ATTEMPTS, AttemptStore, attempt_key from parsedmarc.config import ( IP_ADDRESS_CACHE, REVERSE_DNS_MAP, @@ -198,6 +199,18 @@ class InvalidSMTPTLSReport(ParserError): """Raised when an invalid SMTP TLS report is encountered""" +class ParseTimeoutError(InvalidDMARCReport): + """Returned in place of a report whose parsing exceeded ``parse_timeout`` + + An ``InvalidDMARCReport``, so a timed-out message is handled like any + other message that cannot be parsed: the mbox loop warns and continues, + and the mailbox loop moves it to the ``Invalid`` archive folder. It is + the value for every timed-out input, including one that would have + been an SMTP TLS report or not a report at all, since a parse that was + stopped cannot tell what the input held. + """ + + class InvalidAggregateReport(InvalidDMARCReport): """Raised when an invalid DMARC aggregate report is encountered""" @@ -2407,9 +2420,14 @@ def parse_failure_report( if parsed_report["delivery_result"] not in delivery_results: parsed_report["delivery_result"] = "other" - arrival_utc = human_timestamp_to_datetime( - parsed_report["arrival_date"], to_utc=True - ) + try: + arrival_utc = human_timestamp_to_datetime( + parsed_report["arrival_date"], to_utc=True + ) + except (ValueError, OverflowError) as error: + raise InvalidFailureReport( + f"Invalid Arrival-Date: {sanitize_for_log(str(error))}" + ) from error arrival_utc = arrival_utc.strftime("%Y-%m-%d %H:%M:%S") parsed_report["arrival_date_utc"] = arrival_utc @@ -2815,12 +2833,19 @@ def parse_report_email( msg = mailparser.parse_from_string(input_str) msg_headers = json.loads(msg.headers_json) if "Date" in msg_headers: - msg_date = human_timestamp_to_datetime(msg_headers["Date"]) + try: + msg_date = human_timestamp_to_datetime(msg_headers["Date"]) + except (ValueError, OverflowError) as e: + raise InvalidDMARCReport( + f"Invalid Date header: {sanitize_for_log(str(e))}" + ) from e date = email.utils.format_datetime(msg_date) msg = email.message_from_string(input_str) except MessageLimitExceeded as e: raise InvalidDMARCReport(f"Message rejected: {e}") from e + except InvalidDMARCReport: + raise except Exception as e: raise ParserError(e.__str__() + _exc_origin(e)) from e subject_text = "None" @@ -3345,10 +3370,11 @@ def _dispose_invalid_message( message_id: int | str, delete: bool, invalid_reports_folder: str, -) -> None: +) -> bool: """Delete or move an unparseable message, per ``delete``. Callers pass their effective ``delete_invalid`` value as ``delete``. + Returns whether the message left the reports folder. Shared, unmodified, by the sequential and parallel branches of ``get_dmarc_reports_from_mailbox`` so both dispose of invalid messages @@ -3385,6 +3411,44 @@ def _dispose_invalid_message( f"Mailbox error: Error {action} invalid message UID {message_id}: " f"{type(e).__name__}: {e}" ) + return False + return True + + +def _record_parse_attempt( + attempt_store: AttemptStore, + key: str, + message_id: int | str, + reports_folder: str, + delete_invalid: bool, + invalid_reports_folder: str, + test: bool, +) -> bool: + """Record that a message is about to be parsed; return ``True`` when it + must be set aside instead. + + A message whose earlier parse attempts never finished + ``MAX_PARSE_ATTEMPTS`` times is taken to be what killed those runs: the + error is logged here, and the caller disposes of the message as invalid + without parsing it (or, under ``test``, leaves it in place). Such a + message is not recorded again, so a message left in place by a failed + move or by ``test`` keeps the same count on every later run. + """ + count = attempt_store.count(key) + if not attempt_store.enabled or count < MAX_PARSE_ATTEMPTS: + attempt_store.record(key) + return False + if test: + action = "Leaving it in place without parsing it (test mode)" + elif delete_invalid: + action = "Deleting it without parsing it" + else: + action = f"Moving it to {invalid_reports_folder} without parsing it" + logger.error( + f"Message UID {message_id} in {reports_folder} has {count} unfinished " + f"parse attempts; the limit is {MAX_PARSE_ATTEMPTS}. {action}" + ) + return True def get_dmarc_reports_from_mbox( @@ -3401,6 +3465,7 @@ def get_dmarc_reports_from_mbox( offline: bool = False, normalize_timespan_threshold_hours: float = 24.0, n_procs: int = 1, + parse_timeout: float = 0.0, config: ParserConfig | None = None, ) -> ParsingResults: """Parses a mailbox in mbox format containing e-mails with attached @@ -3425,6 +3490,13 @@ def get_dmarc_reports_from_mbox( parallel. Message reading, deduplication, and result assembly stay in the calling process; only parsing is parallelized. Not part of ``config``; always applies. + parse_timeout (float): Stop parsing a message after this many + seconds and skip it with a warning, as an invalid message + (``0``, the default, means no limit). When set, messages are + parsed in worker processes even with ``n_procs`` 1. A negative + or non-finite value raises ``ValueError``. See + ``parsedmarc.parallel.parallel_map()``. Not part of + ``config``; always applies. config (ParserConfig): a single object carrying all parsing and enrichment options plus the caches; when provided, the individual option keyword arguments listed above are ignored in @@ -3456,8 +3528,12 @@ def get_dmarc_reports_from_mbox( total_messages = len(message_keys) logger.debug(f"Found {total_messages} messages in {input_}") - if n_procs > 1 and total_messages > 1: - from parsedmarc.parallel import _parse_report_email_job, parallel_map + if parse_timeout or (n_procs > 1 and total_messages > 1): + from parsedmarc.parallel import ( + _email_timeout_result, + _parse_report_email_job, + parallel_map, + ) func = functools.partial(_parse_report_email_job, config=cfg) @@ -3468,7 +3544,13 @@ def get_dmarc_reports_from_mbox( yield mbox.get_bytes(message_key) for result in tqdm( - parallel_map(func, _jobs(), n_procs), + parallel_map( + func, + _jobs(), + n_procs, + parse_timeout=parse_timeout, + timeout_result=_email_timeout_result, + ), total=total_messages, disable=None, ): @@ -3595,8 +3677,10 @@ def get_dmarc_reports_from_mailbox( create_folders: bool = True, normalize_timespan_threshold_hours: float = 24.0, n_procs: int = 1, + parse_timeout: float = 0.0, save_callback: Callable[[ParsingResults], bool | None] | None = None, max_unsaved_retries: int = 2, + attempts_file: str | None = None, config: ParserConfig | None = None, ) -> ParsingResults: """ @@ -3650,6 +3734,15 @@ def get_dmarc_reports_from_mailbox( happens after the parsing phase completes, rather than interleaved message-by-message as it is when ``n_procs`` is 1. Not part of ``config``; always applies. + parse_timeout (float): Stop parsing a message after this many + seconds and move it to the ``Invalid`` archive subfolder, as an + invalid message (``0``, the default, means no limit). When set, + messages are parsed in worker processes even with ``n_procs`` + 1, so disposition of invalid messages happens after the parsing + phase as it does with ``n_procs > 1``. A negative or non-finite + value raises ``ValueError``. See + ``parsedmarc.parallel.parallel_map()``. Not part of + ``config``; always applies. save_callback: An optional callable invoked once per fetched batch with a ``ParsingResults`` dict holding only that batch's newly parsed reports, after parsing but before any of the batch's @@ -3694,6 +3787,22 @@ def get_dmarc_reports_from_mailbox( checks), not across separate one-shot processes, each of which starts a message's count over. Mailbox orchestration, so like ``batch_size`` it is not part of ``config``. + attempts_file (str | None): A JSON file in which to count, per + message, the parse attempts that started but never finished, + because the process died while parsing (the out-of-memory + killer, a container memory cap). An attempt is recorded before + a message is parsed and cleared as soon as the parse returns a + report or raises ``ParserError``, so a failed save is not + counted. A message that has died ``MAX_PARSE_ATTEMPTS`` (2) + times is logged at error level and disposed of as invalid + (moved to ``Invalid``, or deleted under ``delete_invalid``) + without being parsed again. With ``n_procs > 1`` or + ``parse_timeout`` set, a message that was being parsed when an + earlier run died is parsed on its own after the others (in this process, or with + ``parse_timeout`` in a worker pool of its own, so the timeout + still applies), so the messages parsed beside it are not blamed + for it. ``None`` (the default) keeps + no record. Mailbox orchestration, not part of ``config``. config (ParserConfig): a single object carrying all parsing and enrichment options plus the caches; when provided, it replaces the individual parsing and enrichment option keyword arguments @@ -3702,8 +3811,9 @@ def get_dmarc_reports_from_mailbox( ignored. The remaining keyword arguments control mailbox handling and orchestration rather than parsing (the folder names, the ``delete`` options, ``test``, ``since``, - ``batch_size``, ``save_callback``, ``max_unsaved_retries``); - they are not part of ``config`` and always apply. + ``batch_size``, ``save_callback``, ``max_unsaved_retries``, + ``attempts_file``); they are not part of ``config`` and always + apply. Returns: dict: Lists of ``aggregate_reports``, ``failure_reports``, and ``smtp_tls_reports`` @@ -3727,9 +3837,15 @@ def get_dmarc_reports_from_mailbox( if max_unsaved_retries < 0: raise ValueError("max_unsaved_retries must be >= 0") + from parsedmarc.parallel import _check_parse_timeout + + _check_parse_timeout(parse_timeout) + if connection is None: raise ValueError("Must supply a connection") + attempt_store = AttemptStore(attempts_file) if attempts_file else None + cfg = _resolve_config( config, offline=offline, @@ -3842,8 +3958,72 @@ def get_dmarc_reports_from_mailbox( logger.debug(f"Processing {message_limit} messages") - if n_procs > 1 and message_limit > 1: - from parsedmarc.parallel import _parse_report_email_job, parallel_map + def _parse_finished(key: str | None) -> None: + # A parse that returned a result or raised ParserError did not + # crash the process, so its attempt is cleared before anything that + # can fail for other reasons (the save, the move) runs. + if attempt_store is not None and key is not None: + attempt_store.clear(key) + + def _parse_in_process( + message_id: int | str, msg_content: str | ParserError + ) -> None: + key: str | None = None + try: + if isinstance(msg_content, ParserError): + raise msg_content + if attempt_store is not None: + key = attempt_key(reports_folder, message_id, msg_content) + if _record_parse_attempt( + attempt_store, + key, + message_id, + reports_folder, + delete_invalid, + invalid_reports_folder, + test, + ): + # The entry is kept until the message has left the + # folder, so a failed move is retried on the next run. + if not test and _dispose_invalid_message( + connection, message_id, delete_invalid, invalid_reports_folder + ): + attempt_store.clear(key) + return + parsed_email = parse_report_email( + msg_content, + config=cfg, + keep_alive=connection.keepalive, + ) + _parse_finished(key) + report_type = _classify_parsed_email( + parsed_email, + batch_aggregate_reports, + batch_failure_reports, + batch_smtp_tls_reports, + seen_aggregate_report_ids=cfg.seen_aggregate_report_ids, + pending_aggregate_keys=pending_aggregate_keys, + ) + if report_type == "aggregate": + aggregate_report_msg_uids.append(message_id) + elif report_type == "failure": + failure_report_msg_uids.append(message_id) + elif report_type == "smtp_tls": + smtp_tls_msg_uids.append(message_id) + except ParserError as error: + _parse_finished(key) + logger.warning(error.__str__()) + if not test: + _dispose_invalid_message( + connection, message_id, delete_invalid, invalid_reports_folder + ) + + if parse_timeout or (n_procs > 1 and message_limit > 1): + from parsedmarc.parallel import ( + _email_timeout_result, + _parse_report_email_job, + parallel_map, + ) # The config's caches (ip_address_cache, seen_aggregate_report_ids, # reverse_dns_map) never cross the process boundary -- @@ -3858,9 +4038,16 @@ def get_dmarc_reports_from_mailbox( # parallel_map yields results in submission order, so the oldest # queued id always belongs to the next yielded result; popping as # results arrive keeps this queue no larger than the in-flight - # submission window. - fetched_ids: deque[int | str] = deque() - invalid_msg_ids: list[int | str] = [] + # submission window. Each id travels with its attempts-file key + # (None when there is no attempts file, or no attempt to clear). + fetched_ids: deque[tuple[int | str, str | None]] = deque() + invalid_msg_ids: list[tuple[int | str, str | None]] = [] + # Messages that were being parsed when an earlier run died. That + # run had up to a whole submission window in flight (with n_procs + # above 1, or with parse_timeout set, which takes this path even + # with one process), so all of them are suspects; parsing each alone, after the others, lets the next + # crash count against the one message that caused it. + suspects: list[tuple[int | str, str]] = [] def _jobs(): for i in range(message_limit): @@ -3875,18 +4062,43 @@ def get_dmarc_reports_from_mailbox( # Never submitted, so never yielded and never queued in # fetched_ids; the post-loop disposal handles it. logger.warning(str(msg_content)) - invalid_msg_ids.append(message_id) + invalid_msg_ids.append((message_id, None)) continue - fetched_ids.append(message_id) + key: str | None = None + if attempt_store is not None: + key = attempt_key(reports_folder, message_id, msg_content) + if 0 < attempt_store.count(key) < MAX_PARSE_ATTEMPTS: + logger.warning( + f"Message UID {message_id} in {reports_folder} " + "was being parsed when parsedmarc last stopped " + "without finishing; parsing it on its own after " + "the rest of the batch" + ) + suspects.append((message_id, msg_content)) + continue + if _record_parse_attempt( + attempt_store, + key, + message_id, + reports_folder, + delete_invalid, + invalid_reports_folder, + test, + ): + invalid_msg_ids.append((message_id, key)) + continue + fetched_ids.append((message_id, key)) yield msg_content - for result in parallel_map( - func, _jobs(), n_procs, heartbeat=connection.keepalive - ): - message_id = fetched_ids.popleft() + def _take_result( + message_id: int | str, + key: str | None, + result: ParsedReport | ParserError, + ) -> None: + _parse_finished(key) if isinstance(result, ParserError): logger.warning(str(result)) - invalid_msg_ids.append(message_id) + invalid_msg_ids.append((message_id, None)) else: report_type = _classify_parsed_email( result, @@ -3903,14 +4115,49 @@ def get_dmarc_reports_from_mailbox( elif report_type == "smtp_tls": smtp_tls_msg_uids.append(message_id) + for result in parallel_map( + func, + _jobs(), + n_procs, + heartbeat=connection.keepalive, + parse_timeout=parse_timeout, + timeout_result=_email_timeout_result, + ): + message_id, key = fetched_ids.popleft() + _take_result(message_id, key, result) + + for message_id, msg_content in suspects: + if not parse_timeout or attempt_store is None: + _parse_in_process(message_id, msg_content) + continue + # Only a worker process can be stopped when the timeout expires, + # so each suspect gets a pool of its own: the timeout still + # bounds it, and a crash is still charged to it alone. A suspect + # is below MAX_PARSE_ATTEMPTS, so this record cannot reach the + # cap. + key = attempt_key(reports_folder, message_id, msg_content) + attempt_store.record(key) + for result in parallel_map( + func, + [msg_content], + 1, + heartbeat=connection.keepalive, + parse_timeout=parse_timeout, + timeout_result=_email_timeout_result, + ): + _take_result(message_id, key, result) + if not test: - for invalid_message_id in invalid_msg_ids: - _dispose_invalid_message( + for invalid_message_id, key in invalid_msg_ids: + # A set-aside message's entry is cleared only once it has + # left the folder, as in _parse_in_process. + if _dispose_invalid_message( connection, invalid_message_id, delete_invalid, invalid_reports_folder, - ) + ): + _parse_finished(key) else: for i in range(message_limit): msg_uid = messages[i] @@ -3918,34 +4165,7 @@ def get_dmarc_reports_from_mailbox( f"Processing message {i + 1} of {message_limit}: UID {msg_uid}" ) message_id, msg_content = _fetch_mailbox_message(connection, msg_uid, test) - try: - if isinstance(msg_content, ParserError): - raise msg_content - parsed_email = parse_report_email( - msg_content, - config=cfg, - keep_alive=connection.keepalive, - ) - report_type = _classify_parsed_email( - parsed_email, - batch_aggregate_reports, - batch_failure_reports, - batch_smtp_tls_reports, - seen_aggregate_report_ids=cfg.seen_aggregate_report_ids, - pending_aggregate_keys=pending_aggregate_keys, - ) - if report_type == "aggregate": - aggregate_report_msg_uids.append(message_id) - elif report_type == "failure": - failure_report_msg_uids.append(message_id) - elif report_type == "smtp_tls": - smtp_tls_msg_uids.append(message_id) - except ParserError as error: - logger.warning(error.__str__()) - if not test: - _dispose_invalid_message( - connection, message_id, delete_invalid, invalid_reports_folder - ) + _parse_in_process(message_id, msg_content) # Ask the caller whether this batch actually made it to its output # destinations before touching a single message. A callback that says @@ -4128,8 +4348,10 @@ def get_dmarc_reports_from_mailbox( results=results, since=current_time, n_procs=n_procs, + parse_timeout=parse_timeout, save_callback=save_callback, max_unsaved_retries=max_unsaved_retries, + attempts_file=attempts_file, config=cfg, ) @@ -4163,7 +4385,9 @@ def watch_inbox( normalize_timespan_threshold_hours: float = 24.0, config_reloading: Callable | None = None, n_procs: int = 1, + parse_timeout: float = 0.0, max_unsaved_retries: int = 2, + attempts_file: str | None = None, config: ParserConfig | None = None, ): """ @@ -4231,11 +4455,23 @@ def watch_inbox( n_procs (int): Number of processes to use for parsing messages in parallel. Passed through to ``get_dmarc_reports_from_mailbox`` on each check. Not part of ``config``; always applies. + parse_timeout (float): Stop parsing a message after this many + seconds and treat it as invalid (``0``, the default, means no + limit). Passed through to ``get_dmarc_reports_from_mailbox`` + on each check; a negative or non-finite value raises + ``ValueError`` before the watch starts. Not part of ``config``; + always applies. max_unsaved_retries (int): How many times a message may be retried after ``callback`` first reported its batch unsaved, before it is moved to the ``Unsaved`` archive subfolder (default 2). Passed through to ``get_dmarc_reports_from_mailbox``, where it is documented in full. Not part of ``config``; always applies. + attempts_file (str | None): A JSON file counting the parse + attempts that never finished, so a message that keeps killing + the process is set aside as invalid (default ``None``: no + record). Passed through to ``get_dmarc_reports_from_mailbox``, + where it is documented in full. Not part of ``config``; always + applies. config (ParserConfig): a single object carrying all parsing and enrichment options plus the caches; when provided, it replaces the individual parsing and enrichment option keyword arguments @@ -4244,8 +4480,8 @@ def watch_inbox( ignored. The remaining keyword arguments control mailbox handling and orchestration rather than parsing (the folder names, the ``delete`` options, ``test``, ``since``, - ``batch_size``, ``max_unsaved_retries``); they are not part of - ``config`` and always apply. + ``batch_size``, ``max_unsaved_retries``, ``attempts_file``); + they are not part of ``config`` and always apply. """ # Validate before the watch loop starts: raised inside a check, this # would be swallowed and endlessly retried by the IMAP and Maildir @@ -4253,6 +4489,10 @@ def watch_inbox( if max_unsaved_retries < 0: raise ValueError("max_unsaved_retries must be >= 0") + from parsedmarc.parallel import _check_parse_timeout + + _check_parse_timeout(parse_timeout) + cfg = _resolve_config( config, offline=offline, @@ -4282,8 +4522,10 @@ def watch_inbox( since=since, create_folders=False, n_procs=n_procs, + parse_timeout=parse_timeout, save_callback=callback, max_unsaved_retries=max_unsaved_retries, + attempts_file=attempts_file, config=cfg, ) diff --git a/parsedmarc/attempts.py b/parsedmarc/attempts.py new file mode 100644 index 00000000..08018843 --- /dev/null +++ b/parsedmarc/attempts.py @@ -0,0 +1,213 @@ +"""A persisted count of mailbox messages whose parsing never finished. + +A message whose parse kills the process (the out-of-memory killer, a +container memory cap, a segfault) is never moved out of the reports folder, +so every later run fetches it and dies on it again. ``AttemptStore`` keeps a +small JSON file that counts, per message, the parse attempts that started +but never produced a result. ``get_dmarc_reports_from_mailbox()`` records an +attempt before it parses a message and clears it as soon as the parse +returns or raises ``ParserError``; a message whose count has reached +``MAX_PARSE_ATTEMPTS`` is set aside as invalid without being parsed again. + +The file is written atomically (a temporary file in the same directory, +fsynced, then renamed over the old one), so a crash during a write leaves +either the old file or the new one, and it is created readable by its owner +only. A write that fails turns the store off for the rest of the batch +instead of stopping the run: the protection is a backstop, and losing it +must not cost the reports. +""" + +from __future__ import annotations + +import contextlib +import hashlib +import json +import os +import tempfile +from datetime import datetime, timedelta, timezone +from typing import Any + +from parsedmarc.log import logger + +# How many parse attempts may die before the message is set aside. Two lets +# a message survive one unrelated crash (a reboot, a kill during a deploy) +# while the third run stops the loop. +MAX_PARSE_ATTEMPTS = 2 + +# An entry not touched for this long belongs to a message that has left the +# reports folder some other way (moved or deleted by hand); drop it on load +# so the file does not grow forever. +PRUNE_AFTER = timedelta(days=30) + +FILE_VERSION = 1 + +# How much of the message the key hashes. Enough to tell two messages +# apart that reuse one UID, small enough to hash at no cost. +_KEY_CONTENT_PREFIX = 65536 + + +def attempt_key( + reports_folder: str, message_id: int | str, content: str | bytes +) -> str: + """Return the store key of one message in one reports folder. + + The key joins the folder, the backend's message id and a hash of the + message's first 64 KiB. The hash keeps a new message that reuses the + UID of an old one (an IMAP folder recreated with a new UIDVALIDITY, + which mailsuite does not expose) from inheriting the old one's count. + + Args: + reports_folder: The folder the message was fetched from + message_id: The backend's id of the message + content: The fetched message + + Returns: + str: The key + """ + if isinstance(content, str): + # surrogatepass: a str decoded with surrogateescape still encodes. + raw = content[:_KEY_CONTENT_PREFIX].encode("utf-8", "surrogatepass") + else: + raw = content[:_KEY_CONTENT_PREFIX] + digest = hashlib.sha256(raw).hexdigest()[:16] + return f"{reports_folder}\x1f{message_id}\x1f{digest}" + + +class AttemptStore: + """Unfinished parse attempts per message, persisted in a JSON file. + + The file holds ``{"version": 1, "attempts": {key: {"count": n, + "last": ""}}}``. A missing file is an empty store; a + file that cannot be read or does not have that shape is logged as a + warning and replaced on the next write. + + Args: + path: The JSON file to read and write + """ + + def __init__(self, path: str) -> None: + self.path = path + self.enabled = True + self._attempts: dict[str, dict[str, Any]] = {} + self.load() + + def load(self) -> None: + """Read the file, replacing the store's entries. + + Entries whose last attempt is older than ``PRUNE_AFTER`` are + dropped. + """ + self._attempts = {} + try: + with open(self.path, "rb") as attempts_file: + raw = attempts_file.read() + except FileNotFoundError: + return + except OSError as error: + logger.warning( + f"Could not read attempts file {self.path}: {error}; starting empty" + ) + return + attempts = _parse_attempts(raw) + if attempts is None: + logger.warning( + f"Attempts file {self.path} is not a version {FILE_VERSION} " + "attempts file; starting empty" + ) + return + cutoff = datetime.now(timezone.utc) - PRUNE_AFTER + self._attempts = { + key: entry + for key, entry in attempts.items() + if datetime.fromisoformat(entry["last"]) >= cutoff + } + + def count(self, key: str) -> int: + """Return the number of unfinished attempts recorded for ``key``.""" + entry = self._attempts.get(key) + return entry["count"] if entry else 0 + + def record(self, key: str) -> int: + """Count one more attempt for ``key`` and write the file. + + Returns: + int: The new count, or ``0`` when the store is off + """ + if not self.enabled: + return 0 + count = self.count(key) + 1 + self._attempts[key] = { + "count": count, + "last": datetime.now(timezone.utc).isoformat(), + } + if not self._flush(): + return 0 + return count + + def clear(self, key: str) -> None: + """Forget ``key`` and write the file, if it had an entry.""" + if not self.enabled or key not in self._attempts: + return + del self._attempts[key] + self._flush() + + def _flush(self) -> bool: + """Write the store atomically; on failure, log and turn it off.""" + directory = os.path.dirname(os.path.abspath(self.path)) + body = json.dumps( + {"version": FILE_VERSION, "attempts": self._attempts}, + sort_keys=True, + ).encode("utf-8") + temp_path = None + try: + os.makedirs(directory, exist_ok=True) + # mkstemp creates the file with mode 0600, and os.replace + # carries that mode over to the attempts file. + descriptor, temp_path = tempfile.mkstemp( + prefix=".attempts-", suffix=".tmp", dir=directory + ) + with os.fdopen(descriptor, "wb") as temp_file: + temp_file.write(body) + temp_file.flush() + os.fsync(temp_file.fileno()) + os.replace(temp_path, self.path) + except OSError as error: + if temp_path is not None: + with contextlib.suppress(OSError): + os.unlink(temp_path) + self.enabled = False + logger.error( + f"Could not write attempts file {self.path}: {error}; " + "crashed-message protection is disabled for the rest of this " + "batch" + ) + return False + return True + + +def _parse_attempts(raw: bytes) -> dict[str, dict[str, Any]] | None: + """Return the ``attempts`` mapping of a version 1 file, or ``None``.""" + try: + document = json.loads(raw) + except ValueError: + # json.JSONDecodeError and UnicodeDecodeError are both ValueErrors. + return None + if not isinstance(document, dict) or document.get("version") != FILE_VERSION: + return None + attempts = document.get("attempts") + if not isinstance(attempts, dict): + return None + for entry in attempts.values(): + if not isinstance(entry, dict): + return None + count = entry.get("count") + last = entry.get("last") + if type(count) is not int or count < 1 or not isinstance(last, str): + return None + try: + last_time = datetime.fromisoformat(last) + except ValueError: + return None + if last_time.tzinfo is None: + return None + return attempts diff --git a/parsedmarc/cli.py b/parsedmarc/cli.py index 67b57a3a..5c3a7c08 100644 --- a/parsedmarc/cli.py +++ b/parsedmarc/cli.py @@ -8,6 +8,8 @@ import functools import http.client import json import logging +import math +import multiprocessing import os import shutil import signal @@ -141,7 +143,11 @@ from parsedmarc.mail import ( MaildirConnection, MSGraphConnection, ) -from parsedmarc.parallel import _parse_report_file_job, parallel_map +from parsedmarc.parallel import ( + _file_timeout_result, + _parse_report_file_job, + parallel_map, +) from parsedmarc.types import ParsedReport, ParsingResults import parsedmarc.utils from parsedmarc.utils import ( @@ -570,6 +576,7 @@ _DIRECT_FILE_KEYS = frozenset( "MSGRAPH_TOKEN_FILE", "GMAIL_API_CREDENTIALS_FILE", "GMAIL_API_TOKEN_FILE", + "MAILBOX_ATTEMPTS_FILE", ] ) @@ -960,6 +967,20 @@ def _parse_config(config: ConfigParser, opts): opts.log_file = _expand_path(general_config["log_file"]) if "n_procs" in general_config: opts.n_procs = general_config.getint("n_procs") + if "parse_timeout" in general_config: + raw_parse_timeout = general_config["parse_timeout"] + try: + parse_timeout = float(raw_parse_timeout) + except ValueError: + parse_timeout = math.nan + # float() also accepts "nan" and "inf", which are no number of + # seconds. + if not math.isfinite(parse_timeout) or parse_timeout < 0: + raise ConfigurationError( + "parse_timeout must be a number of seconds, 0 or greater, " + f"got {raw_parse_timeout!r}" + ) + opts.parse_timeout = parse_timeout if "ip_db_path" in general_config: opts.ip_db_path = _expand_path(general_config["ip_db_path"]) else: @@ -1030,6 +1051,8 @@ def _parse_config(config: ConfigParser, opts): opts.mailbox_max_unsaved_retries = mailbox_config.getint( "max_unsaved_retries" ) + if "attempts_file" in mailbox_config: + opts.mailbox_attempts_file = _expand_path(mailbox_config["attempts_file"]) if "since" in mailbox_config: opts.mailbox_since = mailbox_config["since"] @@ -3210,6 +3233,7 @@ def _main(): mailbox_batch_size=10, mailbox_check_timeout=30, mailbox_max_unsaved_retries=2, + mailbox_attempts_file=None, mailbox_since=None, imap_host=None, imap_skip_certificate_verification=False, @@ -3315,6 +3339,7 @@ def _main(): maildir_create=False, log_file=args.log_file, n_procs=1, + parse_timeout=0.0, archive_directory=None, ip_db_path=None, ipinfo_url=None, @@ -3485,6 +3510,11 @@ def _main(): # "double tap": the first press is graceful, the second short-circuits # to os._exit(130). os._exit is async-signal-safe; sys.exit and # logging are not, so the handlers only set flags / call os._exit. + # Parsing workers ignore SIGINT and os._exit skips the pool's cleanup, + # so the second press first kills this process's child processes, or + # they would run on as orphans. Python runs a signal handler in the + # main thread between bytecodes, not in the C signal context, so + # multiprocessing.active_children() and Process.kill() are safe there. _reload_requested = False _shutdown_requested = False _sigint_count = 0 @@ -3501,6 +3531,8 @@ def _main(): nonlocal _shutdown_requested, _sigint_count _sigint_count += 1 if _sigint_count >= 2: + for child in multiprocessing.active_children(): + child.kill() os._exit(130) _shutdown_requested = True @@ -3535,34 +3567,49 @@ def _main(): parser_config = _build_parser_config(opts) func = functools.partial(_parse_report_file_job, config=parser_config) - for file_path, result in parallel_map( - func, file_paths, n_procs, should_stop=lambda: _shutdown_requested - ): - if pbar is not None: - pbar.update(1) - if isinstance(result, Exception): - logger.error(f"Failed to parse {file_path} - {result}") - else: - if result["report_type"] == "aggregate": - report_org = result["report"]["report_metadata"]["org_name"] - report_id = result["report"]["report_metadata"]["report_id"] - report_key = _aggregate_report_dedup_key(result["report"]) - seen_ids = parser_config.seen_aggregate_report_ids - if report_key not in seen_ids: - seen_ids[report_key] = True - aggregate_reports.append(result["report"]) - else: - logger.debug( - "Skipping duplicate aggregate report " - f"from {sanitize_for_log(str(report_org))} " - f"with ID: {sanitize_for_log(str(report_id))}" - ) - elif result["report_type"] == "failure": - failure_reports.append(result["report"]) - elif result["report_type"] == "smtp_tls": - smtp_tls_reports.append(result["report"]) - if opts.archive_directory: - _archive_processed_file(file_path, opts.archive_directory, result) + # Set when parsing report files or an mbox file ends in a ParserError + # (a worker process that died, a missing mbox). No more input is read; + # what was gathered is saved before the run exits with status 1, since + # files already moved under archive_directory are kept nowhere else. + input_error = False + try: + for file_path, result in parallel_map( + func, + file_paths, + n_procs, + should_stop=lambda: _shutdown_requested, + parse_timeout=opts.parse_timeout, + timeout_result=_file_timeout_result, + ): + if pbar is not None: + pbar.update(1) + if isinstance(result, Exception): + logger.error(f"Failed to parse {file_path} - {result}") + else: + if result["report_type"] == "aggregate": + report_org = result["report"]["report_metadata"]["org_name"] + report_id = result["report"]["report_metadata"]["report_id"] + report_key = _aggregate_report_dedup_key(result["report"]) + seen_ids = parser_config.seen_aggregate_report_ids + if report_key not in seen_ids: + seen_ids[report_key] = True + aggregate_reports.append(result["report"]) + else: + logger.debug( + "Skipping duplicate aggregate report " + f"from {sanitize_for_log(str(report_org))} " + f"with ID: {sanitize_for_log(str(report_id))}" + ) + elif result["report_type"] == "failure": + failure_reports.append(result["report"]) + elif result["report_type"] == "smtp_tls": + smtp_tls_reports.append(result["report"]) + if opts.archive_directory: + _archive_processed_file(file_path, opts.archive_directory, result) + except ParserError as error: + # parallel_map raises ParserError when a worker process dies. + logger.error(error.__str__()) + input_error = True if pbar is not None: pbar.close() @@ -3575,14 +3622,25 @@ def _main(): logger.info("Shutdown requested, stopping file processing early") for mbox_path in mbox_paths: + if input_error: + break if _shutdown_requested: logger.info("Shutdown requested, skipping remaining mbox files") break - reports = get_dmarc_reports_from_mbox( - mbox_path, - config=parser_config, - n_procs=n_procs, - ) + try: + reports = get_dmarc_reports_from_mbox( + mbox_path, + config=parser_config, + n_procs=n_procs, + parse_timeout=opts.parse_timeout, + ) + except ParserError as error: + # A missing mbox, a message error that is not an invalid + # report, or a parsing worker process that died. The reports + # of this mbox are lost with the error; earlier ones are kept. + logger.error(error.__str__()) + input_error = True + break aggregate_reports += reports["aggregate_reports"] failure_reports += reports["failure_reports"] smtp_tls_reports += reports["smtp_tls_reports"] @@ -3600,6 +3658,15 @@ def _main(): "smtp_tls_reports": list(smtp_tls_reports), } + if input_error: + # Save what was parsed, then stop: no mailbox is opened and no + # results email is sent for a run whose input was cut short. + try: + process_reports(file_parsing_results) + except ParserError as error: + logger.error(error.__str__()) + sys.exit(1) + mailbox_connection = None msgraph_connection: MSGraphConnection | None = None mailbox_batch_size_value = 10 @@ -3814,8 +3881,10 @@ def _main(): since=opts.mailbox_since, config=parser_config, n_procs=n_procs, + parse_timeout=opts.parse_timeout, save_callback=mailbox_save_callback, max_unsaved_retries=mailbox_max_unsaved_retries_value, + attempts_file=opts.mailbox_attempts_file, ) aggregate_reports += reports["aggregate_reports"] @@ -3823,11 +3892,18 @@ def _main(): smtp_tls_reports += reports["smtp_tls_reports"] except ParserError as error: - # fail_on_output_error turns a failed batch save into a - # ParserError inside mailbox_save_callback; it reaches here - # through get_dmarc_reports_from_mailbox, which leaves the - # batch's messages in the mailbox on its way out. + # A worker process that died during the fetch, or a failed + # batch save under fail_on_output_error (a ParserError raised + # inside mailbox_save_callback). Either way the batch's + # messages stay in the mailbox and earlier batches are saved; + # the reports from files and mbox inputs, some perhaps already + # moved under archive_directory, are saved before exiting. logger.error(error.__str__()) + if any(file_parsing_results.values()): + try: + process_reports(file_parsing_results) + except ParserError as save_error: + logger.error(save_error.__str__()) sys.exit(1) except (ClientAuthenticationError, APIError, httpx.HTTPError) as error: if msgraph_connection is None: @@ -3964,7 +4040,9 @@ def _main(): config=parser_config, config_reloading=lambda: _reload_requested or _shutdown_requested, n_procs=n_procs, + parse_timeout=opts.parse_timeout, max_unsaved_retries=mailbox_max_unsaved_retries_value, + attempts_file=opts.mailbox_attempts_file, ) except FileExistsError as error: logger.error(f"{error.__str__()}") diff --git a/parsedmarc/config.py b/parsedmarc/config.py index 110419f3..8810cd30 100644 --- a/parsedmarc/config.py +++ b/parsedmarc/config.py @@ -97,9 +97,10 @@ class ParserConfig: interpreter starts with empty caches and accumulates hits across the tasks it handles, matching pre-refactor behavior. - Note that ``keep_alive`` and ``n_procs`` are deliberately **not** fields - on this class: those control process/worker orchestration, not parsing - or enrichment behavior. + Note that ``keep_alive``, ``n_procs``, ``parse_timeout`` and + ``attempts_file`` are deliberately **not** fields on this class: those + control process/worker or mailbox orchestration, not parsing or + enrichment behavior. Attributes: offline: Do not make online requests (DNS, IP database download, diff --git a/parsedmarc/elastic.py b/parsedmarc/elastic.py index 0051a76f..e182c44c 100644 --- a/parsedmarc/elastic.py +++ b/parsedmarc/elastic.py @@ -1438,7 +1438,12 @@ def save_failure_report_to_elasticsearch( sample_date = None if failure_report["parsed_sample"]["date"] is not None: sample_date = failure_report["parsed_sample"]["date"] - sample_date = human_timestamp_to_datetime(sample_date) + try: + sample_date = human_timestamp_to_datetime(sample_date) + except (ValueError, OverflowError) as error: + raise InvalidFailureReport( + f"Invalid sample Date: {sanitize_for_log(str(error))}" + ) from error original_headers = failure_report["parsed_sample"]["headers"] headers: dict[str, Any] = {} for original_header in original_headers: @@ -1446,6 +1451,9 @@ def save_failure_report_to_elasticsearch( # header named "Subject.x" would turn sample.headers.subject into an # object and reject every later sample with a Subject header. header_name = original_header.lower().replace(".", "_") + if not header_name: + # An empty name is not a valid field name for the cluster. + continue headers[header_name] = original_headers[original_header] # arrival_date_utc is a UTC wall-clock string; without assume_utc the @@ -1498,7 +1506,12 @@ def save_failure_report_to_elasticsearch( q = q & Q(subject_query) # pyright: ignore[reportArgumentType] search.query = q # pyright: ignore[reportAttributeAccessIssue] - existing = search.execute() + try: + existing = search.execute() + except Exception as error_: + raise ElasticsearchError( + f"Elasticsearch's search for existing report error: {error_.__str__()}" + ) if len(existing) > 0: raise AlreadySaved( diff --git a/parsedmarc/opensearch.py b/parsedmarc/opensearch.py index 9ba1a2cd..7c5905cb 100644 --- a/parsedmarc/opensearch.py +++ b/parsedmarc/opensearch.py @@ -1373,7 +1373,12 @@ def save_failure_report_to_opensearch( sample_date = None if failure_report["parsed_sample"]["date"] is not None: sample_date = failure_report["parsed_sample"]["date"] - sample_date = human_timestamp_to_datetime(sample_date) + try: + sample_date = human_timestamp_to_datetime(sample_date) + except (ValueError, OverflowError) as error: + raise InvalidFailureReport( + f"Invalid sample Date: {sanitize_for_log(str(error))}" + ) from error original_headers = failure_report["parsed_sample"]["headers"] headers: dict[str, Any] = {} for original_header in original_headers: @@ -1381,6 +1386,9 @@ def save_failure_report_to_opensearch( # header named "Subject.x" would turn sample.headers.subject into an # object and reject every later sample with a Subject header. header_name = original_header.lower().replace(".", "_") + if not header_name: + # An empty name is not a valid field name for the cluster. + continue headers[header_name] = original_headers[original_header] # arrival_date_utc is a UTC wall-clock string; without assume_utc the @@ -1433,7 +1441,12 @@ def save_failure_report_to_opensearch( q = q & Q(subject_query) search.query = q - existing = search.execute() + try: + existing = search.execute() + except Exception as error_: + raise OpenSearchError( + f"OpenSearch's search for existing report error: {error_.__str__()}" + ) if len(existing) > 0: raise AlreadySaved( diff --git a/parsedmarc/parallel.py b/parsedmarc/parallel.py index 6df5f5b4..18e7f640 100644 --- a/parsedmarc/parallel.py +++ b/parsedmarc/parallel.py @@ -1,14 +1,44 @@ -"""Bounded-window multiprocessing helpers for parallel report parsing.""" +"""Bounded-window multiprocessing helpers for parallel report parsing. + +With a ``parse_timeout``, a job that runs too long is stopped by killing +the worker processes, and a worker can be killed at any moment, including +while it sends a result. ``ProcessPoolExecutor`` sends results over one +pipe that the parent reads in a non-daemon management thread; a large +result cut off part way leaves that thread waiting for the rest of the +message forever, and the interpreter then hangs at exit joining it. So the +pool built for a timeout never sends a result through the executor: the +worker pickles it, error values included, into a file of its own in a +directory the pool owns, and the executor carries only ``None`` or a short +error text. That message (about 115 bytes, under 400 with the longest +error text) and the start tokens are below ``PIPE_BUF``, at least 512 +bytes on POSIX, which writes a message that size to a pipe in one piece, +so a killed worker cannot leave a partial message on either pipe. The +pool without a timeout never kills a worker while it runs and sends +results through the executor. +""" from __future__ import annotations +import itertools import logging +import math +import multiprocessing +import os +import pickle +import shutil +import signal +import time from collections import deque from collections.abc import Callable, Iterable, Iterator from concurrent.futures import Future, ProcessPoolExecutor, wait -from typing import TYPE_CHECKING, TypeVar +from concurrent.futures.process import BrokenProcessPool +from tempfile import mkdtemp +from typing import TYPE_CHECKING, Any, Generic, TypeVar if TYPE_CHECKING: + from multiprocessing.context import BaseContext + from multiprocessing.queues import SimpleQueue + from parsedmarc import ParserError from parsedmarc.config import ParserConfig from parsedmarc.types import ParsedReport @@ -16,6 +46,19 @@ if TYPE_CHECKING: _J = TypeVar("_J") _R = TypeVar("_R") +# How long to wait for a killed worker process, and for the executor's +# management thread, to exit after a timed-out job's pool is torn down. +_KILL_JOIN_SECONDS = 5.0 + +# The longest error text a worker returns through the executor, so that its +# message stays below the smallest PIPE_BUF POSIX allows (512 bytes). +_MAX_ERROR_TEXT = 200 + +# Set in each worker of a pool built for a parse_timeout, by +# _init_timed_worker(); _run_timed_job() writes a job's token to it as the +# job starts, so the parent can start that job's clock. +_start_queue: SimpleQueue[int] | None = None + def _init_worker( log_level: int, @@ -59,6 +102,19 @@ def _init_worker( from parsedmarc import utils from parsedmarc.log import configure_logging + # Under fork a worker inherits the parent's signal handlers, and the CLI + # installs SIGTERM and SIGINT handlers that only set a flag. A worker + # running them ignores the SIGTERM ProcessPoolExecutor sends when it + # tears down a broken pool, and the teardown then waits for it forever, + # so SIGTERM gets its default action. Ctrl-C sends SIGINT to the whole + # process group, workers included, under every start method; the parent + # decides how to shut down and lets the batch in progress finish, so + # workers ignore SIGINT. Under spawn or forkserver a Ctrl-C that lands + # before this line has run still kills the worker, which then ends the + # batch as a worker that died does. + signal.signal(signal.SIGTERM, signal.SIG_DFL) + signal.signal(signal.SIGINT, signal.SIG_IGN) + utils._set_ip_worker_state(*ip_worker_state) utils.psl_overrides[:] = psl_overrides @@ -69,6 +125,146 @@ def _init_worker( configure_logging(log_level, log_file) +def _init_timed_worker(start_queue: SimpleQueue[int], *initargs: Any) -> None: + """Pool initializer for a pool whose jobs have a ``parse_timeout``. + + Keeps ``start_queue`` for ``_run_timed_job()`` and then runs + ``_init_worker(*initargs)``. + """ + global _start_queue + _start_queue = start_queue + _init_worker(*initargs) + + +def _result_path(result_dir: str, token: int) -> str: + """Return the file in which the job with ``token`` leaves its outcome.""" + return os.path.join(result_dir, str(token)) + + +def _run_timed_job( + func: Callable[[_J], _R], token: int, job: _J, result_dir: str +) -> tuple[str, str] | None: + """Worker job that reports ``token`` as started, runs ``func(job)``, and + leaves the outcome in ``result_dir`` for ``_take_outcome()``. + + The parent cannot tell from the future alone when a job starts: + ``ProcessPoolExecutor`` marks a future running when it moves the job to + its call queue, which holds one job more than there are workers, so one + job can be "running" while it still waits behind a slow neighbour. The + token written here, before ``func`` runs, is what starts the job's clock. + The outcome, ``("value", result)`` or ``("error", exception)``, is + written to a temporary name and renamed into place, so the file the + parent reads is always whole. Returns ``None``, or, when the outcome + cannot be handed back, ``("directory", text)`` for a file that cannot + be written and ``("outcome", text)`` for an outcome that cannot be + pickled, the text cut to ``_MAX_ERROR_TEXT`` bytes of UTF-8 so the + executor's message stays small; a ``.tmp`` file a failed write leaves + behind goes with the pool's result directory. + """ + if _start_queue is not None: + _start_queue.put(token) + try: + outcome: tuple[str, Any] = ("value", func(job)) + except Exception as error: + outcome = ("error", error) + path = _result_path(result_dir, token) + try: + with open(path + ".tmp", "wb") as result_file: + pickle.dump(outcome, result_file, protocol=pickle.HIGHEST_PROTOCOL) + os.replace(path + ".tmp", path) + except OSError as error: + return "directory", _short_error_text(error) + except Exception as error: + # An unpicklable result, or one too deep or too large to pickle. + return "outcome", _short_error_text(error) + return None + + +def _short_error_text(error: BaseException) -> str: + """Return ``error``'s type and text within ``_MAX_ERROR_TEXT`` bytes. + + The limit is in bytes of UTF-8, since the pipe's atomic-write bound is + in bytes; an exception whose ``__str__`` itself fails is named by its + type alone, so nothing here can raise. + """ + name = type(error).__name__ + try: + text = f"{name}: {error}" + except Exception: + text = name + return text.encode("utf-8")[:_MAX_ERROR_TEXT].decode("utf-8", errors="ignore") + + +def _temp_dir_error(reason: object) -> ParserError: + """Return the error a timed pool raises when its result files cannot be + created, written or read.""" + from parsedmarc import ParserError + + return ParserError( + f"parse_timeout needs a writable temporary directory (TMPDIR): {reason}" + ) + + +def _outcome_error(reason: object) -> ParserError: + """Return the error a timed pool raises when a job's outcome cannot be + handed back to the parent, because it cannot be pickled or unpickled.""" + from parsedmarc import ParserError + + return ParserError( + f"The outcome of a parsing job could not be handed back to parsedmarc: {reason}" + ) + + +def _take_outcome(result_dir: str, token: int) -> Any: + """Read, delete and return the outcome ``_run_timed_job()`` left for + ``token``, raising it when it is an exception.""" + path = _result_path(result_dir, token) + try: + with open(path, "rb") as result_file: + kind, value = pickle.load(result_file) + os.remove(path) + except OSError as error: + raise _temp_dir_error(error) from error + except Exception as error: + # A pickle that does not load, such as an exception whose class + # needs arguments its pickle does not carry. + raise _outcome_error(f"{type(error).__name__}: {error}") from error + if kind == "error": + raise value + return value + + +def _email_timeout_result(msg_content: bytes | str, seconds: float) -> ParserError: + """Return the ``_parse_report_email_job`` value for a timed-out message. + + Passed to ``parallel_map()`` as ``timeout_result``. The value is a + ``ParseTimeoutError``, an ``InvalidDMARCReport``, so the mbox loop warns + and continues and the mailbox loop files the message under ``Invalid``, + as for any other message that cannot be parsed. + """ + from parsedmarc import ParseTimeoutError + + return ParseTimeoutError( + f"Parsing the message took longer than parse_timeout " + f"({seconds:g} seconds) and was stopped" + ) + + +def _file_timeout_result(file_path: str, seconds: float) -> tuple[str, Exception]: + """Return the ``_parse_report_file_job`` value for a timed-out file. + + Passed to ``parallel_map()`` as ``timeout_result``. The value pairs + ``file_path`` with a ``ParseTimeoutError``, a ``ParserError``, so the CLI + logs the failure and, with ``archive_directory`` set, moves the file to + ``Invalid``. + """ + from parsedmarc import ParseTimeoutError + + return file_path, ParseTimeoutError( + f"Parsing took longer than parse_timeout ({seconds:g} seconds) and was stopped" + ) + + def _parse_report_email_job( msg_content: bytes | str, *, config: ParserConfig ) -> ParsedReport | ParserError: @@ -124,6 +320,333 @@ def _parse_report_file_job( return file_path, e +def _check_parse_timeout(parse_timeout: float) -> None: + """Raise ``ValueError`` unless ``parse_timeout`` is finite and >= 0.""" + if not math.isfinite(parse_timeout) or parse_timeout < 0: + raise ValueError( + f"parse_timeout must be a finite number of seconds >= 0, " + f"got {parse_timeout!r}" + ) + + +class _Pending(Generic[_J, _R]): + """One job in ``parallel_map()``'s submission window under a timeout. + + ``started_at`` is the ``time.monotonic()`` time at which the parent + learned that the job started, ``None`` until then. ``future`` is the + executor's future, whose result is ``None`` or a short error marker (the + outcome is in the pool's result file), while ``in_pool`` is ``True``. It is replaced when + the job is resubmitted to a new pool, and by an already resolved future + holding the outcome once ``_DeadlinePool.settle()`` has read it or the + ``timeout_result`` value when the job times out. + """ + + __slots__ = ("future", "in_pool", "job", "started_at", "token") + + def __init__(self, job: _J, token: int, future: Future[Any]) -> None: + self.job = job + self.token = token + self.future = future + self.in_pool = False + self.started_at: float | None = None + + +class _DeadlinePool(Generic[_J, _R]): + """A process pool whose jobs report when they start, and can be killed. + + Each job runs through ``_run_timed_job()``, which writes the job's token + to a queue the parent reads in ``stamp_starts()`` and leaves its outcome + in a file of the pool's result directory, which ``settle()`` reads. + ``replace()`` kills every worker process and builds a fresh pool with a + fresh queue and result directory, since a worker killed while writing to + the old queue may leave it unusable; ``kill()`` and ``close()`` remove + the result directory with any file left in it. + """ + + def __init__( + self, + func: Callable[[_J], _R], + n_procs: int, + initargs: tuple[Any, ...], + ) -> None: + self._func = func + self._n_procs = n_procs + self._initargs = initargs + self._tokens = itertools.count() + self._by_token: dict[int, _Pending[_J, _R]] = {} + self._context: BaseContext = multiprocessing.get_context() + self._executor, self._start_queue, self.result_dir = self._new_executor() + + def _new_executor(self) -> tuple[ProcessPoolExecutor, SimpleQueue[int], str]: + # Readable by this user only (mkdtemp's mode): results hold reports. + try: + result_dir = mkdtemp(prefix="parsedmarc-results-") + except OSError as error: + raise _temp_dir_error(error) from error + start_queue: SimpleQueue[int] = self._context.SimpleQueue() + executor = ProcessPoolExecutor( + max_workers=self._n_procs, + mp_context=self._context, + initializer=_init_timed_worker, + initargs=(start_queue, *self._initargs), + ) + return executor, start_queue, result_dir + + def submit(self, job: _J) -> _Pending[_J, _R]: + """Submit ``job`` and return its new, not yet started, entry.""" + pending: _Pending[_J, _R] = _Pending(job, -1, Future()) + self.resubmit(pending) + return pending + + def resubmit(self, pending: _Pending[_J, _R]) -> None: + """Submit ``pending``'s job to the current pool, with a new token.""" + pending.token = next(self._tokens) + pending.started_at = None + pending.future = self._executor.submit( + _run_timed_job, self._func, pending.token, pending.job, self.result_dir + ) + pending.in_pool = True + self._by_token[pending.token] = pending + + def settle(self, pending: _Pending[_J, _R]) -> None: + """Replace a done job's executor future by one holding its outcome. + + The outcome is read from, and removed with, its result file. An + executor future that failed (``BrokenProcessPool``) is kept, so its + ``result()`` still raises. + """ + if not pending.in_pool: + return + pending.in_pool = False + if pending.future.exception() is not None: + return + settled: Future[Any] = Future() + handback_error = pending.future.result() + try: + if handback_error is not None: + kind, text = handback_error + if kind == "directory": + raise _temp_dir_error(text) + raise _outcome_error(text) + settled.set_result(_take_outcome(self.result_dir, pending.token)) + except Exception as error: + settled.set_exception(error) + pending.future = settled + + def stamp_starts(self, now: float) -> None: + """Set ``started_at`` to ``now`` on each job that has reported starting.""" + while not self._start_queue.empty(): + pending = self._by_token.pop(self._start_queue.get(), None) + if pending is not None: + pending.started_at = now + + def kill(self) -> None: + """Kill the worker processes, as ``_kill_workers()`` does, close the + start queue and remove the result directory.""" + _kill_workers(self._executor) + self._start_queue.close() + self._by_token.clear() + shutil.rmtree(self.result_dir, ignore_errors=True) + + def replace(self) -> None: + """Kill this pool's workers and continue with a fresh pool.""" + self.kill() + self._executor, self._start_queue, self.result_dir = self._new_executor() + + def close(self) -> None: + """Shut the pool down once every job has finished.""" + self._executor.shutdown(wait=True) + self._start_queue.close() + self._by_token.clear() + shutil.rmtree(self.result_dir, ignore_errors=True) + + +def _kill_workers(executor: ProcessPoolExecutor) -> None: + """Kill ``executor``'s worker processes and wait, boundedly, for them. + + ``ProcessPoolExecutor`` has no public way to stop a running job, and + ``shutdown()`` waits for it or, with ``wait=False``, leaves it running, + so the workers are read from ``_processes``, a private attribute present + in every supported Python version. Without it the workers are left to + finish on their own and a warning says so. + """ + from parsedmarc.log import logger + + processes = getattr(executor, "_processes", None) + manager_thread = getattr(executor, "_executor_manager_thread", None) + if processes is None: + logger.warning( + "Cannot stop the worker processes of a parsing pool on this " + "Python version; they keep running until they finish" + ) + workers = [] + else: + workers = list(processes.values()) + for worker in workers: + worker.kill() + executor.shutdown(wait=False, cancel_futures=True) + for worker in workers: + worker.join(_KILL_JOIN_SECONDS) + if manager_thread is not None: + manager_thread.join(_KILL_JOIN_SECONDS) + + +def _worker_died_error() -> ParserError: + """Return the error ``parallel_map()`` raises when a worker dies.""" + from parsedmarc import ParserError + + return ParserError( + "A parsing worker process died (killed, out of memory, or crashed); " + "the rest of this batch was not parsed" + ) + + +def _resolved(value: _R) -> Future[_R]: + future: Future[_R] = Future() + future.set_result(value) + return future + + +def _expire_overdue( + pool: _DeadlinePool[_J, _R], + window: deque[_Pending[_J, _R]], + now: float, + parse_timeout: float, + timeout_result: Callable[[_J, float], _R], +) -> bool: + """Stop every job in ``window`` running for ``parse_timeout`` or longer. + + Returns ``False`` when no job is overdue. Otherwise logs one warning per + overdue job, records which futures are already done and reads their + outcomes (killing the pool gives every other future + ``BrokenProcessPool`` and removes the result files), replaces the pool, + and then, in window order, keeps each done job's result, gives each + overdue job ``timeout_result(job, parse_timeout)``, and resubmits every + other job from scratch. Returns ``True``. + """ + from parsedmarc.log import logger + + done = [pending.future.done() for pending in window] + overdue = [ + not finished + and pending.started_at is not None + and now - pending.started_at >= parse_timeout + for pending, finished in zip(window, done) + ] + if not any(overdue): + return False + for _ in range(sum(overdue)): + logger.warning( + f"A parsing job ran longer than parse_timeout ({parse_timeout:g} " + f"seconds) and was stopped; restarting the worker processes" + ) + for pending, finished in zip(window, done): + if finished: + pool.settle(pending) + pool.replace() + for pending, finished, expired in zip(window, done, overdue): + if finished: + continue + if expired: + pending.started_at = None + pending.in_pool = False + pending.future = _resolved(timeout_result(pending.job, parse_timeout)) + else: + pool.resubmit(pending) + return True + + +def _map_with_timeout( + func: Callable[[_J], _R], + first_job: _J, + jobs_iter: Iterator[_J], + n_procs: int, + window_size: int, + initargs: tuple[Any, ...], + parse_timeout: float, + timeout_result: Callable[[_J, float], _R], + heartbeat: Callable[[], None] | None, + heartbeat_interval: float, + should_stop: Callable[[], bool] | None, +) -> Iterator[_R]: + """``parallel_map()``'s loop when ``parse_timeout`` is set. + + While it waits for a result, the parent wakes at least every + ``min(1.0, parse_timeout / 10, heartbeat_interval)`` seconds (the wait + slice), sooner when a deadline or heartbeat falls due, and expires + overdue jobs with + ``_expire_overdue()``. A ``should_stop`` stop cancels the jobs that have + not been handed to a worker and still waits for the others, which are + themselves bounded by the timeout. Leaving early (an exception, or the + caller closing the iterator) kills the pool instead of waiting for it. + """ + wait_slice = min(1.0, parse_timeout / 10) + if heartbeat is not None: + wait_slice = min(wait_slice, heartbeat_interval) + pool: _DeadlinePool[_J, _R] = _DeadlinePool(func, n_procs, initargs) + finished = False + try: + window: deque[_Pending[_J, _R]] = deque([pool.submit(first_job)]) + while len(window) < window_size: + try: + window.append(pool.submit(next(jobs_iter))) + except StopIteration: + break + + # Absolute, so rebuilding a pool never postpones a heartbeat. + next_heartbeat_at = time.monotonic() + heartbeat_interval + stopping = False + while window: + # Drained here as well as while waiting: when results are already + # done at harvest time the inner loop never runs, and the + # undrained tokens would keep each finished job (its whole input) + # in the pool's token map. + pool.stamp_starts(time.monotonic()) + oldest = window[0] + while not oldest.future.done(): + now = time.monotonic() + pool.stamp_starts(now) + if heartbeat is not None and now >= next_heartbeat_at: + heartbeat() + now = time.monotonic() + next_heartbeat_at = now + heartbeat_interval + if _expire_overdue(pool, window, now, parse_timeout, timeout_result): + continue + limit = wait_slice + started = [ + pending.started_at + for pending in window + if pending.started_at is not None and not pending.future.done() + ] + if started: + limit = min(limit, min(started) + parse_timeout - now) + if heartbeat is not None: + limit = min(limit, next_heartbeat_at - now) + wait([oldest.future], timeout=max(limit, 0.0)) + + window.popleft() + pool.settle(oldest) + yield oldest.future.result() + + if not stopping and should_stop is not None and should_stop(): + stopping = True + for pending in window: + pending.future.cancel() + window = deque(p for p in window if not p.future.cancelled()) + if stopping: + continue + try: + window.append(pool.submit(next(jobs_iter))) + except StopIteration: + continue + finished = True + finally: + if finished: + pool.close() + else: + pool.kill() + + def parallel_map( func: Callable[[_J], _R], jobs: Iterable[_J], @@ -133,6 +656,8 @@ def parallel_map( heartbeat: Callable[[], None] | None = None, heartbeat_interval: float = 30.0, should_stop: Callable[[], bool] | None = None, + parse_timeout: float = 0.0, + timeout_result: Callable[[_J, float], _R] | None = None, ) -> Iterator[_R]: """Map ``func`` over ``jobs`` using a bounded-window process pool. @@ -170,12 +695,48 @@ def parallel_map( every worker by the pool initializer, so IP enrichment and base-domain lookups match what the parent configured under every start method. + If ``parse_timeout`` is greater than zero, a job that runs that many + seconds is stopped and ``timeout_result(job, parse_timeout)`` is + yielded in its place, in its position. ``ProcessPoolExecutor`` cannot + stop one job, so every worker process is killed and a fresh pool is + started; the other unfinished jobs in the window start again from + scratch, and finished results are kept. A job's clock starts when its + worker reports that it began, so a job waiting behind a slow + neighbour is not charged for the wait. The parent checks the clocks + only while it waits for a result, at least every ``min(1.0, + parse_timeout / 10, heartbeat_interval)`` seconds (the wait slice), so + a job is stopped within one wait slice after the parent next waits for + a result; time the caller spends between results is not counted, and a + job can run past its timeout during it. One timeout costs + ``parse_timeout``, up to one wait slice and one pool start, plus a + re-run of the neighbours that were still running. A neighbour that is + itself a slow job loses its partial run and starts again, so P jobs + that all time out cost at most ``(ceil(P / n_procs) + 1) * + (parse_timeout + wait slice + pool start)``, plus, for each expiry, up + to ``(n_procs + 1) * _KILL_JOIN_SECONDS`` spent joining the killed + workers and the pool's management thread, during which no heartbeat is + sent. With + ``parse_timeout`` set, ``should_stop`` cancels the jobs not yet handed + to a worker and waits for the rest, each still bounded by the timeout. + With ``parse_timeout`` at 0 (the default) jobs have no time limit. + Raises: - ValueError: If ``n_procs`` is less than 1. Raised eagerly at the - call itself (not on first iteration of the returned iterator). + ValueError: If ``n_procs`` is less than 1, if ``parse_timeout`` is + negative or not finite, or if ``parse_timeout`` is set without + ``timeout_result``. Raised eagerly at the call itself (not on + first iteration of the returned iterator). + ParserError: While iterating, if a worker process dies (the + out-of-memory killer, a crash), which breaks the pool and loses + every unfinished job. The other workers are killed first; the + ``BrokenProcessPool`` is the error's cause. Also, with + ``parse_timeout`` set, if the temporary directory for the + results cannot be created, written or read. """ if n_procs < 1: raise ValueError(f"n_procs must be at least 1, got {n_procs}") + _check_parse_timeout(parse_timeout) + if parse_timeout and timeout_result is None: + raise ValueError("parse_timeout requires a timeout_result") def _generate() -> Iterator[_R]: jobs_iter = iter(jobs) @@ -195,14 +756,68 @@ def parallel_map( ] ip_worker_state = utils._get_ip_worker_state() psl_overrides = list(utils.psl_overrides) + initargs = (log_level, log_files, ip_worker_state, psl_overrides) window_size = max(window_factor * n_procs, 1) - with ProcessPoolExecutor( - max_workers=n_procs, - initializer=_init_worker, - initargs=(log_level, log_files, ip_worker_state, psl_overrides), - ) as executor: + try: + if parse_timeout and timeout_result is not None: + yield from _map_with_timeout( + func, + first_job, + jobs_iter, + n_procs, + window_size, + initargs, + parse_timeout, + timeout_result, + heartbeat, + heartbeat_interval, + should_stop, + ) + else: + yield from _map_plain( + func, + first_job, + jobs_iter, + n_procs, + window_size, + initargs, + heartbeat, + heartbeat_interval, + should_stop, + ) + except BrokenProcessPool as error: + raise _worker_died_error() from error + + return _generate() + + +def _map_plain( + func: Callable[[_J], _R], + first_job: _J, + jobs_iter: Iterator[_J], + n_procs: int, + window_size: int, + initargs: tuple[Any, ...], + heartbeat: Callable[[], None] | None, + heartbeat_interval: float, + should_stop: Callable[[], bool] | None, +) -> Iterator[_R]: + """``parallel_map()``'s loop when no ``parse_timeout`` is set. + + When a worker dies the pool is broken; its other workers are killed + and ``BrokenProcessPool`` propagates for ``parallel_map()`` to convert. + Any other early exit (an exception, a ``KeyboardInterrupt``, the caller + closing the iterator) kills the workers too: they ignore SIGINT, and + leaving the ``with`` block would otherwise wait for the whole window. + """ + with ProcessPoolExecutor( + max_workers=n_procs, + initializer=_init_worker, + initargs=initargs, + ) as executor: + try: window: deque[Future[_R]] = deque() window.append(executor.submit(func, first_job)) @@ -240,5 +855,6 @@ def parallel_map( except StopIteration: continue window.append(executor.submit(func, job)) - - return _generate() + except BaseException: + _kill_workers(executor) + raise diff --git a/parsedmarc/utils.py b/parsedmarc/utils.py index 02fb1f72..74db74d8 100644 --- a/parsedmarc/utils.py +++ b/parsedmarc/utils.py @@ -652,6 +652,12 @@ def _strip_comments(value: str) -> str: return "".join(out) +# Longer than any RFC 5322 date once its comments, which have no length +# limit, are removed. dateutil's time grows with the length of a digit run, +# so a longer string is refused unparsed. +MAX_TIMESTAMP_LENGTH = 128 + + def human_timestamp_to_datetime( human_timestamp: str, *, to_utc: bool = False, assume_utc: bool = False ) -> datetime: @@ -669,10 +675,17 @@ def human_timestamp_to_datetime( Returns: datetime: The converted timestamp + + Raises: + ValueError: The string is longer than ``MAX_TIMESTAMP_LENGTH`` + characters once comments and surrounding whitespace are + removed, or is not a date """ human_timestamp = human_timestamp.replace("-0000", "") human_timestamp = _strip_comments(human_timestamp).strip() + if len(human_timestamp) > MAX_TIMESTAMP_LENGTH: + raise ValueError(f"Timestamp is longer than {MAX_TIMESTAMP_LENGTH} characters") dt = parse_date(human_timestamp) if assume_utc and dt.tzinfo is None: diff --git a/tests/test_attempts.py b/tests/test_attempts.py new file mode 100644 index 00000000..cfe1846f --- /dev/null +++ b/tests/test_attempts.py @@ -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) diff --git a/tests/test_cli.py b/tests/test_cli.py index d24d9953..02c09ee1 100644 --- a/tests/test_cli.py +++ b/tests/test_cli.py @@ -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 diff --git a/tests/test_elastic.py b/tests/test_elastic.py index bbe5f1ab..49dc3be9 100644 --- a/tests/test_elastic.py +++ b/tests/test_elastic.py @@ -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 diff --git a/tests/test_init.py b/tests/test_init.py index 5954831f..45a8f321 100644 --- a/tests/test_init.py +++ b/tests/test_init.py @@ -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 diff --git a/tests/test_opensearch.py b/tests/test_opensearch.py index f34773e7..f92637ab 100644 --- a/tests/test_opensearch.py +++ b/tests/test_opensearch.py @@ -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 diff --git a/tests/test_parallel.py b/tests/test_parallel.py index 34d7be81..eb485d88 100644 --- a/tests/test_parallel.py +++ b/tests/test_parallel.py @@ -2,18 +2,30 @@ import functools import logging +import math +import multiprocessing import os +import pickle +import shutil import tempfile +import time +import types import unittest +from concurrent.futures import ProcessPoolExecutor from unittest.mock import patch import parsedmarc from parsedmarc.parallel import ( + _MAX_ERROR_TEXT, + _email_timeout_result, + _file_timeout_result, _init_worker, _parse_report_email_job, _parse_report_file_job, + _short_error_text, parallel_map, ) +from tests.timing import budget # Stable sample files reused from tests/test_cli.py's TestDirectoryFilePaths, # plus a third plain aggregate sample, so parity/order tests exercise more @@ -244,13 +256,21 @@ class TestInitWorkerLogging(unittest.TestCase): log files it sets the level (configure_logging still ensures a console handler), and with log files it attaches a FileHandler per path. The IP-lookup state and PSL overrides it also restores are passed through - unchanged here so these tests exercise only the logging side.""" + unchanged here so these tests exercise only the logging side. It also + gives SIGTERM its default action and ignores SIGINT, so the test + process's own handlers are put back after each test.""" def setUp(self): + import signal + from parsedmarc.log import logger as plog self._saved_handlers = list(plog.handlers) self._saved_level = plog.level + for name in ("SIGTERM", "SIGINT"): + if hasattr(signal, name): + number = getattr(signal, name) + self.addCleanup(signal.signal, number, signal.getsignal(number)) def tearDown(self): from parsedmarc.log import logger as plog @@ -296,6 +316,302 @@ class TestInitWorkerLogging(unittest.TestCase): for h in file_handlers: h.close() + def test_timed_initializer_keeps_the_start_queue_and_initializes(self): + """The initializer of a pool built for a ``parse_timeout`` stores its + start queue for the jobs and then runs ``_init_worker``. Called here + in the test process, where coverage can see it.""" + import signal + + from parsedmarc import parallel, utils + from parsedmarc.log import logger as plog + + self.addCleanup(setattr, parallel, "_start_queue", parallel._start_queue) + start_queue = multiprocessing.get_context().SimpleQueue() + self.addCleanup(start_queue.close) + parallel._init_timed_worker( + start_queue, + logging.WARNING, + [], + utils._get_ip_worker_state(), + list(utils.psl_overrides), + ) + self.assertIs(parallel._start_queue, start_queue) + self.assertEqual(plog.level, logging.WARNING) + self.assertIs(signal.getsignal(signal.SIGINT), signal.SIG_IGN) + + +class TestRunTimedJob(unittest.TestCase): + """``_run_timed_job`` writes its token to the worker's start queue before + it runs the job, and only runs the job when the worker has no queue. It + leaves the outcome, a value or an exception the job raised, in a file + ``_take_outcome`` reads back unchanged and removes. It runs in a worker, + so it is called here in the test process.""" + + def setUp(self): + from parsedmarc import parallel + + self.addCleanup(setattr, parallel, "_start_queue", parallel._start_queue) + self.result_dir = tempfile.mkdtemp() + self.addCleanup(shutil.rmtree, self.result_dir, ignore_errors=True) + + def test_token_is_put_on_the_start_queue_before_the_job_runs(self): + from parsedmarc import parallel + + start_queue = multiprocessing.get_context().SimpleQueue() + self.addCleanup(start_queue.close) + parallel._start_queue = start_queue + seen_before_the_job = [] + + def job(value): + seen_before_the_job.append(start_queue.get()) + return value * 2 + + self.assertIsNone(parallel._run_timed_job(job, 7, 21, self.result_dir)) + self.assertEqual(seen_before_the_job, [7]) + self.assertTrue(start_queue.empty()) + self.assertEqual(parallel._take_outcome(self.result_dir, 7), 42) + self.assertEqual(os.listdir(self.result_dir), []) + + def test_result_file_that_cannot_be_written_returns_a_directory_marker(self): + from parsedmarc import parallel + + missing = os.path.join(self.result_dir, "missing") + marker = parallel._run_timed_job(lambda value: value, 1, 1, missing) + assert marker is not None, "the job should have reported a failure" + kind, text = marker + self.assertEqual(kind, "directory") + self.assertIn("FileNotFoundError", text) + + def test_unpicklable_result_returns_an_outcome_marker(self): + from parsedmarc import parallel + + marker = parallel._run_timed_job( + lambda value: lambda: value, 2, 2, self.result_dir + ) + assert marker is not None, "the job should have reported a failure" + kind, text = marker + self.assertEqual(kind, "outcome") + self.assertIn("local object", text) + # The failed write leaves no finished result behind. + self.assertNotIn("2", os.listdir(self.result_dir)) + + def test_unreadable_result_file_raises_the_directory_error(self): + from parsedmarc import ParserError, parallel + + os.mkdir(parallel._result_path(self.result_dir, 3)) + with self.assertRaises(ParserError) as caught: + parallel._take_outcome(self.result_dir, 3) + self.assertIn("writable temporary directory", str(caught.exception)) + self.assertIn("Is a directory", str(caught.exception)) + + def test_without_a_start_queue_the_job_just_runs(self): + from parsedmarc import parallel + + parallel._start_queue = None + parallel._run_timed_job(_echo_job, 7, 21, self.result_dir) + self.assertEqual(parallel._take_outcome(self.result_dir, 7), _echo_job(21)) + + def test_an_error_value_travels_unchanged(self): + """The parse jobs return their errors as values, a file job paired + with its path.""" + from parsedmarc import parallel + + parallel._start_queue = None + error = parsedmarc.InvalidDMARCReport("not a report") + parallel._run_timed_job(_echo_job, 3, ("reports/a.xml", error), self.result_dir) + path, value = parallel._take_outcome(self.result_dir, 3) + self.assertEqual(path, "reports/a.xml") + self.assertIs(type(value), parsedmarc.InvalidDMARCReport) + self.assertEqual(str(value), "not a report") + + def test_a_raised_exception_is_raised_again_by_the_reader(self): + from parsedmarc import parallel + + parallel._start_queue = None + parallel._run_timed_job(_raising_job, 4, "boom", self.result_dir) + with self.assertRaises(ValueError) as caught: + parallel._take_outcome(self.result_dir, 4) + self.assertEqual(str(caught.exception), "boom") + + +class TestTimedJobThatRaises(unittest.TestCase): + """A job that raises, rather than returning its error as a value, still + raises out of ``parallel_map`` with a ``parse_timeout``, as it does + without one, after its exception went through the result file.""" + + def test_exception_is_raised_to_the_caller(self): + with self.assertRaises(ValueError) as caught: + list( + parallel_map( + _raising_job, + ["boom"], + 1, + parse_timeout=30.0, + timeout_result=_timeout_value, + ) + ) + self.assertEqual(str(caught.exception), "boom") + self.assertEqual(multiprocessing.active_children(), []) + + +class TestUnwritableTemporaryDirectory(unittest.TestCase): + """With a ``parse_timeout`` the results travel through a temporary + directory. When it cannot be created, or the workers cannot write in + it, ``parallel_map`` raises a ``ParserError`` naming the cause, which + the CLI logs, instead of a raw ``OSError``. Without a timeout no such + directory is used.""" + + _TEXT = "parse_timeout needs a writable temporary directory (TMPDIR)" + + def _timed_run(self): + return list( + parallel_map( + _echo_job, + [1, 2], + 1, + parse_timeout=30.0, + timeout_result=_timeout_value, + ) + ) + + def test_directory_that_cannot_be_created(self): + refusal = PermissionError(13, "Permission denied", "/tmp/parsedmarc-x") + with patch("parsedmarc.parallel.mkdtemp", side_effect=refusal): + with self.assertRaises(parsedmarc.ParserError) as caught: + self._timed_run() + self.assertEqual(list(parallel_map(_echo_job, [1, 2], 1)), [1, 2]) + self.assertIn(self._TEXT, str(caught.exception)) + self.assertIn("Permission denied", str(caught.exception)) + self.assertIs(caught.exception.__cause__, refusal) + + def test_directory_the_workers_cannot_write(self): + if hasattr(os, "geteuid") and os.geteuid() == 0: + self.skipTest("root can write in a read-only directory") + parent = tempfile.mkdtemp() + self.addCleanup(shutil.rmtree, parent, ignore_errors=True) + read_only = os.path.join(parent, "read-only") + os.mkdir(read_only, 0o500) + # The pool removes the directory itself when it stops. + self.addCleanup(lambda: os.path.isdir(read_only) and os.chmod(read_only, 0o700)) + with patch("parsedmarc.parallel.mkdtemp", return_value=read_only): + with self.assertRaises(parsedmarc.ParserError) as caught: + self._timed_run() + self.assertIn(self._TEXT, str(caught.exception)) + self.assertIn("Permission denied", str(caught.exception)) + self.assertEqual(multiprocessing.active_children(), []) + + +def _unpicklable_job(value): + """Return a lambda, which pickle cannot serialise, for ``None``, and + ``value`` otherwise. Module-level so the job itself pickles.""" + if value is None: + return lambda: None + return value + + +class _NeedsTwoArguments(Exception): + """An exception whose pickle does not load: pickling keeps only + ``args`` (one item here), and loading calls the class with them.""" + + def __init__(self, first, second): + super().__init__(f"{first} {second}") + + +class TestOutcomesThatCannotBeHandedBack(unittest.TestCase): + """An outcome the worker cannot pickle, or the parent cannot unpickle, + becomes a ``ParserError`` saying so; the worker never sends it through + the executor, whose message must stay short.""" + + def test_unpicklable_result_raises_parser_error_and_the_pool_goes_on(self): + from parsedmarc import utils + from parsedmarc.parallel import _DeadlinePool + + initargs = (logging.WARNING, [], utils._get_ip_worker_state(), []) + pool = _DeadlinePool(_unpicklable_job, 1, initargs) + self.addCleanup(pool.close) + pending = pool.submit(None) + pending.future.result(timeout=budget(10)) + pool.settle(pending) + with self.assertRaises(parsedmarc.ParserError) as caught: + pending.future.result() + self.assertIn("could not be handed back", str(caught.exception)) + # The pickler's own complaint about the lambda. + self.assertIn("local object", str(caught.exception)) + + following = pool.submit(5) + following.future.result(timeout=budget(10)) + pool.settle(following) + self.assertEqual(following.future.result(), 5) + + def test_result_file_that_does_not_load_raises_parser_error(self): + from parsedmarc import parallel + + result_dir = tempfile.mkdtemp() + self.addCleanup(shutil.rmtree, result_dir, ignore_errors=True) + with open(parallel._result_path(result_dir, 9), "wb") as result_file: + pickle.dump(("value", _NeedsTwoArguments("a", "b")), result_file) + with self.assertRaises(parsedmarc.ParserError) as caught: + parallel._take_outcome(result_dir, 9) + self.assertIn("could not be handed back", str(caught.exception)) + self.assertIn("TypeError", str(caught.exception)) + + +def _raising_job(message): + """Raise ``ValueError(message)``. Module-level so it pickles.""" + raise ValueError(message) + + +class _ExecutorWithoutProcesses: + """An executor without the private ``_processes`` and + ``_executor_manager_thread`` attributes ``_kill_workers`` reads, as a + Python version that dropped them would be. Records its shutdown.""" + + def __init__(self): + self.shutdowns = [] + + def shutdown(self, wait=True, *, cancel_futures=False): + self.shutdowns.append((wait, cancel_futures)) + + +class TestKillWorkersWithoutProcesses(unittest.TestCase): + """Without ``_processes`` the workers cannot be killed: ``_kill_workers`` + warns that they keep running, and still shuts the executor down without + waiting and with its queued jobs cancelled.""" + + def test_warns_and_shuts_down_without_waiting(self): + from parsedmarc.log import logger as plog + from parsedmarc.parallel import _kill_workers + + self.addCleanup(setattr, plog, "disabled", plog.disabled) + plog.disabled = False + executor = _ExecutorWithoutProcesses() + with self.assertLogs("parsedmarc.log", level="WARNING") as logs: + _kill_workers(executor) # pyright: ignore[reportArgumentType] + self.assertIn("Cannot stop the worker processes", "\n".join(logs.output)) + self.assertEqual(executor.shutdowns, [(False, True)]) + + +class TestPlainPoolHeartbeat(unittest.TestCase): + """Without a ``parse_timeout``, a ``heartbeat`` is still called every + ``heartbeat_interval`` seconds while the parent waits for a slow job.""" + + def test_heartbeat_is_called_while_a_plain_job_runs(self): + calls = [] + start = time.monotonic() + results = list( + parallel_map( + _sleep_job, + [0.5], + 1, + heartbeat=lambda: calls.append(time.monotonic()), + heartbeat_interval=0.1, + ) + ) + self.assertEqual(results, [0.5]) + self.assertGreaterEqual(len(calls), 2) + # One pool start and the 0.5 s job; no heartbeat may hold it up. + self.assertLess(time.monotonic() - start, budget(3)) + def _ip_worker_state_job(_): """Read the worker process's IP-lookup state and PSL overrides so a @@ -378,5 +694,679 @@ class TestParseReportEmailJob(_ParallelTestCase): self.assertIsInstance(result, parsedmarc.ParserError) +# parse_timeout tests: a job that sleeps _SLOW seconds stands in for a parse +# that never ends, and _TIMEOUT is far below it, so a test that finishes in +# about _TIMEOUT seconds shows the job was stopped rather than waited for. +_TIMEOUT = 0.5 +_SLOW = 5.0 + + +def _sleep_job(seconds): + """Sleep ``seconds`` and return it. Module-level so it pickles.""" + time.sleep(seconds) + return seconds + + +def _start_queue_unset_job(seconds): + """Sleep ``seconds``, then report whether the worker has no start queue, + which only a pool built for a ``parse_timeout`` gives it. Module-level + so it pickles.""" + from parsedmarc import parallel + + time.sleep(seconds) + return parallel._start_queue is None + + +def _timeout_value(job, seconds): + return ("timed out", job, seconds) + + +class TestParallelMapParseTimeout(unittest.TestCase): + """parse_timeout stops a job that runs too long and yields + timeout_result(job, parse_timeout) in its place. + + Without a timeout each _SLOW job holds the run for its full 5 s. With a + 0.5 s timeout one stop costs the timeout, a wait slice (0.05 s here) + and one pool start (about 0.3 s under spawn on the workstation, a few + milliseconds under fork), so every bound below allows for two pool + starts and stays far under the 5 s the job would take. + """ + + def _run(self, jobs, n_procs, job=_sleep_job, **kwargs): + kwargs.setdefault("parse_timeout", _TIMEOUT) + kwargs.setdefault("timeout_result", _timeout_value) + start = time.monotonic() + results = list(parallel_map(job, jobs, n_procs, **kwargs)) + return results, time.monotonic() - start + + def test_timed_out_job_yields_timeout_value_in_order(self): + results, elapsed = self._run([0.0, _SLOW, 0.1, 0.2], n_procs=2) + self.assertEqual(results, [0.0, ("timed out", _SLOW, _TIMEOUT), 0.1, 0.2]) + self.assertLess(elapsed, budget(4)) + + def test_timeout_of_first_job_resubmits_the_rest(self): + """With one worker the later jobs are still queued when the first + times out; the pool they were queued in is killed, so they must be + submitted again to the new pool.""" + results, elapsed = self._run([_SLOW, 0.0, 0.1], n_procs=1) + self.assertEqual(results, [("timed out", _SLOW, _TIMEOUT), 0.0, 0.1]) + self.assertLess(elapsed, budget(4)) + + def test_two_consecutive_timeouts_with_one_process(self): + """The second slow job times out in the rebuilt pool too, and its + clock starts only once it runs, so the run takes at least two + timeouts.""" + results, elapsed = self._run([_SLOW, _SLOW, 0.0], n_procs=1) + timed_out = ("timed out", _SLOW, _TIMEOUT) + self.assertEqual(results, [timed_out, timed_out, 0.0]) + self.assertGreaterEqual(elapsed, 2 * _TIMEOUT) + self.assertLess(elapsed, budget(6)) + + def test_job_waiting_behind_a_slow_neighbour_is_not_charged_for_the_wait(self): + """ProcessPoolExecutor marks one job more than it has workers as + running, so with one worker the second job reads as running from the + start. Both jobs here finish within the timeout; timing the second + from when its future first reads as running stopped it after 1.0 s, + 0.3 s before it would have finished.""" + results, elapsed = self._run([0.7, 0.7], n_procs=1, parse_timeout=1.0) + self.assertEqual(results, [0.7, 0.7]) + self.assertLess(elapsed, budget(4)) + + def test_heartbeat_is_called_during_a_long_job(self): + beats = [] + results, elapsed = self._run( + [1.0], + n_procs=1, + parse_timeout=3.0, + heartbeat=lambda: beats.append(time.monotonic()), + heartbeat_interval=0.1, + ) + self.assertEqual(results, [1.0]) + # About ten in the 1 s the job runs; five leaves room for a slow + # pool start, which no heartbeat waits on. + self.assertGreaterEqual(len(beats), 5) + self.assertLess(elapsed, budget(4)) + + def test_zero_timeout_means_no_deadline(self): + """With parse_timeout 0 a job runs in the plain pool, whose workers + never get a start queue, and finishes; the same probe under a + timeout reads the queue, so it can tell the two pools apart.""" + results, elapsed = self._run( + [0.3], n_procs=1, job=_start_queue_unset_job, parse_timeout=0.0 + ) + self.assertEqual(results, [True]) + self.assertGreaterEqual(elapsed, 0.3) + results, _ = self._run( + [0.3], n_procs=1, job=_start_queue_unset_job, parse_timeout=30.0 + ) + self.assertEqual(results, [False]) + + def test_invalid_timeout_arguments_raise_eagerly(self): + for parse_timeout in (-1.0, math.nan, math.inf): + with self.subTest(parse_timeout=parse_timeout): + with self.assertRaises(ValueError): + parallel_map( + _sleep_job, + [0.0], + 1, + parse_timeout=parse_timeout, + timeout_result=_timeout_value, + ) + with self.assertRaises(ValueError): + parallel_map(_sleep_job, [0.0], 1, parse_timeout=_TIMEOUT) + + def test_timed_out_workers_are_reaped_under_every_start_method(self): + """The killed worker is gone when parallel_map returns, rather than + sleeping on for the rest of its 5 s. Stopping it needs the + executor's private ``_processes`` mapping; if a Python version drops + it, this test fails instead of the worker silently surviving.""" + self.assertIsInstance(ProcessPoolExecutor(max_workers=1)._processes, dict) + original_method = multiprocessing.get_start_method() + self.addCleanup(multiprocessing.set_start_method, original_method, force=True) + before = set(multiprocessing.active_children()) + for method in multiprocessing.get_all_start_methods(): + with self.subTest(start_method=method): + multiprocessing.set_start_method(method, force=True) + results, elapsed = self._run([_SLOW], n_procs=1) + self.assertEqual(results, [("timed out", _SLOW, _TIMEOUT)]) + self.assertLess(elapsed, budget(3)) + self.assertLessEqual(set(multiprocessing.active_children()), before) + + def test_should_stop_ends_iteration_early_with_a_timeout(self): + jobs = _CountingIterable(20) + results = list( + parallel_map( + _echo_job, + jobs, + 2, + should_stop=lambda: True, + parse_timeout=_TIMEOUT, + timeout_result=_timeout_value, + ) + ) + self.assertLess(len(results), 20) + self.assertLess(jobs.pulled, 20) + self.assertEqual(results, list(range(len(results)))) + + def test_leaving_early_kills_the_pool(self): + """An exception out of the loop (here from the heartbeat) ends the + run at once instead of waiting for the running job.""" + before = set(multiprocessing.active_children()) + + def failing_heartbeat(): + raise RuntimeError("connection lost") + + start = time.monotonic() + with self.assertRaises(RuntimeError): + self._run( + [_SLOW], + n_procs=1, + parse_timeout=30.0, + heartbeat=failing_heartbeat, + heartbeat_interval=0.1, + ) + self.assertLess(time.monotonic() - start, budget(3)) + self.assertLessEqual(set(multiprocessing.active_children()), before) + + def test_closing_the_iterator_kills_the_pool(self): + """A caller that stops reading and closes the iterator ends the run + at once: the workers still running a slow job are killed instead + of waited for, and the pool's start queue is closed.""" + from parsedmarc.parallel import _DeadlinePool + + start_queues = [] + new_executor = _DeadlinePool._new_executor + + def recording_new_executor(pool): + executor, start_queue, result_dir = new_executor(pool) + start_queues.append(start_queue) + return executor, start_queue, result_dir + + before = set(multiprocessing.active_children()) + with patch.object(_DeadlinePool, "_new_executor", recording_new_executor): + results = parallel_map( + _sleep_job, + [0.0, _SLOW, _SLOW], + 2, + parse_timeout=30.0, + timeout_result=_timeout_value, + ) + # parallel_map is typed to return an Iterator; it is a generator. + assert isinstance(results, types.GeneratorType) + self.assertEqual(next(results), 0.0) + start = time.monotonic() + results.close() + self.assertLess(time.monotonic() - start, budget(3)) + self.assertLessEqual(set(multiprocessing.active_children()), before) + self.assertEqual(len(start_queues), 1) + self.assertTrue(start_queues[0]._reader.closed) + self.assertTrue(start_queues[0]._writer.closed) + + +class TestPlainPoolEarlyExit(unittest.TestCase): + """Without a ``parse_timeout`` the pool is a plain + ``ProcessPoolExecutor``, whose ``with`` block waits for every job in the + window on the way out. Workers ignore SIGINT, so a caller that leaves + early (a ``KeyboardInterrupt``, closing the iterator) would wait for the + whole window; the workers are killed instead.""" + + def test_closing_the_iterator_kills_the_workers(self): + """Before the fix the close waited for both slow jobs, 5.0 s on the + workstation.""" + before = set(multiprocessing.active_children()) + results = parallel_map(_sleep_job, [0.0, _SLOW, _SLOW], 2) + # parallel_map is typed to return an Iterator; it is a generator. + assert isinstance(results, types.GeneratorType) + self.assertEqual(next(results), 0.0) + start = time.monotonic() + results.close() + self.assertLess(time.monotonic() - start, budget(3)) + self.assertLessEqual(set(multiprocessing.active_children()), before) + + +class TestStartTokensAreDrained(unittest.TestCase): + """With a ``parse_timeout`` the pool maps each job's start token to its + entry, input included, until the parent reads the token. When results + are already done at harvest time the parent never waits, so the tokens + must still be read every round, or the map keeps every finished job's + input and outgrows the submission window.""" + + def test_token_map_stays_within_the_window(self): + """The caller pauses after each result, so every later result is + done before it is harvested. Bound: the window, plus the job just + harvested, whose token may arrive after the last read. Before the + fix the map held every job of the run (200 entries for 200 jobs).""" + from parsedmarc.parallel import _DeadlinePool + + sizes = [] + resubmit = _DeadlinePool.resubmit + + def recording_resubmit(pool, pending): + resubmit(pool, pending) + sizes.append(len(pool._by_token)) + + n_procs = 2 + window_size = 2 * n_procs + results = [] + with patch.object(_DeadlinePool, "resubmit", recording_resubmit): + for result in parallel_map( + _echo_job, + range(200), + n_procs, + parse_timeout=5.0, + timeout_result=_timeout_value, + ): + results.append(result) + time.sleep(0.005) + self.assertEqual(results, list(range(200))) + self.assertEqual(len(sizes), 200) + self.assertLessEqual(max(sizes), window_size + 1) + + +def _slow_or_large_job(job): + """``("sleep", seconds)`` sleeps and returns ``seconds``. ``("slow", + marker)`` writes the time it started to the file ``marker`` and sleeps + for a minute. ``("large", marker, offset, size)`` waits for ``marker`` + and returns ``size`` bytes ``offset`` seconds after the time in it, so + that handing them back spans the moment the slow job's timeout kills + the workers. Module-level so it pickles.""" + if job[0] == "sleep": + time.sleep(job[1]) + return job[1] + if job[0] == "slow": + with open(job[1] + ".tmp", "w") as marker: + marker.write(repr(time.time())) + os.replace(job[1] + ".tmp", job[1]) + time.sleep(60) + return None + _, marker_path, offset, size = job + deadline = time.monotonic() + 30 + while not os.path.exists(marker_path) and time.monotonic() < deadline: + time.sleep(0.005) + with open(marker_path) as marker: + slow_started = float(marker.read()) + payload = b"x" * size + time.sleep(max(0.0, slow_started + offset - time.time())) + return payload + + +def _kill_during_large_result_jobs(marker_path, size): + """The jobs of a run in which a 0.5 s ``parse_timeout`` kills the + workers while the large job hands back its result. The large job runs + after a short one, so it has run only about 0.2 s when the slow job + expires and is not itself overdue; it returns 0.4 s after the slow job + started, and pickling and sending its result take longer than the + remaining 0.1 s.""" + return [("slow", marker_path), ("sleep", 0.3), ("large", marker_path, 0.4, size)] + + +# Run by TestKillDuringResultTransmission in a child interpreter. The start +# method, a marker file path and the result size are the arguments. +_KILL_DURING_LARGE_RESULT_SCRIPT = """ +import multiprocessing +import sys + +from parsedmarc.parallel import parallel_map +from tests.test_parallel import ( + _kill_during_large_result_jobs, _slow_or_large_job, _timeout_value, +) + +if __name__ == "__main__": + multiprocessing.set_start_method(sys.argv[1], force=True) + size = int(sys.argv[3]) + jobs = _kill_during_large_result_jobs(sys.argv[2], size) + results = list( + parallel_map( + _slow_or_large_job, jobs, 2, parse_timeout=0.5, + timeout_result=_timeout_value, + ) + ) + assert results[:2] == [_timeout_value(jobs[0], 0.5), 0.3], results[:2] + assert len(results[2]) == size + print("done", flush=True) +""" + + +class TestKillDuringResultTransmission(unittest.TestCase): + """A timeout kills every worker, so it can kill one while it hands back + a large result. Sent through the executor's own pipe, the cut-off result + left the executor's management thread waiting for the rest forever, and + the interpreter then hung at exit joining that thread. Results now + travel through files, and every start method is tried.""" + + def _start_methods(self): + original_method = multiprocessing.get_start_method() + self.addCleanup(multiprocessing.set_start_method, original_method, force=True) + return [ + m + for m in ("fork", "forkserver", "spawn") + if m in multiprocessing.get_all_start_methods() + ] + + def test_large_result_survives_a_neighbour_timeout(self): + from parsedmarc import parallel + + size = 128 * 1024 * 1024 + managers = [] + kill_workers = parallel._kill_workers + + def recording_kill_workers(executor): + manager = getattr(executor, "_executor_manager_thread", None) + kill_workers(executor) + managers.append(manager) + + for method in self._start_methods(): + with self.subTest(start_method=method): + multiprocessing.set_start_method(method, force=True) + managers.clear() + marker_dir = tempfile.mkdtemp() + self.addCleanup(shutil.rmtree, marker_dir, ignore_errors=True) + marker_path = os.path.join(marker_dir, "slow-started") + jobs = _kill_during_large_result_jobs(marker_path, size) + start = time.monotonic() + with patch.object(parallel, "_kill_workers", recording_kill_workers): + results = list( + parallel_map( + _slow_or_large_job, + jobs, + 2, + parse_timeout=0.5, + timeout_result=_timeout_value, + ) + ) + # A timeout, at most one re-run of the large job and two pool + # starts; the slow job alone would take a minute. + self.assertLess(time.monotonic() - start, budget(10)) + self.assertEqual(results[:2], [_timeout_value(jobs[0], 0.5), 0.3]) + large = results[2] + assert isinstance(large, bytes) + self.assertEqual(len(large), size) + self.assertEqual(large.count(b"x"), size) + self.assertGreaterEqual(len(managers), 1) + for manager in managers: + self.assertFalse(manager is not None and manager.is_alive()) + self.assertEqual(multiprocessing.active_children(), []) + + def test_interpreter_exits_after_a_kill_during_a_large_result(self): + """Before the fix the child interpreter never exited (killed after + 25 s on the workstation, with a 400 MiB result).""" + import subprocess + import sys + + for method in self._start_methods(): + with self.subTest(start_method=method): + marker_dir = tempfile.mkdtemp() + self.addCleanup(shutil.rmtree, marker_dir, ignore_errors=True) + limit = budget(30) + start = time.monotonic() + completed = subprocess.run( + [ + sys.executable, + "-c", + _KILL_DURING_LARGE_RESULT_SCRIPT, + method, + os.path.join(marker_dir, "slow-started"), + str(256 * 1024 * 1024), + ], + capture_output=True, + text=True, + timeout=limit, + ) + self.assertEqual(completed.returncode, 0, completed.stderr) + self.assertEqual(completed.stdout.strip(), "done") + self.assertLess(time.monotonic() - start, limit) + + +class TestResultFilesAreRemoved(unittest.TestCase): + """The pool built for a timeout keeps results in a directory of its + own, removed with every file left in it when the pool is closed or + killed.""" + + def _pool(self): + from parsedmarc import utils + from parsedmarc.parallel import _DeadlinePool + + initargs = (logging.WARNING, [], utils._get_ip_worker_state(), []) + return _DeadlinePool(_sleep_job, 1, initargs) + + def test_close_removes_the_result_directory(self): + pool = self._pool() + pending = pool.submit(0.0) + pending.future.result(timeout=budget(10)) + result_dir = pool.result_dir + self.assertEqual(os.listdir(result_dir), ["0"]) + pool.close() + self.assertFalse(os.path.exists(result_dir)) + + def test_kill_removes_the_result_directory_and_its_files(self): + pool = self._pool() + pool.submit(0.0).future.result(timeout=budget(10)) + pool.submit(_SLOW) + result_dir = pool.result_dir + self.assertEqual(os.listdir(result_dir), ["0"]) + pool.kill() + self.assertFalse(os.path.exists(result_dir)) + self.assertEqual(multiprocessing.active_children(), []) + + +class TestTimeoutResults(unittest.TestCase): + """The values parallel_map yields for a timed-out email or file job have + the shapes the callers handle for an unparseable input.""" + + def test_email_timeout_result_is_an_invalid_dmarc_report(self): + result = _email_timeout_result(b"message", 300.0) + self.assertIsInstance(result, parsedmarc.ParseTimeoutError) + self.assertIsInstance(result, parsedmarc.InvalidDMARCReport) + self.assertIn("300 seconds", str(result)) + + def test_file_timeout_result_pairs_the_path_with_the_error(self): + file_path, error = _file_timeout_result("reports/a.xml", 2.5) + self.assertEqual(file_path, "reports/a.xml") + self.assertIsInstance(error, parsedmarc.ParseTimeoutError) + self.assertIn("2.5 seconds", str(error)) + + +def _signal_handler_job(signal_name): + """Report whether the worker's handler for ``signal_name`` is the + default (``"default"``), ignores it (``"ignored"``) or is something else. + Module-level so it pickles.""" + import signal + + handler = signal.getsignal(getattr(signal, signal_name)) + if handler is signal.SIG_DFL: + return "default" + if handler is signal.SIG_IGN: + return "ignored" + return "other" + + +def _parent_signal_handler(signum, frame): + """A handler that, like the CLI's, only notes the signal.""" + + +def _use_fork(test): + """Switch ``test`` to the ``fork`` start method, or skip it.""" + if "fork" not in multiprocessing.get_all_start_methods(): + test.skipTest("the fork start method is not available") + original_method = multiprocessing.get_start_method() + test.addCleanup(multiprocessing.set_start_method, original_method, force=True) + multiprocessing.set_start_method("fork", force=True) + + +class TestWorkerSignalHandlers(unittest.TestCase): + """Under ``fork`` a worker inherits the parent's signal handlers. The + CLI installs SIGTERM and SIGINT handlers that only set a flag, so a + worker running them ignores the SIGTERM ``ProcessPoolExecutor`` sends + when it tears down a broken pool, and the teardown waits for it + forever. The pool initializer restores the default SIGTERM action and + ignores SIGINT, which the parent coordinates, in the plain pool and in + the pool built for a ``parse_timeout``.""" + + def test_workers_take_sigterm_and_ignore_sigint_under_fork(self): + import signal + + _use_fork(self) + names = [n for n in ("SIGTERM", "SIGINT") if hasattr(signal, n)] + for name in names: + number = getattr(signal, name) + self.addCleanup(signal.signal, number, signal.getsignal(number)) + signal.signal(number, _parent_signal_handler) + expected = {"SIGTERM": "default", "SIGINT": "ignored"} + + for kwargs in ({}, {"parse_timeout": 30.0, "timeout_result": _timeout_value}): + with self.subTest(**kwargs): + results = list( + parallel_map(_signal_handler_job, names, n_procs=1, **kwargs) + ) + self.assertEqual( + dict(zip(names, results)), {n: expected[n] for n in names} + ) + + def test_ctrl_c_lets_the_running_jobs_finish_under_every_start_method(self): + """A terminal sends Ctrl-C's SIGINT to every process in its + foreground process group, the workers included. The parent's handler + (here, as in the CLI, one that only notes the signal) lets the batch + finish, so the workers must survive the signal too; with the default + action each worker died and the run ended in ``BrokenProcessPool``. + Each job writes its worker's pid as it starts, and the signal goes + out once every worker has one, so a spawned worker's initializer has + run. The test signals the parent and each worker itself rather than + its whole process group, which holds the test runner too.""" + import signal + import threading + + n_procs = 2 + received = [] + self.addCleanup(signal.signal, signal.SIGINT, signal.getsignal(signal.SIGINT)) + signal.signal(signal.SIGINT, lambda signum, frame: received.append(signum)) + original_method = multiprocessing.get_start_method() + self.addCleanup(multiprocessing.set_start_method, original_method, force=True) + available = multiprocessing.get_all_start_methods() + + for method in ("fork", "forkserver", "spawn"): + for kwargs in ( + {}, + {"parse_timeout": 30.0, "timeout_result": _timeout_value}, + ): + with self.subTest(start_method=method, **kwargs): + if method not in available: + self.skipTest(f"the {method} start method is not available") + multiprocessing.set_start_method(method, force=True) + received.clear() + pid_dir = tempfile.mkdtemp() + self.addCleanup(shutil.rmtree, pid_dir, ignore_errors=True) + signalled = [] + + def interrupt(pid_dir=pid_dir, signalled=signalled): + deadline = time.monotonic() + 30.0 + pids = [] + while time.monotonic() < deadline: + pids = os.listdir(pid_dir) + if len(pids) >= n_procs: + break + time.sleep(0.05) + for pid in pids: + os.kill(int(pid), signal.SIGINT) + signalled.append(pid) + os.kill(os.getpid(), signal.SIGINT) + + timer = threading.Thread(target=interrupt) + timer.start() + jobs = [(pid_dir, 2.0)] * n_procs + try: + results = list( + parallel_map( + _pid_marking_sleep_job, jobs, n_procs, **kwargs + ) + ) + except KeyboardInterrupt: + # A worker that took the signal returns its + # KeyboardInterrupt as the job's outcome. + results = ["KeyboardInterrupt in a worker"] + finally: + timer.join() + self.assertEqual(len(set(signalled)), n_procs) + self.assertEqual(results, [2.0] * n_procs) + self.assertEqual(received, [signal.SIGINT]) + + +def _pid_marking_sleep_job(job): + """Write this worker's pid as a file name under ``job[0]``, then sleep + ``job[1]`` seconds and return it. Module-level so it pickles.""" + pid_dir, seconds = job + with open(os.path.join(pid_dir, str(os.getpid())), "w"): + pass + time.sleep(seconds) + return seconds + + +def _exit_job(value): + """End the worker process at once when ``value`` is ``"exit"``, as the + out-of-memory killer or a crash would; otherwise sleep ``value`` + seconds and return it. Module-level so it pickles.""" + if value == "exit": + os._exit(1) + time.sleep(value) + return value + + +class TestWorkerDeath(unittest.TestCase): + """A worker process that dies breaks the pool, and + ``ProcessPoolExecutor`` then fails every unfinished job with + ``BrokenProcessPool``. ``parallel_map`` raises ``ParserError`` from it, + promptly, and leaves no worker behind, in the plain pool and in the pool + built for a ``parse_timeout``. Without the conversion the + ``BrokenProcessPool`` escaped to the caller, which handles only + ``ParserError``.""" + + def test_dying_worker_raises_parser_error(self): + from concurrent.futures.process import BrokenProcessPool + + methods = [ + m + for m in ("fork", "forkserver") + if m in multiprocessing.get_all_start_methods() + ] + original_method = multiprocessing.get_start_method() + self.addCleanup(multiprocessing.set_start_method, original_method, force=True) + for method in methods: + for kwargs in ( + {}, + {"parse_timeout": 30.0, "timeout_result": _timeout_value}, + ): + with self.subTest(start_method=method, **kwargs): + multiprocessing.set_start_method(method, force=True) + before = set(multiprocessing.active_children()) + start = time.monotonic() + with self.assertRaises(parsedmarc.ParserError) as caught: + list( + parallel_map( + _exit_job, [0.1, "exit", 0.1, 0.1], 2, **kwargs + ) + ) + # About a pool start; the 30 s timeout plays no part. + self.assertLess(time.monotonic() - start, budget(5)) + self.assertIn("worker process died", str(caught.exception)) + self.assertIsInstance(caught.exception.__cause__, BrokenProcessPool) + self.assertLessEqual(set(multiprocessing.active_children()), before) + + if __name__ == "__main__": unittest.main(verbosity=2) + + +class _BrokenStr(Exception): + def __str__(self) -> str: + raise RuntimeError("no text") + + +class TestShortErrorText(unittest.TestCase): + """The error text a worker hands back fits the pipe's atomic-write bound.""" + + def test_cap_is_in_bytes_not_characters(self): + text = _short_error_text(ValueError("\u00e9" * 300)) + self.assertLessEqual(len(text.encode("utf-8")), _MAX_ERROR_TEXT) + self.assertTrue(text.startswith("ValueError: \u00e9")) + + def test_broken_str_falls_back_to_the_type_name(self): + self.assertEqual(_short_error_text(_BrokenStr()), "_BrokenStr") diff --git a/tests/test_utils.py b/tests/test_utils.py index c7543c42..b0851fe3 100644 --- a/tests/test_utils.py +++ b/tests/test_utils.py @@ -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"""