diff --git a/CHANGELOG.md b/CHANGELOG.md index 3bb47ad..50c975c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -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. diff --git a/docs/source/usage.md b/docs/source/usage.md index dc6185a..7a59150 100644 --- a/docs/source/usage.md +++ b/docs/source/usage.md @@ -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 diff --git a/parsedmarc/cli.py b/parsedmarc/cli.py index 02d73c7..578a3e6 100644 --- a/parsedmarc/cli.py +++ b/parsedmarc/cli.py @@ -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( diff --git a/tests/test_cli.py b/tests/test_cli.py index 1825ebe..b3789ba 100644 --- a/tests/test_cli.py +++ b/tests/test_cli.py @@ -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):