diff --git a/docs/guides/installing-a-watcher.md b/docs/guides/installing-a-watcher.md index ca75d751..4e3187e6 100644 --- a/docs/guides/installing-a-watcher.md +++ b/docs/guides/installing-a-watcher.md @@ -195,14 +195,57 @@ The watcher can't reach the Data Hub API. Check: ### Files are detected but not uploading - In **manual mode**, files are not uploaded until approved via the upload queue. Check the web dashboard. -- Check `~/.data-hub/watcher.log` for error details. +- Check the log file at `C:\ProgramData\DataHubWatcher\watcher.log` (Windows) or `~/.data-hub/watcher.log` (macOS/Linux) for error details. - Verify your API token hasn't expired. ### Logs -The watcher writes rotating logs to `~/.data-hub/watcher.log` (10 MB, 5 backups). Check this file for detailed error information. You can also run with `--verbose` for debug-level console output: +The watcher writes rotating logs to: + +- **Windows**: `C:\ProgramData\DataHubWatcher\watcher.log` +- **macOS / Linux**: `~/.data-hub/watcher.log` + +Files are 10 MB each with 5 backups kept (`watcher.log.1` through `watcher.log.5`). Both the CLI `watch` command and the Windows service write to the same path so a single `Get-Content -Wait` (or `tail -F`) shows everything regardless of which entrypoint is running. You can also pass `--verbose` for debug-level console output on the CLI: ```sh data-hub-watcher --verbose watch ``` +#### Don't run `watch` alongside the service + +Running `data-hub-watcher watch` interactively while the Windows service is also running is not supported — both processes would race on the same rotating log file (and on the same watch directory). Stop the service first if you need to run the CLI for debugging: + +```powershell +data-hub-watcher service stop +data-hub-watcher --verbose watch +data-hub-watcher service start # when you're done +``` + +#### Bootstrap log for pre-dispatcher crashes + +The service writes a separate `service-bootstrap.log` next to `watcher.log` that captures crashes happening before the service control dispatcher takes over — for example, a missing `pywin32`, a moved virtualenv, or a corrupt install. If `watcher.log` is empty after a crash, check `C:\ProgramData\DataHubWatcher\service-bootstrap.log` for the traceback. + +#### Turning on debug logging for the service + +Add `DATA_HUB_WATCHER_LOG_LEVEL=DEBUG` to the env file the service is registered against (typically `~/.data-hub/.env.`) and restart the service. No redeploy or `service reinstall` is needed. + +#### Triaging a service that crashes immediately + +If the service exits before writing anything to `watcher.log`, two read-only commands will surface the failure: + +1. Query the Windows Application event log for entries from the watcher or the underlying Python service host: + + ```powershell + Get-WinEvent -FilterHashtable @{LogName='Application'; StartTime=(Get-Date).AddHours(-1)} | + Where-Object { $_.ProviderName -match 'Python|DataHubWatcher' -or $_.Message -match 'DataHubWatcher' } | + Format-List TimeCreated, ProviderName, Id, LevelDisplayName, Message + ``` + +2. Run the service in the foreground from the venv `pywin32` itself ships: + + ```powershell + & "C:\path\to\venv\Scripts\python.exe" -m win32serviceutil debug DataHubWatcher + ``` + + This bypasses the SCM, runs the same startup path the service uses, and prints the full traceback to the console — the fastest way to see why a phase-A/B crash is happening. + diff --git a/docs/guides/upgrading-the-watcher.md b/docs/guides/upgrading-the-watcher.md index 72570624..280e9fd3 100644 --- a/docs/guides/upgrading-the-watcher.md +++ b/docs/guides/upgrading-the-watcher.md @@ -141,7 +141,7 @@ There is no separate "yank" step — a rolled-back release is still on PyPI and The upgrade subprocess started but didn't end up running the new version on the next process startup. The `details.reason` field on the `update_failed` event tells you which sub-case fired: -- `**subprocess raised: …`** — `subprocess.run` itself raised before it could exec the upgrade command. Typically `FileNotFoundError` because `uv` isn't on PATH for the service account, or a permission error. Check `~/.data-hub/watcher.log` for the full traceback. +- `**subprocess raised: …`** — `subprocess.run` itself raised before it could exec the upgrade command. Typically `FileNotFoundError` because `uv` isn't on PATH for the service account, or a permission error. Check `C:\ProgramData\DataHubWatcher\watcher.log` (Windows) or `~/.data-hub/watcher.log` (macOS/Linux) for the full traceback. - `**subprocess exited **` — the upgrade command itself failed. The event details include the last 1000 bytes of stdout/stderr; the most common cause is a transient PyPI / mirror failure or the version not yet existing on the index (see the "don't bump ahead of publish" note above). - `**expected '' after upgrade, running ''**` — the subprocess succeeded, the service restarted, but the running interpreter still imports the old version. Almost always means a stale `__pycache__` or a separate copy of the package on `sys.path`. Run `uv tool uninstall data-hub-watcher && uv tool install data-hub-watcher==` as the service account. @@ -189,7 +189,7 @@ The marker says the upgrade was dispatched via the worker, but the worker never Whenever an upgrade fires, the watcher mirrors `uv`'s full stdout/stderr to disk in two places so a misleading dashboard event doesn't leave you guessing: -- **In-process upgrades (POSIX, Windows pip)** — every line of subprocess output is logged at `INFO` to `~/.data-hub/watcher.log` (or the platform equivalent), prefixed with `Upgrade subprocess stdout/stderr tail:`. This happens regardless of the subprocess return code, so a partial install where uv exits 0 but printed errors is still recoverable. +- **In-process upgrades (POSIX, Windows pip)** — every line of subprocess output is logged at `INFO` to the watcher log (`C:\ProgramData\DataHubWatcher\watcher.log` on Windows, `~/.data-hub/watcher.log` on macOS/Linux), prefixed with `Upgrade subprocess stdout/stderr tail:`. This happens regardless of the subprocess return code, so a partial install where uv exits 0 but printed errors is still recoverable. - **Windows uv-tool worker** — every line of uv's output is echoed line-by-line to `~/.data-hub/upgrade-worker.log` with a UTC timestamp (`uv stdout: …` / `uv stderr: …`). Tail this file to watch an upgrade as it happens. Both files survive a service restart — the watcher only ever appends to them — so an after-the-fact post-mortem of "what did uv actually say five minutes ago?" is always answerable from the lab PC without re-running the upgrade. diff --git a/docs/watcher.md b/docs/watcher.md index 2142a8a3..4afda00b 100644 --- a/docs/watcher.md +++ b/docs/watcher.md @@ -180,7 +180,7 @@ The watcher maintains a SQLite database at `~/.data-hub/watcher.db` with three t - `runs` — tracks which run IDs have been reported and (in auto mode) when their files finished uploading. The most recent `reported_at` timestamp is what the auto-updater consults to gate restarts on a quiet-instrument window. - `detected_files` — the file manifest for every reported run, keyed on `(run_id, relative_path)`. Lets the initial scan skip files that are already part of a reported run even in manual mode (where `uploaded_files` stays empty), and lets the run detector hydrate its in-memory state on startup so a restart doesn't re-POST runs the API has already seen. -Logs are written to `~/.data-hub/watcher.log` (10 MB rotating, 5 backups). +Logs are written to `C:\ProgramData\DataHubWatcher\watcher.log` on Windows and `~/.data-hub/watcher.log` on macOS/Linux (10 MB rotating, 5 backups). Both the CLI `watch` command and the Windows service write to the same file so a single `Get-Content -Wait` (or `tail -F`) covers all entry points. ### Initial scan identity diff --git a/uv.lock b/uv.lock index 525b584e..0a5c629b 100644 --- a/uv.lock +++ b/uv.lock @@ -415,7 +415,7 @@ requires-dist = [ [[package]] name = "data-hub-watcher" -version = "0.2.7" +version = "0.2.8" source = { editable = "watcher" } dependencies = [ { name = "click" }, diff --git a/watcher/pyproject.toml b/watcher/pyproject.toml index 6e7bdeef..077e0880 100644 --- a/watcher/pyproject.toml +++ b/watcher/pyproject.toml @@ -1,6 +1,6 @@ [project] name = "data-hub-watcher" -version = "0.2.7" +version = "0.2.8" description = "File-watcher agent for lab instrument PCs that ingests data into Data Hub." readme = "README.md" requires-python = ">=3.12" diff --git a/watcher/src/data_hub_watcher/cli.py b/watcher/src/data_hub_watcher/cli.py index cd6d7078..abd5504a 100644 --- a/watcher/src/data_hub_watcher/cli.py +++ b/watcher/src/data_hub_watcher/cli.py @@ -160,16 +160,15 @@ def _load_and_client(ctx: click.Context) -> tuple[WatcherConfig, DataHubClient, def _setup_file_logging() -> None: - """Add a RotatingFileHandler to the root logger (`~/.data-hub/watcher.log`).""" - from logging.handlers import RotatingFileHandler + """Add a RotatingFileHandler to the root logger (``~/.data-hub/watcher.log``). - log_path = DEFAULT_CONFIG_DIR / "watcher.log" - log_path.parent.mkdir(parents=True, exist_ok=True) - handler = RotatingFileHandler( - str(log_path), maxBytes=10 * 1024 * 1024, backupCount=5, encoding="utf-8" - ) - handler.setFormatter(logging.Formatter("%(asctime)s [%(levelname)s] %(name)s: %(message)s")) - logging.getLogger().addHandler(handler) + Delegates to the shared helper in :mod:`data_hub_watcher.logging_setup` + so the CLI ``watch`` path and the Windows-service entry point can't + drift on log location, rotation policy, or format. + """ + from data_hub_watcher.logging_setup import setup_file_logging + + setup_file_logging() # --------------------------------------------------------------------------- diff --git a/watcher/src/data_hub_watcher/constants.py b/watcher/src/data_hub_watcher/constants.py index d782e160..36a6421b 100644 --- a/watcher/src/data_hub_watcher/constants.py +++ b/watcher/src/data_hub_watcher/constants.py @@ -1,6 +1,7 @@ from __future__ import annotations import os import re +import sys from importlib.metadata import PackageNotFoundError, version from pathlib import Path @@ -29,6 +30,44 @@ def _read_watcher_version() -> str: DEFAULT_CONFIG_DIR = Path("~/.data-hub").expanduser() DEFAULT_CONFIG_FILENAME = "config.yaml" ENV_FILENAME = ".env" + + +def _resolve_watcher_log_dir() -> Path: + """Pick a log directory that both the operator user and LocalSystem can write to. + + On Windows, ``~/.data-hub`` expands to different paths depending on + the account running the process — ``C:\\Users\\\\.data-hub`` for + the operator running the CLI, ``C:\\Windows\\System32\\config\\ + systemprofile\\.data-hub`` for the LocalSystem account the service + runs as. That split means a tail of "the" log file shows only half + the story during a triage session. We instead anchor logs at + ``C:\\ProgramData\\DataHubWatcher`` (the conventional Windows + location for cross-user app data), where both accounts have write + access by default. + + On non-Windows we keep ``DEFAULT_CONFIG_DIR`` so dev/test runs on + macOS or Linux still write under the working tree's ``~/.data-hub`` + rather than trying to create a Windows-only path. + + The exact filename (``watcher.log``) is shared by the CLI ``watch`` + command and the Windows service. Running both simultaneously on + the same host is not supported — see the troubleshooting guide for + why — so the shared-file rotation race is not a real concern in + operator deployments. + """ + if sys.platform == "win32": + # ``os.environ.get(name, default)`` returns the empty string + # when ``name`` is set to ``""`` rather than falling back to + # the default. Guard against that by treating an empty value + # as missing — otherwise ``Path("") / "DataHubWatcher"`` would + # silently produce a relative path that lands in whatever + # cwd the service happens to start from. + program_data = os.environ.get("ProgramData") or r"C:\ProgramData" + return Path(program_data) / "DataHubWatcher" + return DEFAULT_CONFIG_DIR + + +WATCHER_LOG_DIR = _resolve_watcher_log_dir() SUPPORTED_ENVIRONMENTS: tuple[str, ...] = ("staging", "production", "preview") HEARTBEAT_INTERVAL_SECONDS = 60 diff --git a/watcher/src/data_hub_watcher/logging_setup.py b/watcher/src/data_hub_watcher/logging_setup.py new file mode 100644 index 00000000..8ae73af1 --- /dev/null +++ b/watcher/src/data_hub_watcher/logging_setup.py @@ -0,0 +1,232 @@ +"""Shared logging configuration for the CLI and Windows-service entry points. + +Both ``data-hub-watcher watch`` and the Windows service path need the same +rotating-file behavior so the troubleshooting guide can promise a single +log file regardless of how the watcher was launched. Historically only +the CLI wired up file logging; every ``logger.*`` call made from the +service path was silently dropped — see the long comment on +``setup_file_logging`` for the gory details. + +This module is platform-independent. The ``servicemanager`` integration +takes an already-imported module via :func:`attach_servicemanager_handler` +so that it can be patched out in unit tests on non-Windows hosts. +""" + +from __future__ import annotations +import logging +import os +import sys +import threading +from logging.handlers import RotatingFileHandler +from pathlib import Path +from typing import Any + +from data_hub_watcher.constants import WATCHER_LOG_DIR + +# Format used by the on-disk rotating handler. Includes asctime so a +# bare ``tail -F watcher.log`` is operator-readable without a wrapping +# context (e.g. journalctl) that would supply its own timestamp. +LOG_FORMAT = "%(asctime)s [%(levelname)s] %(name)s: %(message)s" + +# Format used by the Windows Event Log handler. The Event Log itself +# records ``TimeCreated`` and ``LevelDisplayName`` per entry, so we +# drop ``asctime`` and the bracketed level prefix from the message +# body to avoid every entry showing two timestamps and two level +# labels when an operator views it in ``eventvwr.msc``. +EVENT_LOG_FORMAT = "%(name)s: %(message)s" + +LOG_FILENAME = "watcher.log" + +# 32 KB is the per-string cap on a Windows Event Log entry. Leave a small +# margin so the level prefix + timestamp added by ``Formatter`` don't push +# us over the limit when we forward a long traceback. +_EVENT_LOG_MAX_BYTES = 30 * 1024 + +# Map a string level (case-insensitive) to a stdlib level. ``logging`` +# already provides ``getLevelName`` for this but it returns a string for +# unknown inputs, which is not what we want — fall back to INFO instead +# so a typo in a lab PC's ``.env`` file doesn't silence everything. +_LEVEL_ENV_VAR = "DATA_HUB_WATCHER_LOG_LEVEL" + + +def _resolve_root_level(default: int = logging.INFO) -> int: + """Resolve the root log level, honoring the ``DATA_HUB_WATCHER_LOG_LEVEL`` override. + + Lab operators can flip a stuck host to verbose logging by adding + ``DATA_HUB_WATCHER_LOG_LEVEL=DEBUG`` to the registered env file and + restarting the service — no redeploy required. Unknown values fall + back to *default* rather than failing closed so a typo can't make + the watcher silently log nothing. + """ + raw = os.environ.get(_LEVEL_ENV_VAR) + if not raw: + return default + level = logging.getLevelName(raw.upper()) + if isinstance(level, int): + return level + return default + + +def _apply_root_level() -> None: + """Set the root logger level from the env var override if present. + + The watcher's two entrypoints (CLI ``watch`` and the Windows + service) each call into this module once at startup. We only + *force* the level when ``DATA_HUB_WATCHER_LOG_LEVEL`` is set — + otherwise we either initialize the (still-unset) root logger to + INFO, or leave a caller-supplied level alone. Without this + deference, a user that explicitly set ``logging.DEBUG`` at the + top of a script would have their choice silently reverted to + INFO by the first ``setup_file_logging`` call. + """ + raw = os.environ.get(_LEVEL_ENV_VAR) + root = logging.getLogger() + if raw: + root.setLevel(_resolve_root_level()) + return + if root.level == logging.NOTSET: + root.setLevel(logging.INFO) + + +def _watcher_log_path() -> Path: + return WATCHER_LOG_DIR / LOG_FILENAME + + +def setup_file_logging() -> Path: + """Attach a rotating file handler at ``watcher.log`` to the root logger. + + Idempotent: if a ``RotatingFileHandler`` for the same path is already + attached to the root logger, returns the existing path without + adding a duplicate. This matters because both the CLI ``watch`` + command and the service path can call this — and on the service + path it's called inside ``_run_service_loop``, which the SCM may + re-invoke after a restart inside the same Python process. + + The path resolves to ``C:\\ProgramData\\DataHubWatcher\\watcher.log`` + on Windows (a location both the operator user and LocalSystem can + write to) and ``~/.data-hub/watcher.log`` on non-Windows hosts; see + :data:`data_hub_watcher.constants.WATCHER_LOG_DIR` for the + rationale. Running ``data-hub-watcher watch`` while the service is + also running is not supported — both processes would race on the + same rotating file — but neither is running two watchers against + the same instrument, so this is not a new constraint. + """ + log_path = _watcher_log_path() + log_path.parent.mkdir(parents=True, exist_ok=True) + + _apply_root_level() + root = logging.getLogger() + + # ``FileHandler.__init__`` stores ``baseFilename`` as + # ``os.path.abspath(filename)`` — not a resolved path — so we + # compare against that same shape. On case-insensitive + # filesystems (Windows, default APFS) two paths that differ only + # in case point at the same file, so we fold case there to avoid + # accidentally double-registering. + target = os.path.abspath(str(log_path)) + case_insensitive = sys.platform in ("win32", "darwin") + if case_insensitive: + target_cmp = target.lower() + else: + target_cmp = target + + for existing in root.handlers: + if not isinstance(existing, RotatingFileHandler): + continue + existing_base = getattr(existing, "baseFilename", "") + existing_cmp = existing_base.lower() if case_insensitive else existing_base + if existing_cmp == target_cmp: + return log_path + + handler = RotatingFileHandler( + target, maxBytes=10 * 1024 * 1024, backupCount=5, encoding="utf-8" + ) + handler.setFormatter(logging.Formatter(LOG_FORMAT)) + root.addHandler(handler) + return log_path + + +class _ServiceManagerHandler(logging.Handler): + """Forward log records to ``servicemanager.Log*Msg`` so they reach the Windows Event Log. + + Routing is by record level: + + * ``ERROR`` / ``CRITICAL`` -> ``LogErrorMsg`` + * ``WARNING`` -> ``LogWarningMsg`` + * everything else -> ``LogInfoMsg`` + + Two important safety properties: + + 1. Re-entrancy guard. If ``LogErrorMsg`` itself raises (e.g. the + Event Log service is unreachable), the exception is caught by + ``logging.Handler.handleError`` — which, depending on the + configured ``logging.raiseExceptions`` flag, may attempt to log + the failure through the root logger. That would route back + through *this* handler and loop. We guard with a per-thread + flag so re-entry is a no-op. + 2. Truncation. Event Log entries are capped at 32 KB per string. + We truncate the formatted message at 30 KB to leave headroom + for the level prefix the SCM may add, with a clear ``[truncated]`` + marker so an operator reading the event log knows the rest is + in ``watcher.log``. + """ + + def __init__(self, sm: Any) -> None: + super().__init__() + self._sm = sm + self._local = threading.local() + + def emit(self, record: logging.LogRecord) -> None: + if getattr(self._local, "in_emit", False): + return + self._local.in_emit = True + try: + try: + msg = self.format(record) + except Exception: + # Mirrors logging.Handler.emit's standard fallback. + self.handleError(record) + return + + if len(msg) > _EVENT_LOG_MAX_BYTES: + msg = ( + msg[:_EVENT_LOG_MAX_BYTES] + + f"\n... [truncated; see {LOG_FILENAME} for full message]" + ) + + try: + if record.levelno >= logging.ERROR: + self._sm.LogErrorMsg(msg) + elif record.levelno >= logging.WARNING: + self._sm.LogWarningMsg(msg) + else: + self._sm.LogInfoMsg(msg) + except Exception: + # Never raise out of a log call — the worst case is a + # missing Event Log entry, not a crashed service. + self.handleError(record) + finally: + self._local.in_emit = False + + +def attach_servicemanager_handler(sm: Any) -> _ServiceManagerHandler: + """Attach a :class:`_ServiceManagerHandler` for *sm* to the root logger. + + Idempotent: if a handler is already attached for the same *sm* + object, the existing handler is returned unchanged. Callers should + typically invoke this exactly once at service startup, immediately + after :func:`setup_file_logging`, so every subsequent ``logger.*`` + call from the watcher's library code reaches both the rotating + file log AND the Windows Event Log. + """ + _apply_root_level() + root = logging.getLogger() + + for existing in root.handlers: + if isinstance(existing, _ServiceManagerHandler) and existing._sm is sm: + return existing + + handler = _ServiceManagerHandler(sm) + handler.setFormatter(logging.Formatter(EVENT_LOG_FORMAT)) + root.addHandler(handler) + return handler diff --git a/watcher/src/data_hub_watcher/service.py b/watcher/src/data_hub_watcher/service.py index 6ad9b136..cad6518e 100644 --- a/watcher/src/data_hub_watcher/service.py +++ b/watcher/src/data_hub_watcher/service.py @@ -16,13 +16,14 @@ from __future__ import annotations import logging +import os import sys import threading import time from pathlib import Path from typing import Any -from data_hub_watcher.constants import DEFAULT_CONFIG_DIR, SERVICE_NAME +from data_hub_watcher.constants import DEFAULT_CONFIG_DIR, SERVICE_NAME, WATCHER_LOG_DIR logger = logging.getLogger(__name__) @@ -85,6 +86,17 @@ def install_service(config_path: Path, env_path: Path) -> None: _store_paths_in_registry(config_path, env_path) _configure_recovery() + # Create the shared log directory up-front under the operator's + # (elevated) shell. On Windows ``C:\ProgramData\DataHubWatcher`` + # inherits its ACL from ``C:\ProgramData`` — i.e. SYSTEM full + # control + Users: Modify on contained files/folders — so the + # service running under LocalSystem can write here and the + # operator can tail the file from their own shell without + # elevation. Doing this here rather than letting the first + # writer create it on demand avoids a race where, say, an early + # CLI invocation creates the directory with a non-default owner + # before the service tries to rotate the file. + WATCHER_LOG_DIR.mkdir(parents=True, exist_ok=True) # The worker template bakes its sentinel paths in at render time, # so we render against the operator's chosen config directory # (``config_path.parent``) rather than the import-time @@ -443,7 +455,7 @@ def query_service_status() -> dict[str, Any]: ws.CloseServiceHandle(hscm) -def _repair_upgrade_worker_if_missing(sm: Any, config_dir: Path) -> None: +def _repair_upgrade_worker_if_missing(config_dir: Path) -> None: """Re-register the upgrade scheduled task on startup if it has gone missing. Lab PCs that auto-update into the version that introduced the @@ -476,11 +488,13 @@ def _repair_upgrade_worker_if_missing(sm: Any, config_dir: Path) -> None: :class:`~data_hub_watcher.runtime.WatcherRuntime.config_dir` for why ``DEFAULT_CONFIG_DIR`` would resolve incorrectly here. - Failures are logged via the Windows event log but do not raise: - a host that can't register the task should still be able to run - the watcher in its current version. The next auto-update attempt - will surface the missing task as an ``UPDATE_FAILED`` event with - a clearer reason. + Failures are logged via the module logger — which on the service + path is attached to a :class:`_ServiceManagerHandler` so warnings + reach both ``watcher.log`` and the Windows Event Log — but do not + raise: a host that can't register the task should still be able + to run the watcher in its current version. The next auto-update + attempt will surface the missing task as an ``UPDATE_FAILED`` + event with a clearer reason. """ try: from data_hub_watcher.scheduled_task import ( @@ -490,16 +504,17 @@ def _repair_upgrade_worker_if_missing(sm: Any, config_dir: Path) -> None: ) from data_hub_watcher.upgrade_worker import upgrade_worker_script_path except Exception as exc: - sm.LogWarningMsg(f"Cannot import upgrade worker modules during startup: {exc}") + logger.warning("Cannot import upgrade worker modules during startup: %s", exc) return try: present = task_exists() except ScheduledTaskError as exc: - sm.LogWarningMsg( - f"Could not query upgrade scheduled task: {exc}. " + logger.warning( + "Could not query upgrade scheduled task: %s. " "Auto-update may be unavailable until 'data-hub-watcher service " - "reinstall' is run." + "reinstall' is run.", + exc, ) return @@ -511,27 +526,30 @@ def _repair_upgrade_worker_if_missing(sm: Any, config_dir: Path) -> None: # We deliberately do NOT re-render here — see the docstring # for why a SYSTEM-rendered template would silently break the # very thing the repair is meant to fix. - sm.LogWarningMsg( - f"Upgrade scheduled task is missing AND the rendered worker " - f"script is absent from {script_path}. Cannot self-repair " + logger.warning( + "Upgrade scheduled task is missing AND the rendered worker " + "script is absent from %s. Cannot self-repair " "from a LocalSystem context. Run " "'data-hub-watcher service reinstall' as Administrator to " "re-render the worker against the operator's uv tool " - "directories and re-register the task." + "directories and re-register the task.", + script_path, ) return - sm.LogInfoMsg( - f"Upgrade scheduled task missing but worker script is present at " - f"{script_path}; re-registering the task pointing at the existing " - "rendered script." + logger.info( + "Upgrade scheduled task missing but worker script is present at " + "%s; re-registering the task pointing at the existing " + "rendered script.", + script_path, ) try: install_upgrade_task(script_path) except (OSError, ScheduledTaskError) as exc: - sm.LogWarningMsg( - f"Failed to register upgrade scheduled task: {exc}. " - "Run 'data-hub-watcher service reinstall' as Administrator to retry." + logger.warning( + "Failed to register upgrade scheduled task: %s. " + "Run 'data-hub-watcher service reinstall' as Administrator to retry.", + exc, ) @@ -566,6 +584,10 @@ def _run_service_loop(stop_event: threading.Event, sm: Any) -> None: STATE_DB_FILENAME, env_file_path, ) + from data_hub_watcher.logging_setup import ( + attach_servicemanager_handler, + setup_file_logging, + ) from data_hub_watcher.runtime import ( build_runtime, classify_shutdown, @@ -574,7 +596,17 @@ def _run_service_loop(stop_event: threading.Event, sm: Any) -> None: sync_config_to_api, ) - sm.LogInfoMsg(f"{SERVICE_DISPLAY_NAME} starting") + # Wire up file logging + Windows Event Log routing BEFORE any + # other work, so a registry-read or env-load failure on the very + # next line still produces a record in ``watcher.log`` and the + # Event Log. Without this, every ``logger.*`` call made from the + # service path — including those from ``runtime``, ``uploader``, + # ``monitor``, ``heartbeat``, and ``updater`` — is silently + # dropped, which is the bug this whole module-level rework is + # closing. + log_path = setup_file_logging() + attach_servicemanager_handler(sm) + logger.info("%s starting (pid=%s, log=%s)", SERVICE_DISPLAY_NAME, os.getpid(), log_path) # Read registry paths BEFORE the upgrade-worker self-repair so # both have a single source of truth for the operator's config @@ -585,13 +617,14 @@ def _run_service_loop(stop_event: threading.Event, sm: Any) -> None: try: path, env_path = _read_paths_from_registry() except Exception as exc: - sm.LogErrorMsg( - f"Cannot read config/env paths from registry: {exc}. " - "Re-run 'data-hub-watcher service install'." + logger.error( + "Cannot read config/env paths from registry: %s. " + "Re-run 'data-hub-watcher service install'.", + exc, ) raise SystemExit(1) from exc - _repair_upgrade_worker_if_missing(sm, path.parent) + _repair_upgrade_worker_if_missing(path.parent) # Mirror the CLI's ``load_env`` semantics: load the base # ``~/.data-hub/.env`` first (for any shared, non-secret values @@ -622,13 +655,14 @@ def _run_service_loop(stop_event: threading.Event, sm: Any) -> None: try: detail = client.get_instrument(inst.id) except ApiError as exc: - sm.LogErrorMsg(f"Cannot reach API during startup: {exc.message}") + logger.error("Cannot reach API during startup: %s", exc.message) raise SystemExit(1) from exc if detail.status == "pending": - sm.LogErrorMsg( - f"Instrument {inst.id!r} is still pending activation. " - "Service cannot start until the instrument is activated." + logger.error( + "Instrument %r is still pending activation. " + "Service cannot start until the instrument is activated.", + inst.id, ) raise SystemExit(1) @@ -636,7 +670,7 @@ def _run_service_loop(stop_event: threading.Event, sm: Any) -> None: # a service-manager error rather than a hard crash so operators # see a clear message in the Windows event log. if not cfg.watcher_id: - sm.LogErrorMsg("No watcher_id in config. Run 'data-hub-watcher init' first.") + logger.error("No watcher_id in config. Run 'data-hub-watcher init' first.") raise SystemExit(1) db_path = path.parent / STATE_DB_FILENAME @@ -652,11 +686,11 @@ def _run_service_loop(stop_event: threading.Event, sm: Any) -> None: # instead of only as a Windows-event-log warning that operators # rarely read). if sync_config_to_api(client, cfg.watcher_id, path, rt.reporter, trigger="startup"): - sm.LogInfoMsg("Config synced to Data Hub") + logger.info("Config synced to Data Hub") start_runtime(rt, started_message=f"Service started on {platform.node()}") - sm.LogInfoMsg(f"{SERVICE_DISPLAY_NAME} is running") + logger.info("%s is running", SERVICE_DISPLAY_NAME) # Wait for either the SCM's stop_event (operator-initiated stop, or # OS shutdown) or the runtime's shutdown_event (in-process updater @@ -674,7 +708,7 @@ def _run_service_loop(stop_event: threading.Event, sm: Any) -> None: stop_runtime(rt, stopped_message=decision.stopped_message) if decision.is_upgrade_restart: - sm.LogInfoMsg(f"{SERVICE_DISPLAY_NAME} restarting to load upgraded watcher") + logger.info("%s restarting to load upgraded watcher", SERVICE_DISPLAY_NAME) # Exit non-zero so the SCM's failure-actions config kicks in and # restarts the service on the configured 60 s delay. Without # SERVICE_CONFIG_FAILURE_ACTIONS_FLAG this would look like a @@ -682,7 +716,7 @@ def _run_service_loop(stop_event: threading.Event, sm: Any) -> None: # comment on `_configure_recovery` for details. raise SystemExit(1) - sm.LogInfoMsg(f"{SERVICE_DISPLAY_NAME} stopped") + logger.info("%s stopped", SERVICE_DISPLAY_NAME) def _create_service_class() -> type | None: @@ -732,12 +766,82 @@ def SvcStop(self) -> None: # When the SCM starts the process, Python executes this __main__ block which # hands control to the service dispatcher. + +def _write_bootstrap_failure(exc_info: BaseException) -> None: + """Append the current exception traceback to the bootstrap log file. + + This runs in the narrow window between Python starting and + ``StartServiceCtrlDispatcher`` handing control to our service + class. Failures here (broken venv, missing ``pywin32``, corrupt + bytecode, etc.) bypass every ``servicemanager.LogErrorMsg`` call + in this module because the dispatcher itself hasn't been wired + up yet — so without this side-channel the only signal an + operator sees is "the service started and exited immediately + with no log entries anywhere." + + Only *unexpected* exceptions are captured here. ``SystemExit`` + and ``KeyboardInterrupt`` are filtered out by the caller so a + clean upgrade restart (which raises ``SystemExit(1)`` to trigger + the SCM's recovery action) doesn't pollute the bootstrap log + with a misleading traceback. + + We deliberately do not route through ``logging_setup`` here: + the failure modes we're capturing may include ``logging``, + ``pathlib``, or import-time failures in ``data_hub_watcher`` + itself. Everything is wrapped in a nested ``try`` so a write + failure is silent — the original exception is re-raised by the + caller regardless. + + The log lives alongside ``watcher.log`` (at + :data:`data_hub_watcher.constants.WATCHER_LOG_DIR`) so an + operator can tail one directory to see both pre- and + post-dispatcher failure trails. + """ + import datetime + import traceback + + try: + WATCHER_LOG_DIR.mkdir(parents=True, exist_ok=True) + bootstrap_log = WATCHER_LOG_DIR / "service-bootstrap.log" + with bootstrap_log.open("a", encoding="utf-8") as fh: + timestamp = datetime.datetime.now(datetime.timezone.utc).isoformat() + fh.write(f"\n--- {timestamp} bootstrap failure ---\n") + traceback.print_exception(type(exc_info), exc_info, exc_info.__traceback__, file=fh) + except Exception: + # Last-ditch: if even writing to the bootstrap log fails + # there is nothing useful we can do — the original + # exception will still propagate to the SCM as a non-zero + # exit code. + pass + + +def _start_service_dispatcher() -> None: + """Hand control to the SCM dispatcher, capturing bootstrap-window failures. + + Extracted from the ``__main__`` block so the bootstrap-capture + contract is unit-testable on non-Windows hosts. Only *unexpected* + exceptions are diverted into ``service-bootstrap.log`` — + ``SystemExit`` (the canonical "exit with non-zero" signal used + by ``_run_service_loop`` for upgrade restarts and several + early-exit failure modes) and ``KeyboardInterrupt`` (operator + Ctrl-C in interactive debug mode) are re-raised untouched so + they don't pollute the dedicated pre-dispatcher channel. + """ + import servicemanager # type: ignore[import-untyped] + + try: + servicemanager.Initialize(SERVICE_NAME) # type: ignore[attr-defined] + servicemanager.PrepareToHostSingle(_svc_cls) # type: ignore[attr-defined] + servicemanager.StartServiceCtrlDispatcher() # type: ignore[attr-defined] + except (SystemExit, KeyboardInterrupt): + raise + except BaseException as exc: + _write_bootstrap_failure(exc) + raise + + if __name__ == "__main__": if _svc_cls is None: raise SystemExit("This module must be run on Windows.") - import servicemanager # type: ignore[import-untyped] - - servicemanager.Initialize(SERVICE_NAME) # type: ignore[attr-defined] - servicemanager.PrepareToHostSingle(_svc_cls) # type: ignore[attr-defined] - servicemanager.StartServiceCtrlDispatcher() # type: ignore[attr-defined] + _start_service_dispatcher() diff --git a/watcher/tests/test_logging_setup.py b/watcher/tests/test_logging_setup.py new file mode 100644 index 00000000..2a0cb199 --- /dev/null +++ b/watcher/tests/test_logging_setup.py @@ -0,0 +1,256 @@ +"""Unit tests for the shared file + Event-Log logging helpers. + +These exercise the cross-platform parts of ``data_hub_watcher.logging_setup``: +the rotating file handler attached by ``setup_file_logging`` and the +``servicemanager``-routing handler attached by +``attach_servicemanager_handler``. The Windows-specific wiring inside +``service._run_service_loop`` is covered separately by +``test_service.py``. +""" + +from __future__ import annotations +import logging +from logging.handlers import RotatingFileHandler +from pathlib import Path +from typing import Any +from unittest.mock import MagicMock + +import pytest + +from data_hub_watcher import logging_setup + + +@pytest.fixture(autouse=True) +def _isolated_root_logger() -> Any: + """Snapshot and restore the root logger so tests don't leak handlers. + + Adding handlers to the root logger is the explicit job of the + helpers under test, so isolation here is mandatory — otherwise a + test that exercises ``setup_file_logging`` would leave a real + ``RotatingFileHandler`` attached that subsequent tests would + silently inherit and emit through. + """ + root = logging.getLogger() + original_handlers = list(root.handlers) + original_level = root.level + try: + yield + finally: + # Close any handlers added during the test before discarding + # them, otherwise on Windows the underlying log file stays + # locked and the tmp_path teardown fails with a PermissionError. + for handler in root.handlers: + if handler not in original_handlers: + try: + handler.close() + except Exception: + pass + root.handlers = original_handlers + root.setLevel(original_level) + + +@pytest.fixture +def patch_log_dir(monkeypatch: pytest.MonkeyPatch, tmp_path: Path) -> Path: + """Redirect ``WATCHER_LOG_DIR`` so file logging lands in tmp_path. + + Patches both the source-module constant and the re-exported binding + inside ``logging_setup`` so the helper picks the tmp directory up + regardless of how its imports resolve. + """ + from data_hub_watcher import constants + + monkeypatch.setattr(constants, "WATCHER_LOG_DIR", tmp_path) + monkeypatch.setattr(logging_setup, "WATCHER_LOG_DIR", tmp_path) + return tmp_path + + +class TestSetupFileLogging: + def test_creates_log_file_and_attaches_rotating_handler(self, patch_log_dir: Path) -> None: + log_path = logging_setup.setup_file_logging() + + assert log_path == patch_log_dir / logging_setup.LOG_FILENAME + + root = logging.getLogger() + rotating = [h for h in root.handlers if isinstance(h, RotatingFileHandler)] + assert len(rotating) == 1 + + handler = rotating[0] + assert Path(handler.baseFilename) == log_path + # 10 MB / 5 backups matches the historical CLI behavior and + # what's documented in the troubleshooting guide. + assert handler.maxBytes == 10 * 1024 * 1024 + assert handler.backupCount == 5 + + def test_writes_records_to_disk( + self, + patch_log_dir: Path, + monkeypatch: pytest.MonkeyPatch, + ) -> None: + # Pytest's logging plugin defaults the root logger to WARNING, + # so we exercise the operator-visible flow by setting the env + # override explicitly here — this is the same knob a lab PC + # operator would flip in ``~/.data-hub/.env.`` + # to confirm watcher.log is receiving INFO traffic. + monkeypatch.setenv("DATA_HUB_WATCHER_LOG_LEVEL", "INFO") + + log_path = logging_setup.setup_file_logging() + logger = logging.getLogger("data_hub_watcher.test") + logger.info("hello from the test") + + for handler in logging.getLogger().handlers: + handler.flush() + + assert log_path.exists() + contents = log_path.read_text(encoding="utf-8") + assert "hello from the test" in contents + # Format includes level + logger name so a tail of the file + # is actually useful during a lab-PC triage. + assert "[INFO]" in contents + assert "data_hub_watcher.test" in contents + + def test_is_idempotent(self, patch_log_dir: Path) -> None: + logging_setup.setup_file_logging() + logging_setup.setup_file_logging() + logging_setup.setup_file_logging() + + rotating = [h for h in logging.getLogger().handlers if isinstance(h, RotatingFileHandler)] + assert len(rotating) == 1 + + def test_log_level_env_var_overrides_default( + self, + patch_log_dir: Path, + monkeypatch: pytest.MonkeyPatch, + ) -> None: + monkeypatch.setenv("DATA_HUB_WATCHER_LOG_LEVEL", "DEBUG") + logging_setup.setup_file_logging() + assert logging.getLogger().level == logging.DEBUG + + def test_unknown_log_level_falls_back_to_info( + self, + patch_log_dir: Path, + monkeypatch: pytest.MonkeyPatch, + ) -> None: + # A typo in a lab-PC env file must NOT silence logging — the + # whole point of the env-var override is that an operator can + # turn debug on without redeploying, and the failure mode of + # the wrong knob disabling output altogether would defeat + # the feature. + monkeypatch.setenv("DATA_HUB_WATCHER_LOG_LEVEL", "definitely-not-a-level") + logging_setup.setup_file_logging() + assert logging.getLogger().level == logging.INFO + + +class TestServiceManagerHandler: + def test_error_routes_to_log_error_msg(self) -> None: + sm = MagicMock(name="servicemanager") + logging_setup.attach_servicemanager_handler(sm) + + logging.getLogger("data_hub_watcher.test").error("boom") + + sm.LogErrorMsg.assert_called_once() + msg = sm.LogErrorMsg.call_args.args[0] + # The Event Log records ``LevelDisplayName`` and + # ``TimeCreated`` per entry, so the formatter intentionally + # drops the bracketed level + asctime — the message body + # is just ``: ``. We still include the + # logger name so an operator scanning event viewer can tell + # ``uploader`` failures from ``api_client`` failures. + assert "boom" in msg + assert "data_hub_watcher.test" in msg + sm.LogWarningMsg.assert_not_called() + sm.LogInfoMsg.assert_not_called() + + def test_warning_routes_to_log_warning_msg(self) -> None: + sm = MagicMock(name="servicemanager") + logging_setup.attach_servicemanager_handler(sm) + + logging.getLogger("data_hub_watcher.test").warning("careful") + + sm.LogWarningMsg.assert_called_once() + assert "careful" in sm.LogWarningMsg.call_args.args[0] + sm.LogErrorMsg.assert_not_called() + sm.LogInfoMsg.assert_not_called() + + def test_info_and_debug_route_to_log_info_msg(self, monkeypatch: pytest.MonkeyPatch) -> None: + # Set the env var so the operator-facing override path runs + # rather than relying on whatever level pytest's logging + # plugin currently defaults the root to. + monkeypatch.setenv("DATA_HUB_WATCHER_LOG_LEVEL", "DEBUG") + sm = MagicMock(name="servicemanager") + logging_setup.attach_servicemanager_handler(sm) + + logger = logging.getLogger("data_hub_watcher.test") + logger.info("hello") + logger.debug("noisy") + + assert sm.LogInfoMsg.call_count == 2 + bodies = [c.args[0] for c in sm.LogInfoMsg.call_args_list] + assert any("hello" in b for b in bodies) + assert any("noisy" in b for b in bodies) + sm.LogErrorMsg.assert_not_called() + sm.LogWarningMsg.assert_not_called() + + def test_idempotent_for_same_sm(self) -> None: + sm = MagicMock(name="servicemanager") + first = logging_setup.attach_servicemanager_handler(sm) + second = logging_setup.attach_servicemanager_handler(sm) + + assert first is second + root = logging.getLogger() + handlers = [h for h in root.handlers if isinstance(h, logging_setup._ServiceManagerHandler)] + assert len(handlers) == 1 + + def test_separate_handler_per_sm_object(self) -> None: + sm1 = MagicMock(name="sm1") + sm2 = MagicMock(name="sm2") + logging_setup.attach_servicemanager_handler(sm1) + logging_setup.attach_servicemanager_handler(sm2) + + logging.getLogger("data_hub_watcher.test").error("dispatch") + + sm1.LogErrorMsg.assert_called_once() + sm2.LogErrorMsg.assert_called_once() + + def test_truncates_oversize_messages(self) -> None: + sm = MagicMock(name="servicemanager") + logging_setup.attach_servicemanager_handler(sm) + + # The truncation cap is 30 KB to leave headroom under the + # 32 KB Windows Event Log per-string limit. Build a message + # comfortably past the cap so the truncation logic kicks in. + big = "x" * (40 * 1024) + logging.getLogger("data_hub_watcher.test").error(big) + + sm.LogErrorMsg.assert_called_once() + forwarded = sm.LogErrorMsg.call_args.args[0] + assert len(forwarded) <= 30 * 1024 + 200 # cap + truncation marker + assert "truncated" in forwarded + + def test_swallows_underlying_sm_errors(self) -> None: + # If the servicemanager call itself raises (e.g. Event Log is + # full or unreachable) we must NOT propagate — the worst case + # is a missing Event Log entry, not a crashed service. The + # original record should also still reach any sibling handler + # like the rotating file log. + sm = MagicMock(name="servicemanager") + sm.LogErrorMsg.side_effect = RuntimeError("event log unavailable") + logging_setup.attach_servicemanager_handler(sm) + + logging.getLogger("data_hub_watcher.test").error("still useful") + + sm.LogErrorMsg.assert_called_once() + # No exception escaped. + + def test_does_not_recurse_if_format_raises(self) -> None: + # If formatting the record itself blows up, we must fall back + # to the standard logging.Handler error path instead of + # looping by emitting another record through ourselves. + sm = MagicMock(name="servicemanager") + handler = logging_setup.attach_servicemanager_handler(sm) + handler.setFormatter(logging.Formatter("%(asctime)s %(missing_attribute)s %(message)s")) + + # Should not raise, should not call any sm.Log* method since + # formatting fails before routing. + logging.getLogger("data_hub_watcher.test").error("payload") + + sm.LogErrorMsg.assert_not_called() diff --git a/watcher/tests/test_service.py b/watcher/tests/test_service.py index ebca4562..8a990beb 100644 --- a/watcher/tests/test_service.py +++ b/watcher/tests/test_service.py @@ -22,6 +22,7 @@ from __future__ import annotations import importlib +import logging import sys import threading from collections.abc import Iterator @@ -461,7 +462,6 @@ def test_repair_skipped_when_task_already_registered( monkeypatch: pytest.MonkeyPatch, tmp_path: Path, ) -> None: - sm = MagicMock(name="servicemanager") monkeypatch.setattr("data_hub_watcher.scheduled_task.task_exists", lambda: True) install_calls: list[Path] = [] monkeypatch.setattr( @@ -469,7 +469,7 @@ def test_repair_skipped_when_task_already_registered( lambda script_path: install_calls.append(script_path), ) - service_module._repair_upgrade_worker_if_missing(sm, tmp_path) + service_module._repair_upgrade_worker_if_missing(tmp_path) assert install_calls == [] @@ -489,7 +489,6 @@ def test_repair_re_registers_when_task_missing_and_script_present( script_path.parent.mkdir(parents=True, exist_ok=True) script_path.write_text("# previously rendered worker", encoding="utf-8") - sm = MagicMock(name="servicemanager") monkeypatch.setattr("data_hub_watcher.scheduled_task.task_exists", lambda: False) install_calls: list[Path] = [] monkeypatch.setattr( @@ -497,7 +496,7 @@ def test_repair_re_registers_when_task_missing_and_script_present( lambda script_path: install_calls.append(script_path), ) - service_module._repair_upgrade_worker_if_missing(sm, tmp_path) + service_module._repair_upgrade_worker_if_missing(tmp_path) # Task is re-registered against the existing script. assert install_calls == [script_path] @@ -513,6 +512,7 @@ def test_repair_punts_when_task_and_script_both_missing( service_module: ModuleType, monkeypatch: pytest.MonkeyPatch, tmp_path: Path, + caplog: pytest.LogCaptureFixture, ) -> None: # Without a rendered script on disk we have no way to # reconstruct the operator's UV_TOOL_DIR from a SYSTEM @@ -522,7 +522,6 @@ def test_repair_punts_when_task_and_script_both_missing( # is to log a clear pointer at `service reinstall` and punt; # the next auto-update tick will fail loudly with a usable # error. - sm = MagicMock(name="servicemanager") monkeypatch.setattr("data_hub_watcher.scheduled_task.task_exists", lambda: False) install_calls: list[Path] = [] monkeypatch.setattr( @@ -530,43 +529,49 @@ def test_repair_punts_when_task_and_script_both_missing( lambda script_path: install_calls.append(script_path), ) - service_module._repair_upgrade_worker_if_missing(sm, tmp_path) + with caplog.at_level(logging.WARNING, logger="data_hub_watcher.service"): + service_module._repair_upgrade_worker_if_missing(tmp_path) # No re-registration happened — punted to operator action. assert install_calls == [] # …and the operator-facing message points at the recovery - # command, not a bare error code. - sm.LogWarningMsg.assert_called_once() - msg = sm.LogWarningMsg.call_args.args[0] - assert "service reinstall" in msg + # command, not a bare error code. The helper now routes + # through ``logger.warning`` so the Event-Log handler picks + # it up only when one is attached (service path); tests + # assert on the stdlib log record directly. + warnings_ = [r for r in caplog.records if r.levelno == logging.WARNING] + assert len(warnings_) == 1 + assert "service reinstall" in warnings_[0].getMessage() def test_repair_swallows_query_errors( self, service_module: ModuleType, monkeypatch: pytest.MonkeyPatch, tmp_path: Path, + caplog: pytest.LogCaptureFixture, ) -> None: # If we can't even query Task Scheduler we should NOT block # service startup — the host should keep running its current - # version and surface the issue via LogWarningMsg + the next - # auto-update event. + # version and surface the issue as a logged warning + the + # next auto-update event. from data_hub_watcher.scheduled_task import ScheduledTaskError - sm = MagicMock(name="servicemanager") - def boom() -> bool: raise ScheduledTaskError("rpc dead") monkeypatch.setattr("data_hub_watcher.scheduled_task.task_exists", boom) - # Must not raise. - service_module._repair_upgrade_worker_if_missing(sm, tmp_path) - sm.LogWarningMsg.assert_called_once() + with caplog.at_level(logging.WARNING, logger="data_hub_watcher.service"): + # Must not raise. + service_module._repair_upgrade_worker_if_missing(tmp_path) + warnings_ = [r for r in caplog.records if r.levelno == logging.WARNING] + assert len(warnings_) == 1 def test_repair_swallows_install_failures( self, service_module: ModuleType, monkeypatch: pytest.MonkeyPatch, tmp_path: Path, + caplog: pytest.LogCaptureFixture, ) -> None: from data_hub_watcher.scheduled_task import ScheduledTaskError from data_hub_watcher.upgrade_worker import upgrade_worker_script_path @@ -577,16 +582,17 @@ def test_repair_swallows_install_failures( script_path.parent.mkdir(parents=True, exist_ok=True) script_path.write_text("# previously rendered worker", encoding="utf-8") - sm = MagicMock(name="servicemanager") monkeypatch.setattr("data_hub_watcher.scheduled_task.task_exists", lambda: False) def boom(script_path: Path) -> None: raise ScheduledTaskError("Access is denied") monkeypatch.setattr("data_hub_watcher.scheduled_task.install_upgrade_task", boom) - # Must not raise even when re-registration fails. - service_module._repair_upgrade_worker_if_missing(sm, tmp_path) - sm.LogWarningMsg.assert_called_once() + with caplog.at_level(logging.WARNING, logger="data_hub_watcher.service"): + # Must not raise even when re-registration fails. + service_module._repair_upgrade_worker_if_missing(tmp_path) + warnings_ = [r for r in caplog.records if r.levelno == logging.WARNING] + assert len(warnings_) == 1 # --- _configure_recovery actions + non-crash failure flag -------------------- @@ -1025,11 +1031,11 @@ def __init__( # Stub out the upgrade-worker self-repair so existing # ``_run_service_loop`` tests don't try to invoke ``schtasks.exe`` # — that helper has its own dedicated test class above. - self.repair_calls: list[tuple[Any, Path]] = [] + self.repair_calls: list[Path] = [] monkeypatch.setattr( service_module, "_repair_upgrade_worker_if_missing", - lambda sm, config_dir: self.repair_calls.append((sm, config_dir)), + lambda config_dir: self.repair_calls.append(config_dir), ) # Patch source modules of the lazy imports inside _run_service_loop. @@ -1073,14 +1079,59 @@ def __init__( lambda *args, **kwargs: self.dotenv_calls.append((args, kwargs)), ) + # Patch the file-logging side of ``logging_setup`` so the + # service loop doesn't touch the operator's real + # ``~/.data-hub/watcher.log``. The Event-Log handler is + # allowed to run for real because every test below asserts + # against ``self.sm.LogErrorMsg`` / ``LogInfoMsg`` — i.e. the + # SCM-routing handler is the thing under test. + from data_hub_watcher import logging_setup + + self.setup_file_logging_calls: list[None] = [] + + def _fake_setup_file_logging() -> Path: + self.setup_file_logging_calls.append(None) + return tmp_path / "watcher.log" + + monkeypatch.setattr(logging_setup, "setup_file_logging", _fake_setup_file_logging) + # service.py imports these symbols lazily inside + # _run_service_loop, so patching at the source module is + # sufficient — there's no re-export to keep in sync. + + # Force the operator-facing env override on so the root + # logger drops down to INFO (pytest's logging plugin + # defaults it to WARNING, which would silence the very + # ``logger.info`` calls these tests assert on). + monkeypatch.setenv("DATA_HUB_WATCHER_LOG_LEVEL", "INFO") + @pytest.fixture def harness( service_module: ModuleType, monkeypatch: pytest.MonkeyPatch, tmp_path: Path, -) -> _LoopHarness: - return _LoopHarness(service_module, monkeypatch, tmp_path) +) -> Iterator[_LoopHarness]: + # Snapshot the root logger's handlers so each test's + # ``attach_servicemanager_handler`` call doesn't leak into the + # next test. Without this, a previous test's handler would still + # be attached and would forward records to a stale MagicMock — + # which is harmless for assertions on the current ``sm`` but + # would muddy any future assertions about the root logger's + # handler list. + root = logging.getLogger() + original_handlers = list(root.handlers) + original_level = root.level + try: + yield _LoopHarness(service_module, monkeypatch, tmp_path) + finally: + for handler in root.handlers: + if handler not in original_handlers: + try: + handler.close() + except Exception: + pass + root.handlers = original_handlers + root.setLevel(original_level) class TestRunServiceLoopHappyPath: @@ -1266,3 +1317,268 @@ def test_matching_checksum_skips_push(self, harness: _LoopHarness) -> None: harness.client.push_config.assert_not_called() assert len(harness.start_calls) == 1 + + +class TestRunServiceLoopLogging: + """The service path must wire up file + Event-Log logging before doing anything else. + + Without this, any failure between ``SvcDoRun`` being invoked and + the first explicit ``logger.error`` call would be invisible — + which is the original "service crashes immediately, no logs" + bug the logging gaps closure is fixing. These tests lock in: + + 1. ``setup_file_logging`` is called before any other work, so + a registry-read failure on the very next line still produces + a record on disk. + 2. The converted ``logger.error(...)`` calls in + ``_run_service_loop`` are routed back to ``sm.LogErrorMsg`` + via the attached ``_ServiceManagerHandler``, preserving the + operator-visible Windows event log behavior. + """ + + def test_setup_file_logging_runs_before_registry_read( + self, + harness: _LoopHarness, + ) -> None: + # Record the call order: file-logging setup must precede the + # registry read so a failure inside the read is still + # captured on disk. + order: list[str] = [] + + from data_hub_watcher import logging_setup + + def _record_setup() -> Path: + order.append("setup_file_logging") + return harness.tmp_path / "watcher.log" + + def _record_registry_read() -> tuple[Path, Path]: + order.append("read_paths_from_registry") + return harness.config_path, harness.env_path + + harness.monkeypatch.setattr(logging_setup, "setup_file_logging", _record_setup) + harness.monkeypatch.setattr(harness.svc, "_read_paths_from_registry", _record_registry_read) + + stop_event = threading.Event() + stop_event.set() + harness.svc._run_service_loop(stop_event, harness.sm) + + assert order[0] == "setup_file_logging" + assert "read_paths_from_registry" in order + assert order.index("setup_file_logging") < order.index("read_paths_from_registry") + + def test_logger_error_reaches_log_error_msg_via_handler( + self, + harness: _LoopHarness, + ) -> None: + # Smoke-test the wiring: the registry-read failure path uses + # ``logger.error(...)`` now, but historically the test + # ``test_registry_read_failure_exits_with_error_log`` asserted + # against ``sm.LogErrorMsg`` directly. Confirm the handler + # has been attached and is forwarding so the same operator + # contract holds (registry/install language in the event log + # entry) regardless of the stdlib-logging refactor. + def boom() -> tuple[Path, Path]: + raise OSError("registry key missing") + + harness.monkeypatch.setattr(harness.svc, "_read_paths_from_registry", boom) + + with pytest.raises(SystemExit): + harness.svc._run_service_loop(threading.Event(), harness.sm) + + # The Event-Log handler formats records with + # ``EVENT_LOG_FORMAT`` (``: ``) — asctime and + # the bracketed level prefix are intentionally dropped because + # the Windows Event Log already records ``TimeCreated`` and + # ``LevelDisplayName`` per entry. Substring checks remain the + # right assertion shape because operator-facing wording must + # not silently drift on a refactor. + harness.sm.LogErrorMsg.assert_called_once() + forwarded = harness.sm.LogErrorMsg.call_args.args[0] + assert "registry" in forwarded.lower() + assert "service install" in forwarded + + def test_startup_emits_pid_and_log_path_info_message( + self, + harness: _LoopHarness, + ) -> None: + # On a healthy host the very first thing visible in the event + # log should be a service-starting line that includes the + # PID and the resolved log path. Lab operators use this to + # confirm which python.exe instance is currently running and + # to copy-paste the log path into a remote-support session. + stop_event = threading.Event() + stop_event.set() + harness.svc._run_service_loop(stop_event, harness.sm) + + info_messages = [c.args[0] for c in harness.sm.LogInfoMsg.call_args_list] + assert any( + "starting" in m.lower() and "pid=" in m.lower() and "log=" in m.lower() + for m in info_messages + ) + + +class TestBootstrapFailureLog: + """Phase-A/B crashes (before the dispatcher hands off to ``SvcDoRun``) + must still leave a trace on disk via ``service-bootstrap.log``. This is + the only logging path that bypasses ``logging_setup`` because the + failure mode it captures may include ``logging`` itself or + ``pathlib`` being broken on the host.""" + + def test_writes_traceback_to_bootstrap_log( + self, + service_module: ModuleType, + monkeypatch: pytest.MonkeyPatch, + tmp_path: Path, + ) -> None: + from data_hub_watcher import constants + + monkeypatch.setattr(constants, "WATCHER_LOG_DIR", tmp_path) + monkeypatch.setattr(service_module, "WATCHER_LOG_DIR", tmp_path) + + try: + raise RuntimeError("simulated dispatcher failure") + except RuntimeError as exc: + service_module._write_bootstrap_failure(exc) + + bootstrap_log = tmp_path / "service-bootstrap.log" + assert bootstrap_log.exists() + contents = bootstrap_log.read_text(encoding="utf-8") + assert "bootstrap failure" in contents + assert "simulated dispatcher failure" in contents + assert "RuntimeError" in contents + + def test_appends_subsequent_failures( + self, + service_module: ModuleType, + monkeypatch: pytest.MonkeyPatch, + tmp_path: Path, + ) -> None: + # The SCM retries the service on failure, so subsequent + # bootstrap crashes must accumulate in the log rather than + # truncate it — operators need the full history to triage a + # restart loop. + from data_hub_watcher import constants + + monkeypatch.setattr(constants, "WATCHER_LOG_DIR", tmp_path) + monkeypatch.setattr(service_module, "WATCHER_LOG_DIR", tmp_path) + + for i in range(3): + try: + raise ValueError(f"attempt {i}") + except ValueError as exc: + service_module._write_bootstrap_failure(exc) + + contents = (tmp_path / "service-bootstrap.log").read_text(encoding="utf-8") + assert "attempt 0" in contents + assert "attempt 1" in contents + assert "attempt 2" in contents + + def test_silent_when_log_write_fails( + self, + service_module: ModuleType, + monkeypatch: pytest.MonkeyPatch, + tmp_path: Path, + ) -> None: + # The bootstrap helper must NEVER raise — it runs in an + # except block whose only job is to re-raise the original + # exception. If we fail to write the log (out-of-disk, locked + # file, perms) the operator still needs to see the original + # SystemExit propagate to the SCM. + from data_hub_watcher import constants + + # Point at a path that cannot be created (file-as-parent). + bogus_parent = tmp_path / "blocker" + bogus_parent.write_text("not a directory") + monkeypatch.setattr(constants, "WATCHER_LOG_DIR", bogus_parent / "child") + monkeypatch.setattr(service_module, "WATCHER_LOG_DIR", bogus_parent / "child") + + try: + raise RuntimeError("original failure") + except RuntimeError as exc: + # Must not raise even though directory creation will fail. + service_module._write_bootstrap_failure(exc) + + +class TestStartServiceDispatcher: + """``_start_service_dispatcher`` must distinguish *unexpected* crashes + from clean SCM exit signals. + + The bootstrap log exists for crashes that happen before + ``SvcDoRun`` is reachable (broken venv, missing ``pywin32``, + import-time errors). ``SystemExit`` is the canonical "exit with a + non-zero code" mechanism the in-process loop uses to ask the SCM + to restart the service after an upgrade — treating those as + bootstrap failures would append a fresh traceback on every clean + upgrade restart, defeating the purpose of the channel. + """ + + def test_unexpected_exception_writes_bootstrap_log_and_reraises( + self, + service_module: ModuleType, + monkeypatch: pytest.MonkeyPatch, + tmp_path: Path, + ) -> None: + from data_hub_watcher import constants + + monkeypatch.setattr(constants, "WATCHER_LOG_DIR", tmp_path) + monkeypatch.setattr(service_module, "WATCHER_LOG_DIR", tmp_path) + + sm = sys.modules["servicemanager"] + sm.StartServiceCtrlDispatcher.side_effect = RuntimeError("dispatcher exploded") + + with pytest.raises(RuntimeError, match="dispatcher exploded"): + service_module._start_service_dispatcher() + + bootstrap_log = tmp_path / "service-bootstrap.log" + assert bootstrap_log.exists() + contents = bootstrap_log.read_text(encoding="utf-8") + assert "dispatcher exploded" in contents + assert "RuntimeError" in contents + + def test_systemexit_propagates_without_bootstrap_log( + self, + service_module: ModuleType, + monkeypatch: pytest.MonkeyPatch, + tmp_path: Path, + ) -> None: + # The upgrade-restart path raises ``SystemExit(1)`` inside + # ``_run_service_loop``. If pywin32 propagates that out of + # ``StartServiceCtrlDispatcher`` (version-dependent behavior), + # we must NOT write a misleading "bootstrap failure" entry — + # the watcher exited cleanly to trigger the SCM's recovery + # action, not because of a bootstrap-window crash. + from data_hub_watcher import constants + + monkeypatch.setattr(constants, "WATCHER_LOG_DIR", tmp_path) + monkeypatch.setattr(service_module, "WATCHER_LOG_DIR", tmp_path) + + sm = sys.modules["servicemanager"] + sm.StartServiceCtrlDispatcher.side_effect = SystemExit(1) + + with pytest.raises(SystemExit) as excinfo: + service_module._start_service_dispatcher() + + assert excinfo.value.code == 1 + assert not (tmp_path / "service-bootstrap.log").exists() + + def test_keyboard_interrupt_propagates_without_bootstrap_log( + self, + service_module: ModuleType, + monkeypatch: pytest.MonkeyPatch, + tmp_path: Path, + ) -> None: + # Operator Ctrl-C from ``win32serviceutil debug`` (the + # debug-in-foreground path referenced in the troubleshooting + # guide) must also be treated as a clean exit signal. + from data_hub_watcher import constants + + monkeypatch.setattr(constants, "WATCHER_LOG_DIR", tmp_path) + monkeypatch.setattr(service_module, "WATCHER_LOG_DIR", tmp_path) + + sm = sys.modules["servicemanager"] + sm.StartServiceCtrlDispatcher.side_effect = KeyboardInterrupt() + + with pytest.raises(KeyboardInterrupt): + service_module._start_service_dispatcher() + + assert not (tmp_path / "service-bootstrap.log").exists()