mirror of
https://github.com/domainaware/parsedmarc.git
synced 2026-07-16 13:34:56 +00:00
Make Microsoft Graph connection activity observable (#815)
* Make Microsoft Graph connection activity observable parsedmarc only configured its own logger, so all Graph connection activity was silently dropped even with --debug: the mailbox layer logs under mailsuite.mailbox.graph, token acquisition under azure.identity (including the AADSTS error codes that distinguish a local config problem from an Exchange Online / Entra ID one), and HTTP traffic under httpx/msgraph — none of which had a handler or level set. _main() also logged nothing around the MSGraphConnection call, so a hang left no trace at all. Three changes, all parsedmarc-side (no mailsuite changes needed): - Log a redacted connection summary at INFO before connecting (auth method, tenant ID, client ID, mailbox, Graph URL) plus a --debug detail line with certificate path, token-file path, and set/not-set flags for secrets. Secret values are never logged; a regression test asserts they don't appear in captured output. - Log a timing line after the connection object is initialized. - Propagate parsedmarc's --verbose/--debug level and handlers to the dependency loggers (mailsuite, azure, msgraph, httpx, httpcore) via _configure_dependency_logging(), synced to exactly the parsedmarc logger's handlers so SIGHUP log-file swaps neither duplicate output nor write to closed handlers. At the default level dependency loggers sit at WARNING, so their warnings keep surfacing (formatted) without new noise. All four new tests fail on the unfixed code (verified by stashing the cli.py change). Fixes https://github.com/domainaware/parsedmarc/issues/814. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> * Disable propagation on dependency loggers; document kiota's absence Set propagate=False on the dependency loggers when syncing handlers, so a stray logging.basicConfig() anywhere in the process cannot double-print every dependency record through the root logger — the function already owns these loggers' handler lists, and this makes that ownership complete. Asserted alongside the existing level/handler checks. kiota_http and its sibling packages were considered for _DEPENDENCY_LOGGERS but verified to not use Python logging at all (their observability is OpenTelemetry tracing), so a comment now records why they are absent rather than leaving the omission to be "fixed" later. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> --------- Co-authored-by: MISAPOR LAB <misapor@lab.misapor.pl> Co-authored-by: Claude Fable 5 <noreply@anthropic.com> Co-authored-by: Sean Whalen <44679+seanthegeek@users.noreply.github.com>
This commit is contained in:
Kili
co-authored by
MISAPOR LAB
Claude Fable 5
Sean Whalen
MISAPOR LAB
Claude Fable 5
Sean Whalen
parent
7fed72798a
commit
3fda55d385
@@ -2,6 +2,13 @@
|
||||
|
||||
## Unreleased
|
||||
|
||||
### Changes
|
||||
|
||||
- **Microsoft Graph connections are now observable** ([#814](https://github.com/domainaware/parsedmarc/issues/814)). Previously `--debug` showed nothing about Graph connection activity: the mailbox layer logs under `mailsuite.mailbox.graph`, token acquisition under `azure.identity`, and HTTP traffic under `httpx`/`msgraph` — none of which parsedmarc configured, so everything below WARNING was silently dropped, and `_main()` logged nothing around the connection attempt itself. Now:
|
||||
- A **redacted connection summary** is logged at INFO before connecting (auth method, tenant ID, client ID, mailbox, Graph URL), with a `--debug` detail line adding the certificate path, token-file path, and set/not-set flags for secrets. Secret values (passwords, client secrets, certificate passwords, client assertions) are never logged, and a regression test asserts they don't appear in captured output.
|
||||
- A timing line (`Microsoft Graph connection initialized in N seconds`) is logged after the connection object is created.
|
||||
- parsedmarc's `--verbose`/`--debug` level now **propagates to the dependency loggers** (`mailsuite`, `azure`, `msgraph`, `httpx`, `httpcore`), so `--debug` surfaces azure-identity's token-endpoint activity — including the `AADSTS` error codes that distinguish a local config problem from an Exchange Online / Entra ID one — and the Graph SDK's HTTP requests. At the default level, dependency loggers sit at WARNING so their warnings keep surfacing (now formatted) without new noise. This also benefits the IMAP backend, which lives in mailsuite too.
|
||||
|
||||
### Bug fixes
|
||||
|
||||
- **Failure-report timestamps are no longer skewed by the host's UTC offset in the Elasticsearch, OpenSearch, and Splunk HEC outputs** ([#811](https://github.com/domainaware/parsedmarc/issues/811), bug 1). `arrival_date_utc` is a UTC wall-clock string, but the three sinks parsed it into a naive `datetime` and called `.timestamp()`, which per the Python docs interprets naive values as *local* time — so on any non-UTC host, the epoch stored as the ES/OpenSearch `arrival_date` field, used in the failure-report dedup query, and sent as the Splunk HEC event `time` was off by the host's UTC offset (1–2 h for most of Europe). `human_timestamp_to_datetime()` / `human_timestamp_to_unix_timestamp()` gained an `assume_utc` keyword that attaches `timezone.utc` to naive parses, and the `arrival_date_utc` consumers now use it.
|
||||
|
||||
@@ -263,6 +263,18 @@ The full set of configuration options are:
|
||||
username, you must grant the app `Mail.ReadWrite.Shared`.
|
||||
:::
|
||||
|
||||
:::{tip}
|
||||
**Troubleshooting connections.** Run with `--verbose` to log a
|
||||
redacted connection summary (auth method, tenant, client ID,
|
||||
mailbox, Graph URL) before the connection attempt, and with
|
||||
`--debug` to additionally surface the underlying library activity —
|
||||
`azure.identity` token acquisition (including `AADSTS` error codes
|
||||
from Entra ID, which distinguish a local configuration problem from
|
||||
an Exchange Online-side one), Microsoft Graph SDK requests, and
|
||||
`httpx` HTTP request lines. Secret values (passwords, client
|
||||
secrets, certificate passwords) are never written to logs.
|
||||
:::
|
||||
|
||||
:::{warning}
|
||||
If you are using the `ClientSecret` auth method, you need to
|
||||
grant the `Mail.ReadWrite` (application) permission to the
|
||||
|
||||
+83
-1
@@ -317,6 +317,51 @@ def _configure_logging(log_level, log_file=None):
|
||||
logger.warning("Unable to write to log file: {}".format(error))
|
||||
|
||||
|
||||
# Loggers of the libraries that implement the mailbox and Microsoft Graph
|
||||
# layers. parsedmarc only configures its own logger, so without this list
|
||||
# their records — including azure-identity's AADSTS token-endpoint errors,
|
||||
# which are what distinguish a local config problem from an Exchange
|
||||
# Online / Entra ID one — are silently dropped even with --debug.
|
||||
# The Graph SDK's kiota middleware (kiota_http etc.) is deliberately
|
||||
# absent: it does not use Python logging (its observability is
|
||||
# OpenTelemetry tracing), so there are no records to enable.
|
||||
_DEPENDENCY_LOGGERS = (
|
||||
"mailsuite",
|
||||
"azure",
|
||||
"msgraph",
|
||||
"httpx",
|
||||
"httpcore",
|
||||
)
|
||||
|
||||
|
||||
def _configure_dependency_logging(level: int) -> None:
|
||||
"""Apply parsedmarc's logging verbosity to dependency loggers.
|
||||
|
||||
Follows the parsedmarc log level when ``--verbose``/``--debug`` makes it
|
||||
more verbose than WARNING, and stays at WARNING otherwise, so dependency
|
||||
warnings keep surfacing without adding noise at the default level.
|
||||
|
||||
Handlers are synced to exactly the parsedmarc logger's own handlers
|
||||
(console and optional file), so dependency records reach the same
|
||||
destinations, and a SIGHUP reload that swaps the log file neither
|
||||
duplicates output nor keeps writing to a closed handler. Propagation
|
||||
to the root logger is disabled so that a stray ``logging.basicConfig()``
|
||||
anywhere in the process cannot double-print every dependency record.
|
||||
CLI-only: library consumers configure logging themselves.
|
||||
"""
|
||||
dep_level = min(level, logging.WARNING)
|
||||
for name in _DEPENDENCY_LOGGERS:
|
||||
dep_logger = logging.getLogger(name)
|
||||
dep_logger.setLevel(dep_level)
|
||||
dep_logger.propagate = False
|
||||
for existing in list(dep_logger.handlers):
|
||||
if existing not in logger.handlers:
|
||||
dep_logger.removeHandler(existing)
|
||||
for wanted in logger.handlers:
|
||||
if wanted not in dep_logger.handlers:
|
||||
dep_logger.addHandler(wanted)
|
||||
|
||||
|
||||
def cli_parse(
|
||||
file_path,
|
||||
sa,
|
||||
@@ -2110,6 +2155,7 @@ def _main():
|
||||
logger.warning("Unable to write to log file: {}".format(error))
|
||||
|
||||
opts.active_log_file = opts.log_file
|
||||
_configure_dependency_logging(logger.level)
|
||||
|
||||
if (
|
||||
opts.imap_host is None
|
||||
@@ -2391,7 +2437,34 @@ def _main():
|
||||
if opts.graph_client_id:
|
||||
try:
|
||||
mailbox = opts.graph_mailbox or opts.graph_user
|
||||
logger.info("Connecting to Microsoft Graph mailbox %s", mailbox)
|
||||
# Redacted connection summary: enough to spot a wrong
|
||||
# tenant/client/mailbox at a glance, before any network I/O,
|
||||
# so a hang during credential construction leaves a trace.
|
||||
# Secret values are never logged.
|
||||
logger.info(
|
||||
"Connecting to Microsoft Graph (auth_method=%s, tenant_id=%s, "
|
||||
"client_id=%s, mailbox=%s, graph_url=%s)",
|
||||
opts.graph_auth_method,
|
||||
opts.graph_tenant_id,
|
||||
opts.graph_client_id,
|
||||
mailbox,
|
||||
opts.graph_url,
|
||||
)
|
||||
logger.debug(
|
||||
"Microsoft Graph auth details: username=%s, "
|
||||
"certificate_path=%s, certificate_password %s, "
|
||||
"client_secret %s, password %s, client_assertion %s, "
|
||||
"token_file=%s, allow_unencrypted_storage=%s",
|
||||
opts.graph_user,
|
||||
opts.graph_certificate_path,
|
||||
"set" if opts.graph_certificate_password else "not set",
|
||||
"set" if opts.graph_client_secret else "not set",
|
||||
"set" if opts.graph_password else "not set",
|
||||
"set" if opts.graph_client_assertion else "not set",
|
||||
opts.graph_token_file,
|
||||
bool(opts.graph_allow_unencrypted_storage),
|
||||
)
|
||||
connect_start = time.monotonic()
|
||||
mailbox_connection = MSGraphConnection(
|
||||
auth_method=opts.graph_auth_method,
|
||||
mailbox=mailbox,
|
||||
@@ -2408,6 +2481,13 @@ def _main():
|
||||
graph_url=opts.graph_url,
|
||||
token_cache_name="parsedmarc",
|
||||
)
|
||||
# App-only methods (ClientSecret/Certificate) construct their
|
||||
# credential lazily; the first token request happens on the
|
||||
# first mailbox call, so failures can still surface later.
|
||||
logger.info(
|
||||
"Microsoft Graph connection initialized in %.2f seconds",
|
||||
time.monotonic() - connect_start,
|
||||
)
|
||||
|
||||
except Exception:
|
||||
logger.exception("MS Graph Error")
|
||||
@@ -2694,6 +2774,8 @@ def _main():
|
||||
)
|
||||
opts.active_log_file = new_log_file
|
||||
|
||||
_configure_dependency_logging(logger.level)
|
||||
|
||||
logger.info("Configuration reloaded successfully")
|
||||
except Exception:
|
||||
logger.exception(
|
||||
|
||||
+150
-20
@@ -3,6 +3,7 @@ env-var overrides, mailbox watch wiring, and SIGHUP reload."""
|
||||
|
||||
import io
|
||||
import json
|
||||
import logging
|
||||
import os
|
||||
import signal
|
||||
import sys
|
||||
@@ -1657,45 +1658,174 @@ certificate_path = /tmp/msgraph-cert.pem
|
||||
mock_graph_connection.assert_not_called()
|
||||
mock_get_mailbox_reports.assert_not_called()
|
||||
|
||||
|
||||
class TestMSGraphConnectionLogging(unittest.TestCase):
|
||||
"""MS Graph connection observability (issue #814): a redacted
|
||||
connection summary is logged before connecting, timing after, secret
|
||||
values never appear in log output, and the dependency loggers that
|
||||
carry the actual auth/HTTP activity (mailsuite, azure, msgraph,
|
||||
httpx, httpcore) follow parsedmarc's --verbose/--debug level."""
|
||||
|
||||
CERT_CONFIG = """[general]
|
||||
silent = true
|
||||
|
||||
[msgraph]
|
||||
auth_method = Certificate
|
||||
client_id = client-id-1234
|
||||
tenant_id = tenant-id-5678
|
||||
mailbox = shared@example.com
|
||||
certificate_path = /tmp/msgraph-cert.pem
|
||||
certificate_password = s3cret-cert-pass
|
||||
"""
|
||||
|
||||
def setUp(self):
|
||||
# _configure_dependency_logging mutates process-global loggers;
|
||||
# snapshot and restore their levels and handlers so these tests
|
||||
# don't leak state into the rest of the suite.
|
||||
saved = {}
|
||||
for name in parsedmarc.cli._DEPENDENCY_LOGGERS:
|
||||
dep = logging.getLogger(name)
|
||||
saved[name] = (dep.level, list(dep.handlers), dep.propagate)
|
||||
|
||||
def restore():
|
||||
for name, (level, handlers, propagate) in saved.items():
|
||||
dep = logging.getLogger(name)
|
||||
dep.setLevel(level)
|
||||
dep.handlers = handlers
|
||||
dep.propagate = propagate
|
||||
|
||||
self.addCleanup(restore)
|
||||
|
||||
def _write_config(self, config_text):
|
||||
with tempfile.NamedTemporaryFile("w", suffix=".ini", delete=False) as cfg:
|
||||
cfg.write(config_text)
|
||||
cfg_path = cfg.name
|
||||
self.addCleanup(lambda: os.path.exists(cfg_path) and os.remove(cfg_path))
|
||||
return cfg_path
|
||||
|
||||
def _run_main(self, cfg_path, *cli_args):
|
||||
with patch.object(sys, "argv", ["parsedmarc", "-c", cfg_path, *cli_args]):
|
||||
parsedmarc.cli._main()
|
||||
|
||||
@patch("parsedmarc.cli.get_dmarc_reports_from_mailbox")
|
||||
@patch("parsedmarc.cli.MSGraphConnection")
|
||||
def testCliLogsMsGraphConnectionAttempt(
|
||||
def testCliLogsMsGraphConnectionSummaryAndTiming(
|
||||
self, mock_graph_connection, mock_get_mailbox_reports
|
||||
):
|
||||
"""An INFO log is emitted when parsedmarc starts a Graph connection."""
|
||||
"""The INFO summary identifies the auth method, tenant, client,
|
||||
mailbox, and Graph URL before any network I/O, and a timing line
|
||||
follows once the connection object is initialized."""
|
||||
mock_graph_connection.return_value = object()
|
||||
mock_get_mailbox_reports.return_value = {
|
||||
"aggregate_reports": [],
|
||||
"failure_reports": [],
|
||||
"smtp_tls_reports": [],
|
||||
}
|
||||
cfg_path = self._write_config(self.CERT_CONFIG)
|
||||
|
||||
config_text = """[general]
|
||||
with self.assertLogs("parsedmarc.log", level="INFO") as cm:
|
||||
self._run_main(cfg_path, "--verbose")
|
||||
|
||||
output = "\n".join(cm.output)
|
||||
self.assertIn("Connecting to Microsoft Graph", output)
|
||||
self.assertIn("auth_method=Certificate", output)
|
||||
self.assertIn("tenant_id=tenant-id-5678", output)
|
||||
self.assertIn("client_id=client-id-1234", output)
|
||||
self.assertIn("mailbox=shared@example.com", output)
|
||||
self.assertIn("graph_url=https://graph.microsoft.com", output)
|
||||
self.assertIn("Microsoft Graph connection initialized in", output)
|
||||
|
||||
@patch("parsedmarc.cli.get_dmarc_reports_from_mailbox")
|
||||
@patch("parsedmarc.cli.MSGraphConnection")
|
||||
def testCliMsGraphLoggingNeverLogsSecretValues(
|
||||
self, mock_graph_connection, mock_get_mailbox_reports
|
||||
):
|
||||
"""Even at --debug, secret values (certificate_password and
|
||||
client_assertion here) must not appear anywhere in parsedmarc's
|
||||
log output — the debug detail line reports set/not-set flags
|
||||
instead."""
|
||||
mock_graph_connection.return_value = object()
|
||||
mock_get_mailbox_reports.return_value = {
|
||||
"aggregate_reports": [],
|
||||
"failure_reports": [],
|
||||
"smtp_tls_reports": [],
|
||||
}
|
||||
cfg_path = self._write_config(self.CERT_CONFIG)
|
||||
|
||||
with self.assertLogs("parsedmarc.log", level="DEBUG") as cm:
|
||||
self._run_main(cfg_path, "--debug")
|
||||
|
||||
output = "\n".join(cm.output)
|
||||
self.assertNotIn("s3cret-cert-pass", output)
|
||||
self.assertIn("certificate_path=/tmp/msgraph-cert.pem", output)
|
||||
self.assertIn("certificate_password set", output)
|
||||
self.assertIn("client_assertion not set", output)
|
||||
|
||||
assertion_config = """[general]
|
||||
silent = true
|
||||
|
||||
[msgraph]
|
||||
auth_method = Certificate
|
||||
client_id = client-id
|
||||
tenant_id = tenant-id
|
||||
auth_method = ClientAssertion
|
||||
client_id = client-id-1234
|
||||
tenant_id = tenant-id-5678
|
||||
mailbox = shared@example.com
|
||||
certificate_path = /tmp/msgraph-cert.pem
|
||||
client_assertion = s3cret-signed-jwt-assertion
|
||||
"""
|
||||
cfg_path = self._write_config(assertion_config)
|
||||
|
||||
with tempfile.NamedTemporaryFile("w", suffix=".ini", delete=False) as cfg:
|
||||
cfg.write(config_text)
|
||||
cfg_path = cfg.name
|
||||
self.addCleanup(lambda: os.path.exists(cfg_path) and os.remove(cfg_path))
|
||||
with self.assertLogs("parsedmarc.log", level="DEBUG") as cm:
|
||||
self._run_main(cfg_path, "--debug")
|
||||
|
||||
with patch.object(sys, "argv", ["parsedmarc", "-c", cfg_path, "--verbose"]):
|
||||
with self.assertLogs("parsedmarc.log", level="INFO") as cm:
|
||||
parsedmarc.cli._main()
|
||||
output = "\n".join(cm.output)
|
||||
self.assertNotIn("s3cret-signed-jwt-assertion", output)
|
||||
self.assertIn("client_assertion set", output)
|
||||
|
||||
self.assertTrue(
|
||||
any(
|
||||
"Connecting to Microsoft Graph mailbox shared@example.com" in message
|
||||
for message in cm.output
|
||||
)
|
||||
)
|
||||
@patch("parsedmarc.cli.get_dmarc_reports_from_mailbox")
|
||||
@patch("parsedmarc.cli.MSGraphConnection")
|
||||
def testCliDebugEnablesDependencyLoggers(
|
||||
self, mock_graph_connection, mock_get_mailbox_reports
|
||||
):
|
||||
"""--debug propagates DEBUG level and parsedmarc's handlers to the
|
||||
mailsuite/azure/msgraph/httpx/httpcore loggers, so token and HTTP
|
||||
activity reaches the console (and log file) instead of being
|
||||
dropped."""
|
||||
mock_graph_connection.return_value = object()
|
||||
mock_get_mailbox_reports.return_value = {
|
||||
"aggregate_reports": [],
|
||||
"failure_reports": [],
|
||||
"smtp_tls_reports": [],
|
||||
}
|
||||
cfg_path = self._write_config(self.CERT_CONFIG)
|
||||
self._run_main(cfg_path, "--debug")
|
||||
|
||||
parsedmarc_logger = logging.getLogger("parsedmarc.log")
|
||||
for name in parsedmarc.cli._DEPENDENCY_LOGGERS:
|
||||
dep = logging.getLogger(name)
|
||||
self.assertEqual(dep.level, logging.DEBUG, name)
|
||||
# Propagation is disabled so a stray logging.basicConfig()
|
||||
# elsewhere in the process can't double-print these records.
|
||||
self.assertFalse(dep.propagate, name)
|
||||
for wanted in parsedmarc_logger.handlers:
|
||||
self.assertIn(wanted, dep.handlers, name)
|
||||
|
||||
@patch("parsedmarc.cli.get_dmarc_reports_from_mailbox")
|
||||
@patch("parsedmarc.cli.MSGraphConnection")
|
||||
def testCliDefaultKeepsDependencyLoggersAtWarning(
|
||||
self, mock_graph_connection, mock_get_mailbox_reports
|
||||
):
|
||||
"""Without --verbose/--debug, dependency loggers sit at WARNING —
|
||||
their warnings surface (formatted) but no new noise appears."""
|
||||
mock_graph_connection.return_value = object()
|
||||
mock_get_mailbox_reports.return_value = {
|
||||
"aggregate_reports": [],
|
||||
"failure_reports": [],
|
||||
"smtp_tls_reports": [],
|
||||
}
|
||||
cfg_path = self._write_config(self.CERT_CONFIG)
|
||||
self._run_main(cfg_path)
|
||||
|
||||
for name in parsedmarc.cli._DEPENDENCY_LOGGERS:
|
||||
self.assertEqual(logging.getLogger(name).level, logging.WARNING, name)
|
||||
|
||||
|
||||
class TestSighupReload(unittest.TestCase):
|
||||
|
||||
Reference in New Issue
Block a user