From 89ed7397fc9cde0c1b573449b2251799c6fb1646 Mon Sep 17 00:00:00 2001 From: Marcus Date: Tue, 11 Aug 2026 01:12:12 +0800 Subject: [PATCH 1/2] fix: degrade on bad Slack settings, catch typos early, strip comments Three things came out of setting Slack up against a real workspace. A misconfigured optional notifier could stop the program from logging: a malformed credential raised out of the first log call and killed the process. The handler already refuses to let a dead webhook do that, so a typo in the same feature should not either. Slack is now switched off and the reason written once at CRITICAL; log_dir and level still raise, since there is nothing sensible to fall back to there. LoggerConfig.slack_problem() is the check. Setting names are checked by Logger() and configure() rather than where they are resolved. Resolution is lazy, so configure(load_env=True) used to fail at the first log call with a traceback pointing at a line that was perfectly correct. Near misses are now suggested, e.g. did you mean load_dotenv. chat.postMessage payloads carry a top-level text field as well as the attachment. Without it the push notification and sidebar preview arrive blank. Also: comments removed from the source, with the two load-bearing ones folded into docstrings; a README appendix on inviting the bot to the channel, which is the most common reason a correct-looking setup delivers nothing, along with the error codes that distinguish it and the "# common" copy-paste trap. Verified: 153 tests on 3.8/3.9/3.12, pre-commit clean, wheel builds, every README example executed, and alerts confirmed arriving in a real Slack channel. Co-Authored-By: Claude Opus 5 --- README.md | 129 +++++++++++-- main.py | 2 +- src/loggerhelper/_internal/__init__.py | 6 +- src/loggerhelper/_internal/config.py | 177 +++++++----------- src/loggerhelper/_internal/decorators.py | 23 +-- src/loggerhelper/_internal/format.py | 41 +--- src/loggerhelper/_internal/handler.py | 34 +--- .../_internal/notifiers/__init__.py | 8 +- src/loggerhelper/_internal/notifiers/slack.py | 90 +++------ src/loggerhelper/logger.py | 81 ++++---- tests/_internal/test_config.py | 90 +++++++-- tests/_internal/test_slack.py | 115 ++++++++++++ 12 files changed, 458 insertions(+), 338 deletions(-) diff --git a/README.md b/README.md index 354f013..3d08124 100644 --- a/README.md +++ b/README.md @@ -5,7 +5,7 @@ A small logging package with no dependencies: - Coloured console output, plain text in files - One file per level under a dated directory, rotated by size and by day - A decorator that logs an escaping exception and names the definition it escaped from -- Optional Slack alerts, attached only when a webhook is configured +- Optional Slack alerts, attached only when a credential is configured This README is the complete reference. The source carries no type annotations, so every signature and accepted value is written out below. @@ -28,6 +28,7 @@ so every signature and accepted value is written out below. - [Upgrading from 1.x](#upgrading-from-1x) - [Development](#development) - [Deployment](#deployment) +- [Appendix: the bot must be in the channel](#appendix-the-bot-must-be-in-the-channel) --- @@ -340,11 +341,13 @@ SLACK_BOT_TOKEN=xoxb-YOUR-BOT-TOKEN SLACK_CHANNEL=#alerts ``` -Step 5 is easy to forget — without it Slack answers `not_in_channel` and the -alert is reported to stderr rather than delivered. +Step 5 is easy to forget, and it is the most common reason a correct-looking +setup delivers nothing: without it Slack answers `not_in_channel` and the alert +is reported to stderr instead. Slack's UI writes the channel as `# common` with +a space for looks — the name is `common`, so the value is `#common`. -Set one or the other. Setting both is refused, because they mean two different -destinations and silently picking one would be worse than saying so. +Set one or the other. Setting both is reported as a problem, because they name +two different destinations and silently picking one would be worse. ### Configuring it @@ -383,9 +386,29 @@ traceback, coloured by severity. - **Notices silent rejections.** `chat.postMessage` answers `200 OK` with `{"ok": false}` for a bad channel or a missing scope; that is treated as the failure it is, not as a delivered message. -- **`https://` only,** and credentials never appear in a `repr()` — an - `http://` webhook is rejected rather than putting the secret on the wire in - clear text. +- **`https://` only,** and credentials never appear in a `repr()` or in an error + message, so neither can leak into a log file. + +### If the Slack settings are wrong + +Alerting is an optional extra, so a mistake in it never stops the program from +logging. Slack is switched off and the reason is written once, at `CRITICAL`, to +the console and to `CRITICAL.log`: + +``` +[2026-08-11 09:14:02]-CRITICAL-(...)=> Slack alerts are disabled: SLACK_BOT_TOKEN +does not look like a bot token; it should start with 'xoxb-'. The Basic +Information page has no bot token on it -- find it under OAuth & Permissions -> +Bot User OAuth Token +``` + +This applies to the credential being malformed, both credentials being set at +once, a token without a channel, and a non-`https` webhook. It deliberately does +**not** apply to `LOG_LEVEL` or `LOG_DIR`, where there is nothing sensible to +fall back to and the error is raised. + +`config.slack_problem()` returns that sentence, or `None` when Slack is usable, +if you would rather check at start-up yourself. --- @@ -500,7 +523,8 @@ act as the base for several loggers that differ in a detail. | ------------------------------- | ------------------------------------------------------- | | `LoggerConfig.from_env(env=None, **overrides)` | Build from the environment, overrides winning | | `config.replace(**changes)` | A copy with some settings changed; `None` means "leave it" | -| `config.slack_enabled` | Whether a Slack credential was configured | +| `config.slack_enabled` | Whether Slack will actually be used | +| `config.slack_problem()` | Why it will not, as a sentence, or `None` | | `LoggerConfig.SETTINGS` | The names of every accepted setting | `repr()` masks the Slack credentials, so a config is safe to log or to include @@ -509,8 +533,17 @@ in a traceback. ### `ConfigError` Raised for a setting that cannot be used — an unknown level, a non-numeric size, -an `http://` webhook. Subclasses `ValueError`, and the message names the setting -and lists the valid values. +a misspelled setting name. Subclasses `ValueError`; the message names the +setting, lists the valid values, and suggests the intended spelling for a near +miss (`unknown setting(s): 'load_env' (did you mean 'load_dotenv'?)`). + +Names are checked by `Logger()` and `configure()` immediately, not when the +settings are finally resolved — settings resolve lazily, so otherwise a typo +would surface at the first log call and point the traceback at a line that is +perfectly correct. + +Slack problems are the exception: they are reported rather than raised, as +described [above](#if-the-slack-settings-are-wrong). --- @@ -607,6 +640,80 @@ That is the only place it is written — `pyproject.toml` declares the version `dynamic` and reads it from there, so the built artefact and `loggerhelper.__version__` cannot disagree. +--- + +## Appendix: the bot must be in the channel + +**If you use `SLACK_BOT_TOKEN`, adding the app to the channel is a required +step. Without it nothing is delivered, no matter how correct the settings are.** + +This is the single most common reason a working-looking setup stays silent. +Everything checks out — the token is valid, `chat:write` is granted, the channel +name is right — and Slack still refuses, because a bot may only post where it +has been invited. + +### Do this + +In the channel you want alerts in, type: + +``` +/invite @your-app-name +``` + +Use the app's name as it appears in Slack (the bot user, e.g. `@loggerhelper`), +not the app ID. Repeat it for every channel you point `SLACK_CHANNEL` at. + +For a **private** channel you must invite the bot as well, and the token needs +the `groups:write` scope on top of `chat:write`. + +An **incoming webhook** does not need any of this — the channel was chosen when +the webhook was created, and access came with it. If you would rather not manage +invitations, use `SLACK_WEBHOOK_URL` instead. + +### How it looks when this is the problem + +The application keeps running and keeps logging normally; only the alert is +lost. It is reported once on stderr: + +``` +loggerhelper: Slack notification failed, staying quiet from here: +RuntimeError: Slack rejected the message: 'not_in_channel' +``` + +`not_in_channel` is Slack's way of saying exactly this. Note that +`chat.postMessage` returns **HTTP 200** for it — the failure is in the response +body, not the status code, which is why a hand-rolled webhook client usually +reports success here and this one does not. + +### Telling the failures apart + +| Slack says | What it means | Fix | +| ------------------- | --------------------------------- | ---------------------------------------------- | +| `not_in_channel` | The bot is not in that channel | `/invite @your-app-name` in the channel | +| `channel_not_found` | No channel by that name | Check `SLACK_CHANNEL`; see the note below | +| `missing_scope` | The token lacks `chat:write` | Add the scope, then **reinstall** the app | +| `invalid_auth` | The token is wrong or revoked | Copy the Bot User OAuth Token again | +| `is_archived` | The channel is archived | Point at a live channel | + +Adding a scope does not take effect until the app is reinstalled to the +workspace, and reinstalling issues a **new token** — remember to update +`SLACK_BOT_TOKEN`. + +### The `# common` trap + +Slack's UI renders a channel as `# common`, with a space after the hash, purely +for looks. The name is `common`. Copying what you see gives you a value with a +space in it, and Slack answers `channel_not_found` because no channel can +contain a space. + +```dotenv +SLACK_CHANNEL=#common # right +SLACK_CHANNEL=# common # wrong: that space is Slack's typography +``` + +The channel ID (`C0123456789`, from **Copy link** on the channel) also works and +avoids the question entirely. It keeps working if the channel is renamed. + ## License MIT diff --git a/main.py b/main.py index c7a6e91..0726628 100644 --- a/main.py +++ b/main.py @@ -2,7 +2,7 @@ from loggerhelper import configure, log -configure(log_dir="./log", level="DEBUG") +configure(log_dir="./log", level="DEBUG", load_dotenv=True) log.debug("cache hit for key=42") log.info("System started") diff --git a/src/loggerhelper/_internal/__init__.py b/src/loggerhelper/_internal/__init__.py index 0b11335..e121fc6 100644 --- a/src/loggerhelper/_internal/__init__.py +++ b/src/loggerhelper/_internal/__init__.py @@ -1,8 +1,6 @@ """ Implementation detail. Nothing here is part of the public API. -Consumers import from ``loggerhelper`` (or ``loggerhelper.logger``); the layout -inside this package may change in any release. Modules here may import each -other, but must never import ``loggerhelper.logger`` -- the dependency runs one -way, outward. +Consumers import from ``loggerhelper``; the layout inside may change in any +release. Modules here may import each other, never ``loggerhelper.logger``. """ diff --git a/src/loggerhelper/_internal/config.py b/src/loggerhelper/_internal/config.py index e3725cb..c9a391e 100644 --- a/src/loggerhelper/_internal/config.py +++ b/src/loggerhelper/_internal/config.py @@ -1,15 +1,6 @@ -""" -Where a logger's settings come from. - -Precedence is explicit argument, then environment variable, then the default -defined here -- so a consumer who only cares about the directory writes -``configure(log_dir="./logs")`` and a deployment overrides the level without -touching code. - -``env`` is a parameter rather than a direct ``os.environ`` read so tests can -inject a mapping instead of mutating the process environment. -""" +"""Settings resolution: explicit argument, then environment, then default.""" +import difflib import os from pathlib import Path @@ -19,13 +10,10 @@ DEFAULT_RETENTION_DAYS = 30 DEFAULT_SLACK_LEVEL = "WARNING" -#: The levels that get their own file. Ordered least to most severe. LEVEL_NAMES = ("DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL") _LEVEL_NUMBERS = {"DEBUG": 10, "INFO": 20, "WARNING": 30, "ERROR": 40, "CRITICAL": 50} -# What `logging` itself accepts, so a value copied from another config still works. _LEVEL_ALIASES = {"WARN": "WARNING", "FATAL": "CRITICAL"} - _COLOR_MODES = ("auto", "always", "never") @@ -34,7 +22,6 @@ class ConfigError(ValueError): def normalise_level(value, source="level"): - """Canonical upper-case level name, or a message naming the valid ones.""" name = str(value).strip().upper() name = _LEVEL_ALIASES.get(name, name) if name not in _LEVEL_NUMBERS: @@ -45,21 +32,11 @@ def normalise_level(value, source="level"): def level_number(value): - """ - The `logging` integer for a level name. - - Replaces the private ``logging._nameToLevel`` the first version reached for. - """ return _LEVEL_NUMBERS[normalise_level(value)] def detect_log_dir(start=None): - """ - Walk up from the working directory for a project root and put ``log/`` there. - - Anchored on the working directory rather than this file, so an installed - package logs into the consumer's project instead of into site-packages. - """ + """Put ``log/`` at the project root, found by walking up from the cwd.""" current = Path.cwd() if start is None else Path(start) for parent in [current, *current.parents]: for marker in (".venv", "pyproject.toml", ".git"): @@ -76,26 +53,8 @@ def _as_int(raw, source): class LoggerConfig: - """ - Everything a Logger needs, already validated. - - ``log_dir`` where the dated directories go; detected if omitted - ``level`` threshold, one of LEVEL_NAMES - ``name`` tag on every line; also separates one logger from another - ``max_bytes`` per-file cap before rotation; 0 disables size rotation - ``backup_count`` rotated copies kept - ``retention_days`` dated directories older than this are deleted; 0 keeps all - ``color`` "auto", "always" or "never" - ``slack_webhook_url`` an incoming webhook; the channel is baked into the URL - ``slack_bot_token`` an ``xoxb-`` token, the other way to reach Slack - ``slack_channel`` which channel the bot token posts to; required with it - ``slack_level`` threshold for Slack alerts - ``slack_env`` deployment tag ("prod") shown on alerts - - Slack stays entirely unconfigured unless one of the two credentials is set. - """ + """Everything a Logger needs, already validated. See the README for each setting.""" - #: Every accepted setting, in the order they appear in __init__. SETTINGS = ( "log_dir", "level", @@ -111,6 +70,8 @@ class LoggerConfig: "slack_env", ) + _SECRETS = ("slack_webhook_url", "slack_bot_token") + def __init__( self, log_dir=None, @@ -146,61 +107,52 @@ def __init__( raise ConfigError(f"{attr}={value!r} must be a whole number >= 0") setattr(self, attr, value) - url = slack_webhook_url.strip() or None if slack_webhook_url is not None else None - if url is not None and not url.startswith("https://"): - # The handler posts to this with urllib; anything but https is - # either a typo or credentials over the wire in clear text. - raise ConfigError(f"slack_webhook_url={slack_webhook_url!r} must be https://") - self.slack_webhook_url = url - - token = slack_bot_token.strip() or None if slack_bot_token is not None else None - if token is not None and not token.startswith("xox"): - raise ConfigError( - "slack_bot_token does not look like a Slack token (it should start with " - "'xoxb-'). Find it under OAuth & Permissions -> Bot User OAuth Token." - ) - self.slack_bot_token = token + self.slack_webhook_url = slack_webhook_url.strip() or None if slack_webhook_url else None + self.slack_bot_token = slack_bot_token.strip() or None if slack_bot_token else None self.slack_channel = slack_channel.strip() or None if slack_channel else None - if url and token: - raise ConfigError( - "slack_webhook_url and slack_bot_token are two different ways to reach " - "Slack; set one, not both. The webhook already names its channel, the " - "token needs slack_channel." - ) - if token and not self.slack_channel: - raise ConfigError( - "slack_bot_token needs slack_channel (SLACK_CHANNEL) -- a token can post " - "anywhere, so it cannot guess which channel you meant." - ) + def _shown(self, name): + value = getattr(self, name) + return "***" if value and name in self._SECRETS else repr(value) def __repr__(self): - #: Credentials must not end up in a log line or a traceback. - secret = ("slack_webhook_url", "slack_bot_token") - shown = ", ".join( - f"{name}={'***' if name in secret and getattr(self, name) else getattr(self, name)!r}" - for name in self.SETTINGS - ) + shown = ", ".join(f"{name}={self._shown(name)}" for name in self.SETTINGS) return f"LoggerConfig({shown})" - @property - def slack_enabled(self): - """No credential configured means the Slack plugin stays out of the way.""" - return bool(self.slack_webhook_url or self.slack_bot_token) - - def replace(self, **changes): + def slack_problem(self): """ - A copy with some settings changed. A change of ``None`` is ignored. + Why Slack cannot be used, as a sentence, or None if it can. - Lets one config act as a base for several loggers that differ in a - detail or two, rather than each having to repeat the whole set. + Reported rather than raised: a mistake in an optional notifier must not + stop the program from logging. Never quotes a value back -- two of the + three are credentials. """ - unknown = set(changes) - set(self.SETTINGS) - if unknown: - raise ConfigError( - f"unknown setting(s): {', '.join(sorted(unknown))}. " - f"Known settings: {', '.join(self.SETTINGS)}" + url, token = self.slack_webhook_url, self.slack_bot_token + if url and token: + return ( + "SLACK_WEBHOOK_URL and SLACK_BOT_TOKEN are two different ways to reach " + "Slack and they name different destinations; set one, not both" + ) + if url and not url.startswith("https://"): + return "SLACK_WEBHOOK_URL must start with https://" + if token and not token.startswith("xox"): + return ( + "SLACK_BOT_TOKEN does not look like a bot token; it should start with " + "'xoxb-'. The Basic Information page has no bot token on it -- find it " + "under OAuth & Permissions -> Bot User OAuth Token" ) + if token and not self.slack_channel: + return "SLACK_BOT_TOKEN needs SLACK_CHANNEL; a token can post to any channel" + return None + + @property + def slack_enabled(self): + """Whether Slack will actually be used. slack_problem() says why not.""" + return bool(self.slack_webhook_url or self.slack_bot_token) and not self.slack_problem() + + def replace(self, **changes): + """A copy with some settings changed. A change of None is ignored.""" + check_setting_names(changes) values = {name: getattr(self, name) for name in self.SETTINGS} values.update({k: v for k, v in changes.items() if v is not None}) return LoggerConfig(**values) @@ -208,11 +160,10 @@ def replace(self, **changes): @classmethod def from_env(cls, env=None, **overrides): """ - Build a config from the environment, with ``overrides`` winning. + Build from the environment, with overrides winning. - An override of ``None`` means "not given" and falls through to the - environment -- so callers can pass optional arguments straight down - without branching on whether the user supplied them. + An override of None means "not given" and falls through to the + environment, so callers can forward optional arguments without branching. """ env = os.environ if env is None else env values = {} @@ -241,22 +192,34 @@ def pick(field_name, env_key, cast=None): pick("slack_level", "SLACK_LOG_LEVEL") pick("slack_env", "SLACK_ENV") - if remaining: - unknown = ", ".join(sorted(remaining)) - raise ConfigError( - f"unknown setting(s): {unknown}. Known settings: {', '.join(cls.SETTINGS)}" - ) - + check_setting_names(remaining) return cls(**values) -def parse_dotenv(text): +def check_setting_names(names, extra=()): """ - Parse ``KEY=value`` lines. Deliberately small: no interpolation, no export. + Reject unknown setting names, suggesting a near miss. - Kept here rather than taking a dependency, since this package promises to - install nothing. + Called from Logger() and configure() rather than where settings are + resolved: resolution is lazy, so otherwise a typo surfaces at the first log + call and the traceback points at a line that is perfectly correct. """ + known = tuple(LoggerConfig.SETTINGS) + tuple(extra) + unknown = sorted(name for name in names if name not in known) + if not unknown: + return + + described = [] + for name in unknown: + close = difflib.get_close_matches(name, known, n=1) + described.append(f"{name!r} (did you mean {close[0]!r}?)" if close else repr(name)) + raise ConfigError( + f"unknown setting(s): {', '.join(described)}. Known settings: {', '.join(known)}" + ) + + +def parse_dotenv(text): + """Parse KEY=value lines. No interpolation, no dependency.""" values = {} for line in text.splitlines(): stripped = line.strip() @@ -279,10 +242,10 @@ def parse_dotenv(text): def load_repo_dotenv(filename=".env", start=None, override=False): """ - Apply the nearest ``.env`` walking up from the working directory. + Apply the nearest .env walking up from the working directory. - Off by default: a library that edits ``os.environ`` on import surprises the - application that imported it. ``configure(load_dotenv=True)`` opts in. + Off unless asked for: a library that edits os.environ on import surprises + the application that imported it. """ current = Path.cwd() if start is None else Path(start) for parent in [current, *current.parents]: diff --git a/src/loggerhelper/_internal/decorators.py b/src/loggerhelper/_internal/decorators.py index 8dbc19c..cf7671c 100644 --- a/src/loggerhelper/_internal/decorators.py +++ b/src/loggerhelper/_internal/decorators.py @@ -1,16 +1,4 @@ -""" -The ``@catch`` decorator: log an escaping exception, and say which definition -it escaped from. - -Three things changed from the first version's ``@logger.error``: - -* it re-raises by default. Swallowing turned a precise exception into a stray - ``None`` that the caller could not tell from a real result. -* it emits one record carrying the traceback, not two. Two records interleave - with other lines in the file, and fire any alerting integration twice. -* it works on ``async def``. Decorating a coroutine function previously - returned the coroutine object without awaiting it, so nothing was ever caught. -""" +"""The ``@catch`` decorator: log an escaping exception, and name where it came from.""" import functools import inspect @@ -21,9 +9,8 @@ def describe_failure(func, exc): """ ``TypeError in service.pool.AdapterPool.acquire (pool.py:87): ...`` - ``__qualname__`` so a method reads as ``Class.method``, and the line comes - from the deepest traceback frame -- where the exception was actually raised, - not where the decorator happens to sit. + The line comes from the deepest traceback frame -- where the exception was + actually raised, not where the decorator sits. """ where = f"{getattr(func, '__module__', '?')}.{getattr(func, '__qualname__', func)}" @@ -43,8 +30,8 @@ def catch(emit, func=None, level="ERROR", reraise=True, default=None, exclude=() Wrap ``func`` so an escaping exception is logged through ``emit``. ``emit(level, message, exception)`` is a callable rather than a logger, so - the decorator can be applied at import time without forcing a logger to be - built. Usable bare (``@catch``) or called (``@catch(level="CRITICAL")``). + decorating at import time does not force a logger to be built. Usable bare + or called, on ``def`` and on ``async def``. """ def decorate(target): diff --git a/src/loggerhelper/_internal/format.py b/src/loggerhelper/_internal/format.py index 009ae6d..f47a94c 100644 --- a/src/loggerhelper/_internal/format.py +++ b/src/loggerhelper/_internal/format.py @@ -1,10 +1,4 @@ -""" -How a record turns into a line. - -Two things happen here. ``OriginFilter`` answers "which definition wrote this", -which is the whole point of the ``(module.function:line)`` field. The formatters -then render it, coloured on a terminal and plain everywhere else. -""" +"""Turning a record into a line: the origin field, and colour on a terminal.""" import copy import logging @@ -13,7 +7,6 @@ from functools import lru_cache from pathlib import Path -#: The line every handler renders. `origin` comes from OriginFilter. BASE_FORMAT = "[%(asctime)s]-%(levelname)s-(%(origin)s)=> %(message)s" DATE_FORMAT = "%Y-%m-%d %H:%M:%S" @@ -27,8 +20,6 @@ class Color: CRITICAL_RED = "\033[91m" -# Keyed on levelno rather than levelname: the name gets wrapped in escape codes -# on its way out, the number never changes. LEVEL_COLORS = { logging.DEBUG: Color.GREY, logging.INFO: Color.GREEN, @@ -37,16 +28,12 @@ class Color: logging.CRITICAL: Color.CRITICAL_RED, } -# Deep nesting is not worth a directory walk per source file. _MAX_PACKAGE_DEPTH = 10 @lru_cache(maxsize=512) def _dotted_module(pathname, fallback): - """ - ``src/service/pool.py`` -> ``service.pool``, by walking up while there is an - ``__init__.py``. Cached, so the directory probing costs once per source file. - """ + """``src/service/pool.py`` -> ``service.pool``, cached per source file.""" try: path = Path(pathname) except (TypeError, ValueError): @@ -72,10 +59,8 @@ class OriginFilter(logging.Filter): """ Attach ``record.origin`` -- ``module.function:line`` of the call site. - This replaces the random per-process UUID the first version printed, which - carried no information a single-process program could use. Correct output - depends on the caller passing ``stacklevel`` so the record points at user - code and not at this package. + Correct output depends on the caller passing ``stacklevel``, so the record + points at user code and not at this package. """ def __init__(self, tag=None): @@ -97,11 +82,8 @@ class ColorFormatter(logging.Formatter): """ The console line, with the level and timestamp coloured. - The first version coloured by running ``str.replace`` over the rendered - line, so a message that happened to contain ``-INFO-`` or the same timestamp - got mangled too. Colour is applied to the fields instead, and to a *copy* of - the record -- the file handlers format the same object and must not see the - escape codes. + Colour goes on the fields, and on a copy of the record: the file handlers + format the same object and must not see the escape codes. """ def __init__(self, fmt=None, datefmt=None, use_color=True): @@ -116,19 +98,17 @@ def format(self, record): clone.levelname = f"{color}{record.levelname}{Color.RESET}" return super().format(clone) - def formatTime(self, record, datefmt=None): # noqa: N802 - name fixed by logging + def formatTime(self, record, datefmt=None): # noqa: N802 stamp = super().formatTime(record, datefmt) color = LEVEL_COLORS.get(record.levelno, "") if self.use_color else "" return f"{color}{stamp}{Color.RESET}" if color else stamp def _enable_windows_ansi(): - """Turn on virtual terminal processing so escape codes render, not print.""" try: import ctypes kernel32 = ctypes.windll.kernel32 - # -11 is STD_OUTPUT_HANDLE, -12 STD_ERROR_HANDLE; 0x4 enables VT. for stream_id in (-11, -12): handle = kernel32.GetStdHandle(stream_id) mode = ctypes.c_uint32() @@ -141,12 +121,7 @@ def _enable_windows_ansi(): def should_use_color(mode, stream=None): - """ - ``always`` / ``never`` are taken at face value; ``auto`` asks the stream. - - Without this, piping output to a file or running under CI filled the log - with escape codes -- the first version coloured unconditionally. - """ + """``always``/``never`` at face value; ``auto`` asks the stream.""" if mode == "never": return False if mode == "auto": diff --git a/src/loggerhelper/_internal/handler.py b/src/loggerhelper/_internal/handler.py index b844e6b..13515f4 100644 --- a/src/loggerhelper/_internal/handler.py +++ b/src/loggerhelper/_internal/handler.py @@ -1,11 +1,4 @@ -""" -Where lines land. - -One file per level under a dated directory, as before -- but the date is -decided when a record is written rather than when the handler was built, so a -process that outlives midnight rolls over instead of writing into yesterday -forever. -""" +"""One file per level under a dated directory, rotated by size and by day.""" import logging import logging.handlers @@ -26,17 +19,16 @@ def _today(): def prune_old_logs(log_dir, retention_days): """ - Delete dated directories older than the retention window. Returns the count. + Delete dated directories older than the window, and return the count. - Only directories named exactly ``YYYY-MM-DD`` directly under ``log_dir`` are - touched -- whatever else the user keeps there is not ours to remove. + Only directories named exactly ``YYYY-MM-DD`` directly under ``log_dir`` + are touched; whatever else is kept there is not ours to remove. """ if retention_days <= 0: return 0 cutoff = date.today() - timedelta(days=retention_days) - root = Path(log_dir) try: - entries = list(root.iterdir()) + entries = list(Path(log_dir).iterdir()) except OSError: return 0 @@ -56,10 +48,10 @@ def prune_old_logs(log_dir, retention_days): class DailyDirRotatingFileHandler(logging.handlers.RotatingFileHandler): """ - ``//.log``, rotated by size and by day. + ``//.log``. - Opened lazily (``delay=True``): attaching the handler creates nothing, so a - program that only ever logs INFO does not leave four empty files behind. + The date is decided when a record is written, so a process that outlives + midnight rolls over. Opened lazily, so attaching the handler creates nothing. """ def __init__( @@ -87,25 +79,20 @@ def _path_for(self, day): return self.log_dir / day / f"{self.level_name}.log" def _open(self): - # The directory may not exist yet, or may have been cleaned up under us. Path(self.baseFilename).parent.mkdir(parents=True, exist_ok=True) return super()._open() - def shouldRollover(self, record): # noqa: N802 - logging API + def shouldRollover(self, record): # noqa: N802 if _today() != self._current_day: - # Checked before delegating: the parent opens the stream to measure - # it, and it would open yesterday's file to do so. return 1 return super().shouldRollover(record) - def doRollover(self): # noqa: N802 - logging API + def doRollover(self): # noqa: N802 today = _today() if today == self._current_day: super().doRollover() return - # A new day gets a fresh directory, so there is nothing to rename -- - # just point at the new path and let the next emit open it. if self.stream: self.stream.close() self.stream = None @@ -117,7 +104,6 @@ def doRollover(self): # noqa: N802 - logging API def get_file_handler(level_name, config): - """One handler per level, each taking only records of exactly that level.""" handler = DailyDirRotatingFileHandler( config.log_dir, level_name, diff --git a/src/loggerhelper/_internal/notifiers/__init__.py b/src/loggerhelper/_internal/notifiers/__init__.py index 0b42849..d643304 100644 --- a/src/loggerhelper/_internal/notifiers/__init__.py +++ b/src/loggerhelper/_internal/notifiers/__init__.py @@ -1,7 +1 @@ -""" -Optional outbound alerting. - -Each notifier is attached only when its configuration is present, so a -deployment that sets nothing gets exactly the behaviour it had before. Future -transports (Telegram, email) belong here alongside ``slack``. -""" +"""Optional outbound alerting, attached only when configured.""" diff --git a/src/loggerhelper/_internal/notifiers/slack.py b/src/loggerhelper/_internal/notifiers/slack.py index 43824b1..3d90502 100644 --- a/src/loggerhelper/_internal/notifiers/slack.py +++ b/src/loggerhelper/_internal/notifiers/slack.py @@ -1,21 +1,10 @@ """ -Slack alerts for WARNING and above, when a credential is configured. +Slack alerts, by incoming webhook or by bot token. -Slack offers two ways in and this supports both, because which one you have -depends on how the app was set up: - -* an **incoming webhook** (``https://hooks.slack.com/services/...``), which has - its channel baked in; or -* a **bot token** (``xoxb-...``) posted to ``chat.postMessage``, which needs to - be told the channel. - -Two constraints shape the rest. Logging must never block the caller, so the POST -happens on a background thread behind a bounded queue. And an error loop must -not flood the channel (or get the app rate-limited by Slack), so repeats of the -same failure are collapsed into a count. - -Sending nothing is always preferable to raising: a broken webhook is not the -application's problem to handle. +Logging must never block the caller, so the POST happens on a background thread +behind a bounded queue. An error loop must not flood the channel, so repeats are +collapsed into a count. Sending nothing beats raising: a broken webhook is not +the application's problem to handle. """ import atexit @@ -31,10 +20,8 @@ from ..config import level_number -#: Where a bot token posts. A webhook carries its own URL. CHAT_POST_MESSAGE_URL = "https://slack.com/api/chat.postMessage" -#: Slack renders a wall of text badly and rejects very large payloads. MAX_TEXT_CHARS = 2800 DEFAULT_THROTTLE_SECONDS = 60.0 DEFAULT_MAX_PER_MINUTE = 20 @@ -55,10 +42,7 @@ def _truncate(text, limit=MAX_TEXT_CHARS): class SlackHandler(logging.Handler): - """ - POST records to Slack, by webhook or by bot token. Runs on the listener - thread, so everything here is allowed to be slow. - """ + """Runs on the listener thread, so it is allowed to be slow.""" def __init__( self, @@ -97,11 +81,8 @@ def __init__( self._window_dropped = 0 self._reported_failure = False - # ---- throttling ------------------------------------------------- - @staticmethod def _key(record): - """Same level, same place, same exception type -- treat as a repeat.""" return ( record.levelname, getattr(record, "origin", record.name), @@ -109,10 +90,7 @@ def _key(record): ) def _admit(self, record, now): - """ - Decide whether to send. Returns how many repeats were folded in, or - ``None`` to stay quiet. - """ + """How many repeats were folded in, or None to stay quiet.""" key = self._key(record) with self._lock: if now - self._window_start >= 60.0: @@ -134,11 +112,7 @@ def _admit(self, record, now): self._window_count += 1 return self._suppressed.pop(key, 0) - # ---- rendering -------------------------------------------------- - def _payload(self, record, suppressed): - # QueueHandler.prepare already folded the traceback into the message, - # so the first line is the summary and the rest is the traceback. text = record.getMessage() title, _, detail = text.partition("\n") @@ -169,11 +143,17 @@ def _payload(self, record, suppressed): if detail.strip(): attachment["text"] = f"```{_truncate(detail.strip())}```" - return {"attachments": [attachment]} - - # ---- delivery --------------------------------------------------- + return { + "text": f"{record.levelname}: {_truncate(title, 300)}", + "attachments": [attachment], + } def _post(self, payload): + """ + A webhook signals failure with the status code, which urlopen raises on. + chat.postMessage answers 200 with ok:false instead, so a bad channel or + a missing scope would otherwise look like success. + """ headers = {"Content-Type": "application/json; charset=utf-8"} if self.bot_token: url = CHAT_POST_MESSAGE_URL @@ -188,14 +168,9 @@ def _post(self, payload): headers=headers, method="POST", ) - # The scheme is pinned to https in __init__ and again in LoggerConfig, - # so this cannot be pointed at file:// or ftp://. with urllib.request.urlopen(request, timeout=self.timeout) as response: # nosec B310 if not self.bot_token: return - # A webhook signals failure with a non-2xx status, which urlopen - # raises on. chat.postMessage answers 200 with ok:false instead, so - # a bad channel or a missing scope would otherwise look like success. body = json.loads(response.read().decode("utf-8") or "{}") if not body.get("ok"): raise RuntimeError(f"Slack rejected the message: {body.get('error')!r}") @@ -209,13 +184,8 @@ def emit(self, record): except Exception: self.handleError(record) - def handleError(self, record): # noqa: N802 - logging API - """ - Report the first failure and then go quiet. - - A webhook that is down usually stays down for a while; repeating the - stack trace for every record would bury the real output. - """ + def handleError(self, record): # noqa: N802 + """Report the first failure and then go quiet; a dead webhook stays dead.""" with self._lock: first = not self._reported_failure self._reported_failure = True @@ -231,8 +201,8 @@ class _DroppingQueueHandler(logging.handlers.QueueHandler): """ Hand records to the listener thread, dropping them if it falls behind. - A bounded queue is the point: an unbounded one turns a Slack outage during - an error storm into unbounded memory growth. + An unbounded queue would turn a Slack outage during an error storm into + unbounded memory growth. """ def __init__(self, q): @@ -240,8 +210,6 @@ def __init__(self, q): self.dropped = 0 def prepare(self, record): - # The parent clears exc_info (it may not be picklable), so capture the - # exception type first -- the throttle keys on it. if record.exc_info and record.exc_info[0] is not None: record.exc_type = record.exc_info[0].__name__ return super().prepare(record) @@ -254,13 +222,7 @@ def enqueue(self, record): class _IdempotentQueueListener(logging.handlers.QueueListener): - """ - A listener that can be stopped twice. - - ``Logger.close()`` stops it and so does the ``atexit`` hook; the stdlib - version raises on the second call, which surfaces as a traceback printed - during interpreter shutdown. - """ + """Logger.close() stops it and so does atexit; the stdlib raises on the second.""" def stop(self): if getattr(self, "_thread", None) is None: @@ -269,12 +231,7 @@ def stop(self): def create_slack_handler(config): - """ - Build the queued Slack handler, or ``None`` when no credential is configured. - - Returning ``None`` rather than a no-op handler keeps the "not configured" - case entirely free of cost. - """ + """The queued Slack handler, or None when Slack is not usable.""" if not config.slack_enabled: return None @@ -290,12 +247,9 @@ def create_slack_handler(config): handler = _DroppingQueueHandler(queue.Queue(maxsize=QUEUE_SIZE)) handler.setLevel(threshold) - # Only the message and its traceback survive the queue, so that is what the - # formatter has to produce. handler.setFormatter(logging.Formatter("%(message)s")) listener = _IdempotentQueueListener(handler.queue, target, respect_handler_level=True) listener.start() - # Anything still queued when the process ends should still get sent. atexit.register(listener.stop) return handler, listener diff --git a/src/loggerhelper/logger.py b/src/loggerhelper/logger.py index 490bdcb..6e2ba25 100644 --- a/src/loggerhelper/logger.py +++ b/src/loggerhelper/logger.py @@ -1,10 +1,8 @@ """ The logger itself -- the only implementation module a consumer needs to read. -Nothing is built until the first line is written. That matters because a -package that creates directories while being imported forces every consumer to -wrap it in a lazy holder of their own, and because ``@log.catch`` has to be -usable as a decorator at import time. +Nothing is built until the first line is written, so importing costs nothing and +``@log.catch`` is usable as a decorator at import time. """ import atexit @@ -13,14 +11,18 @@ import threading import warnings -from ._internal.config import LEVEL_NAMES, LoggerConfig, level_number, load_repo_dotenv +from ._internal.config import ( + LEVEL_NAMES, + LoggerConfig, + check_setting_names, + level_number, + load_repo_dotenv, +) from ._internal.decorators import catch as _catch from ._internal.format import OriginFilter from ._internal.handler import get_console_handler, get_file_handler, prune_old_logs from ._internal.notifiers.slack import create_slack_handler -# How many frames sit between a caller and `logging` when it goes through the -# public methods here: the method itself, plus `_emit`. _STACK_OFFSET = 2 @@ -28,17 +30,14 @@ class Logger: """ A colourful console logger that also splits its output into per-level files. - Construction is free -- no directories, no files, no threads. The first call - that actually logs something builds the handlers. - - Instances are keyed by ``name``: two ``Logger()`` objects with the same name - share one set of handlers, which is what stops the same line being written - twice. Give a distinct ``name`` to a logger that should write somewhere else. - - Accepts every setting LoggerConfig does; see the README for the full list. + Construction is free -- no directories, no files, no threads. Instances are + keyed by ``name``: two with the same name share one set of handlers, which + is what stops a line being written twice. Accepts every setting + ``LoggerConfig`` does; see the README. """ def __init__(self, log_dir=None, level=None, name=None, config=None, env=None, **settings): + check_setting_names(settings, extra=("config", "env")) self._explicit_config = config self._settings = dict(log_dir=log_dir, level=level, name=name, **settings) self._env = env @@ -48,16 +47,12 @@ def __init__(self, log_dir=None, level=None, name=None, config=None, env=None, * self._slack_listener = None atexit.register(self.close) - # ---- construction ------------------------------------------------ - @property def config(self): - """The resolved settings. Reading this does not build any handlers.""" + """The resolved settings. Reading this builds no handlers.""" with self._lock: if self._config is None: if self._explicit_config is not None: - # A ready-made config is a base, not the last word: settings - # passed alongside it must still take effect, not vanish. self._config = self._explicit_config.replace(**self._settings) else: self._config = LoggerConfig.from_env(env=self._env, **self._settings) @@ -67,18 +62,18 @@ def _resolve(self): if self._logger is None: with self._lock: if self._logger is None: - self._logger = self._build() + logger, slack_problem = self._build() + self._logger = logger + if slack_problem: + logger.critical("Slack alerts are disabled: %s", slack_problem) return self._logger def _build(self): config = self.config logger = logging.getLogger(f"loggerhelper.{config.name}" if config.name else "loggerhelper") logger.setLevel(level_number(config.level)) - # The application owns the root logger; our records are not its business. logger.propagate = False - # Rebuilding must not stack a second set of handlers on the shared - # stdlib logger -- that is what made the first version log twice. for handler in list(logger.handlers): logger.removeHandler(handler) handler.close() @@ -98,15 +93,16 @@ def _build(self): self._slack_listener = listener logger.addHandler(handler) - return logger + return logger, config.slack_problem() def reconfigure(self, config=None, env=None, **settings): """ Change settings. Values of ``None`` mean "leave as is". - Doing this after logging has started is legal but noted in the log -- - earlier lines went somewhere else, and that is worth being able to see. + Doing this after logging has started is noted in the log: earlier lines + went somewhere else. """ + check_setting_names(settings, extra=("config", "env", "load_dotenv")) with self._lock: started = self._logger is not None if config is not None: @@ -130,7 +126,6 @@ def close(self): logger, self._logger = self._logger, None if listener is not None: - # Nothing useful is left to do if the listener thread is already gone. with contextlib.suppress(Exception): listener.stop() if logger is not None: @@ -138,11 +133,11 @@ def close(self): logger.removeHandler(handler) handler.close() - # ---- logging ----------------------------------------------------- - def _emit(self, level, message, *args, **kwargs): - # stacklevel is what makes `origin` point at the caller instead of at - # this file; every public method must be exactly one frame above here. + """ + stacklevel is what makes ``origin`` point at the caller rather than at + this file. Every public method must sit exactly one frame above here. + """ kwargs["stacklevel"] = kwargs.pop("stacklevel", 1) + _STACK_OFFSET self._resolve().log(level, message, *args, **kwargs) @@ -155,7 +150,7 @@ def info(self, message, *args, **kwargs): self._emit(logging.INFO, message, *args, **kwargs) def warning(self, message, *args, **kwargs): - """Degraded, but this operation still succeeded -- a retry, a fallback.""" + """Degraded, but this operation still succeeded.""" self._emit(logging.WARNING, message, *args, **kwargs) def error(self, message, *args, **kwargs): @@ -199,10 +194,7 @@ def warn(self, message, *args, **kwargs): ) self._emit(logging.WARNING, message, *args, **kwargs) - # ---- decorator --------------------------------------------------- - def _emit_failure(self, level, message, exc): - """One record, carrying the traceback, from the decorator.""" self._resolve().log(level_number(level), message, exc_info=exc, stacklevel=3) def catch(self, func=None, level="ERROR", reraise=True, default=None, exclude=()): @@ -210,9 +202,8 @@ def catch(self, func=None, level="ERROR", reraise=True, default=None, exclude=() Log any exception escaping the decorated function, then re-raise it. ``ERROR`` by default because an exception escaping a function means that - operation failed -- regardless of how important the function is. Reserve - ``level="CRITICAL"`` for start-up and other paths where the failure ends - the process. + operation failed, whatever the function does. Reserve ``CRITICAL`` for + start-up paths where the failure ends the process. @log.catch def handle(request): ... @@ -223,8 +214,7 @@ def load_config(): ... @log.catch(reraise=False, default=[]) def optional_extras(): ... - Works on ``async def`` too. Decorating does not build the logger, so it - is safe at import time. + Works on ``async def``. Decorating does not build the logger. """ return _catch( self._emit_failure, @@ -236,8 +226,6 @@ def optional_extras(): ... ) -#: The shared logger. Import it and start writing; settings come from the -#: environment, or from configure(). log = Logger() @@ -249,10 +237,9 @@ def configure( configure(log_dir="./logs") - Call it before the first log line. Afterwards is allowed, and says so in the - log. ``load_dotenv=True`` applies the nearest ``.env`` first; it is off by - default because a library should not edit the environment behind the - application's back. + Call it before the first log line. ``load_dotenv=True`` applies the nearest + ``.env`` first; it is off by default because a library should not edit the + environment behind the application's back. """ if load_dotenv: load_repo_dotenv() diff --git a/tests/_internal/test_config.py b/tests/_internal/test_config.py index 4418ca1..3663e89 100644 --- a/tests/_internal/test_config.py +++ b/tests/_internal/test_config.py @@ -88,11 +88,6 @@ def test_the_slack_level_can_be_raised(self): ) assert config.slack_level == "CRITICAL" - def test_plain_http_is_refused(self): - """The handler posts this URL; http would put the secret on the wire.""" - with pytest.raises(ConfigError, match="https"): - LoggerConfig(slack_webhook_url="http://hooks.slack.com/x") - def test_an_empty_webhook_is_the_same_as_unset(self): assert LoggerConfig(slack_webhook_url=" ").slack_enabled is False @@ -103,22 +98,44 @@ def test_a_bot_token_with_a_channel_enables_it(self): assert config.slack_enabled is True assert config.slack_channel == "#alerts" + def test_a_working_setup_reports_no_problem(self): + assert LoggerConfig(slack_webhook_url="https://hooks.slack.com/x").slack_problem() is None + assert ( + LoggerConfig(slack_bot_token="xoxb-1-2-abc", slack_channel="#a").slack_problem() is None + ) + assert LoggerConfig().slack_problem() is None + def test_a_bot_token_without_a_channel_says_so(self): - with pytest.raises(ConfigError, match="SLACK_CHANNEL"): - LoggerConfig(slack_bot_token="xoxb-1-2-abc") - - def test_both_credentials_at_once_is_rejected(self): - with pytest.raises(ConfigError, match="one, not both"): - LoggerConfig( - slack_webhook_url="https://hooks.slack.com/x", - slack_bot_token="xoxb-1-2-abc", - slack_channel="#alerts", - ) + problem = LoggerConfig(slack_bot_token="xoxb-1-2-abc").slack_problem() + assert "SLACK_CHANNEL" in problem + + def test_both_credentials_at_once_is_reported(self): + problem = LoggerConfig( + slack_webhook_url="https://hooks.slack.com/x", + slack_bot_token="xoxb-1-2-abc", + slack_channel="#alerts", + ).slack_problem() + assert "one, not both" in problem def test_something_that_is_not_a_token_points_at_the_right_page(self): - """The App Credentials page shows a Client Secret, which is not this.""" - with pytest.raises(ConfigError, match="OAuth & Permissions"): - LoggerConfig(slack_bot_token="8f14e45fceea167a", slack_channel="#alerts") + """The Basic Information page shows a Verification Token, which is not this.""" + problem = LoggerConfig( + slack_bot_token="8f14e45fceea167a", slack_channel="#alerts" + ).slack_problem() + assert "OAuth & Permissions" in problem + + def test_plain_http_is_reported(self): + assert "https" in LoggerConfig(slack_webhook_url="http://hooks.slack.com/x").slack_problem() + + def test_a_broken_setup_is_not_enabled(self): + assert ( + LoggerConfig(slack_bot_token="not-a-token", slack_channel="#a").slack_enabled is False + ) + + def test_a_problem_never_quotes_the_credential_back(self): + """The message often ends up in a log file; the secret must not.""" + problem = LoggerConfig(slack_webhook_url="http://hooks.slack.com/secret").slack_problem() + assert "secret" not in problem def test_credentials_are_not_shown_in_the_repr(self): config = LoggerConfig(slack_webhook_url="https://hooks.slack.com/services/T/B/secret") @@ -126,6 +143,43 @@ def test_credentials_are_not_shown_in_the_repr(self): assert "slack_webhook_url='***'" in repr(config) or "slack_webhook_url=***" in repr(config) +class TestEarlyNameChecking: + """ + Settings resolve lazily, so an unchecked typo would surface at the first log + call -- pointing the traceback at a line that is perfectly correct. + """ + + def test_a_typo_is_caught_at_construction(self, tmp_path): + from loggerhelper import Logger + + with pytest.raises(ConfigError): + Logger(log_dir=str(tmp_path), colur="never") + + def test_a_typo_is_caught_by_configure(self): + from loggerhelper import configure + + with pytest.raises(ConfigError): + configure(load_env=True) + + def test_a_near_miss_is_suggested(self): + from loggerhelper._internal.config import check_setting_names + + with pytest.raises(ConfigError, match="did you mean 'load_dotenv'"): + check_setting_names(["load_env"], extra=("load_dotenv",)) + + def test_something_unrecognisable_gets_no_wild_guess(self): + from loggerhelper._internal.config import check_setting_names + + with pytest.raises(ConfigError) as caught: + check_setting_names(["zzzzzzzz"]) + assert "did you mean" not in str(caught.value) + + def test_the_real_settings_pass(self): + from loggerhelper._internal.config import check_setting_names + + check_setting_names(LoggerConfig.SETTINGS) + + class TestReplace: def test_a_copy_differs_only_where_asked(self): base = LoggerConfig(log_dir="/base", level="DEBUG", retention_days=7) diff --git a/tests/_internal/test_slack.py b/tests/_internal/test_slack.py index 5089ccd..2cdf3f3 100644 --- a/tests/_internal/test_slack.py +++ b/tests/_internal/test_slack.py @@ -145,6 +145,14 @@ def test_a_token_posts_to_chat_postmessage(self, sent, posted): assert posted[0]["channel"] == "#alerts" assert posted[0]["attachments"][0]["title"].startswith("ERROR:") + def test_a_notification_fallback_is_included(self, posted): + """An attachment-only message shows up blank in push notifications.""" + handler = SlackHandler(bot_token=BOT_TOKEN, channel="#alerts") + handler.emit(make_record()) + + assert posted[0]["text"].startswith("ERROR:") + assert "it failed" in posted[0]["text"] + def test_a_webhook_does_not_send_a_channel_or_a_token(self, sent, posted): handler = SlackHandler(WEBHOOK) handler.emit(make_record()) @@ -208,6 +216,113 @@ def test_end_to_end_through_a_logger(self, posted, tmp_path): assert "the job failed" in posted[0]["attachments"][0]["title"] +class TestBrokenConfigurationDegrades: + """ + A mistake in an optional notifier must not stop the program from logging. + The handler already refuses to let a dead webhook do that; a malformed + credential must not be able to either. + """ + + @staticmethod + def _read(log_dir, level): + from datetime import date + + return (log_dir / date.today().isoformat() / f"{level}.log").read_text(encoding="utf-8") + + def test_logging_still_works_with_a_bad_token(self, tmp_path): + from loggerhelper import Logger + + logger = Logger( + log_dir=str(tmp_path), + name="slack-broken", + env={}, + color="never", + slack_bot_token="8f14e45fceea167a", # the Verification Token, not a bot token + slack_channel="#alerts", + ) + try: + logger.info("the application carries on") + finally: + logger.close() + + assert "the application carries on" in self._read(tmp_path, "INFO") + + def test_the_reason_is_logged_loudly(self, tmp_path): + from loggerhelper import Logger + + logger = Logger( + log_dir=str(tmp_path), + name="slack-loud", + env={}, + color="never", + slack_bot_token="8f14e45fceea167a", + slack_channel="#alerts", + ) + try: + logger.info("anything") + finally: + logger.close() + + written = self._read(tmp_path, "CRITICAL") + assert "Slack alerts are disabled" in written + assert "OAuth & Permissions" in written + + def test_it_is_said_once_not_on_every_line(self, tmp_path): + from loggerhelper import Logger + + logger = Logger( + log_dir=str(tmp_path), + name="slack-once-only", + env={}, + color="never", + slack_bot_token="nope", + slack_channel="#alerts", + ) + try: + for _ in range(5): + logger.info("tick") + finally: + logger.close() + + assert self._read(tmp_path, "CRITICAL").count("Slack alerts are disabled") == 1 + + def test_no_alert_is_attempted(self, sent, tmp_path): + from loggerhelper import Logger + + logger = Logger( + log_dir=str(tmp_path), + name="slack-silent", + env={}, + color="never", + slack_bot_token="nope", + slack_channel="#alerts", + ) + try: + logger.error("this would have been an alert") + finally: + logger.close() + + assert sent == [], "a credential that cannot work must not be used" + + def test_a_correct_setup_says_nothing(self, posted, tmp_path): + from loggerhelper import Logger + + logger = Logger( + log_dir=str(tmp_path), + name="slack-quiet", + env={}, + color="never", + slack_bot_token=BOT_TOKEN, + slack_channel="#alerts", + ) + try: + logger.info("anything") + finally: + logger.close() + + assert not (tmp_path / "CRITICAL.log").exists() + + class TestThrottling: def test_a_repeat_of_the_same_failure_is_held_back(self, posted): handler = SlackHandler(WEBHOOK, throttle_seconds=600) From a3c74c51c39542a6f274de536713d71383bb8d01 Mon Sep 17 00:00:00 2001 From: Marcus Date: Tue, 11 Aug 2026 01:17:04 +0800 Subject: [PATCH 2/2] docs: add .env.example, and test that it stays in step with the code Setting this up from the README means reading prose and remembering which steps apply. A template that is already in the right shape removes that: copy it, delete what you do not need, fill in the rest. The Slack section carries its setup steps inline, with the one everyone skips called out where it cannot be missed -- inviting the bot to the channel. It also records the two traps that cost real time: adding a scope needs a reinstall, which issues a new token; and Slack's UI draws a channel as "# common" with a space that is not part of the name. .env.example is committed and .env is gitignored, so the template can drift away from the code without anyone noticing. Four tests stop that: every variable it names must be one the code reads, every variable the code reads must appear in it, its uncommented lines must produce a usable config, and no value in it may look like a real token. Writing them turned up that the variable names were spelled out inline in from_env, so they now come from one ENV_KEYS mapping that both the loader and the tests use. Verified: 161 tests on 3.8/3.9/3.12, pre-commit clean, wheel builds. Co-Authored-By: Claude Opus 5 --- .env.example | 88 ++++++++++++++++++++++++++++ README.md | 11 +++- src/loggerhelper/_internal/config.py | 38 +++++++----- tests/test_env_example.py | 65 ++++++++++++++++++++ 4 files changed, 185 insertions(+), 17 deletions(-) create mode 100644 .env.example create mode 100644 tests/test_env_example.py diff --git a/.env.example b/.env.example new file mode 100644 index 0000000..557055b --- /dev/null +++ b/.env.example @@ -0,0 +1,88 @@ +# Copy this file to `.env` and fill in what you need, then call +# `configure(load_dotenv=True)` once at start-up. Every line here is optional -- +# delete the ones you do not care about. +# +# cp .env.example .env +# +# `.env` is gitignored. This file is not: keep real credentials out of it. +# Values already set in the real environment win over this file, so a container +# or CI can override anything below without editing it. + +# --------------------------------------------------------------------------- +# Logging +# --------------------------------------------------------------------------- + +# Where the dated directories go. Defaults to /log. +LOG_DIR=./log + +# DEBUG / INFO / WARNING / ERROR / CRITICAL +LOG_LEVEL=INFO + +# Tag on every line. Also what separates one logger from another; set it when +# more than one service writes into the same place. +# LOG_NAME=etl-worker + +# Per-file size cap before rotation, in bytes. 0 disables size rotation. +# LOG_MAX_BYTES=52428800 + +# How many rotated copies to keep. +# LOG_BACKUP_COUNT=5 + +# Dated directories older than this are deleted. 0 keeps everything forever. +LOG_RETENTION_DAYS=30 + +# auto / always / never. `auto` colours a terminal and nothing else, so piped +# output and CI logs stay free of escape codes. +# LOG_COLOR=auto + +# --------------------------------------------------------------------------- +# Slack alerts -- entirely optional +# --------------------------------------------------------------------------- +# +# Leave both credentials unset and no Slack handler is attached at all. +# Set ONE of them; setting both is a mistake and will be reported, because a +# webhook and a token name different destinations. +# +# Neither credential is on the Basic Information page. The Client Secret, +# Signing Secret and Verification Token shown there cannot post a message. + +# --- Option A: incoming webhook ------------------------------------------- +# +# 1. Sidebar -> Features -> Incoming Webhooks +# 2. Turn "Activate Incoming Webhooks" on +# 3. "Add New Webhook to Workspace", pick the channel, Allow +# 4. Copy the URL below +# +# The channel is baked into the URL, so there is nothing to invite. +# +# SLACK_WEBHOOK_URL=https://hooks.slack.com/services/T000/B000/xxxxxxxx + +# --- Option B: bot token --------------------------------------------------- +# +# 1. Sidebar -> Features -> OAuth & Permissions +# 2. Scopes -> Bot Token Scopes -> add `chat:write` +# 3. "Install to Workspace" at the top of that page, Allow +# 4. Copy the "Bot User OAuth Token" (starts with xoxb-) below +# 5. >>> In the channel itself, type: /invite @your-app-name <<< +# +# STEP 5 IS THE ONE EVERYONE FORGETS. Without it Slack answers +# `not_in_channel` and nothing is delivered, however correct the rest is. +# Repeat it for every channel you point SLACK_CHANNEL at. A private channel +# also needs the `groups:write` scope. +# +# Adding a scope only takes effect after reinstalling the app, and reinstalling +# issues a NEW token -- come back and update this value. +# +# SLACK_BOT_TOKEN=xoxb-YOUR-BOT-TOKEN + +# Required with SLACK_BOT_TOKEN, ignored with a webhook. +# Slack's UI draws the name as "# common" with a space, for looks. The name is +# `common`, so write `#common`. A channel ID (C0123456789, from the channel's +# "Copy link") also works and survives a rename. +# SLACK_CHANNEL=#alerts + +# Alerts fire at this level and above. WARNING is the default. +# SLACK_LOG_LEVEL=WARNING + +# Free-form deployment tag shown on each alert. +# SLACK_ENV=prod diff --git a/README.md b/README.md index 3d08124..5dad172 100644 --- a/README.md +++ b/README.md @@ -271,7 +271,14 @@ output and CI logs stay free of escape codes. `export` on every shell is tedious and does not survive a new terminal, a service restart or a colleague's machine. Put the values in a `.env` file next -to your `pyproject.toml` instead: +to your `pyproject.toml` instead. + +**Start from [`.env.example`](.env.example)** — it lists every variable with its +default, and carries the Slack setup steps inline so none of them gets skipped: + +```bash +cp .env.example .env +``` ```dotenv # .env -- keep this out of version control @@ -335,6 +342,8 @@ SLACK_WEBHOOK_URL=https://hooks.slack.com/services/T000/B000/xxxxxxxx 3. **Install to Workspace** (top of the same page), **Allow** 4. Copy the **Bot User OAuth Token**: `xoxb-…` 5. Invite the bot into the channel: `/invite @your-app-name` + ([appendix](#appendix-the-bot-must-be-in-the-channel) — this is the step + people skip) ```dotenv SLACK_BOT_TOKEN=xoxb-YOUR-BOT-TOKEN diff --git a/src/loggerhelper/_internal/config.py b/src/loggerhelper/_internal/config.py index c9a391e..8b65594 100644 --- a/src/loggerhelper/_internal/config.py +++ b/src/loggerhelper/_internal/config.py @@ -12,6 +12,21 @@ LEVEL_NAMES = ("DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL") +ENV_KEYS = { + "log_dir": "LOG_DIR", + "level": "LOG_LEVEL", + "name": "LOG_NAME", + "max_bytes": "LOG_MAX_BYTES", + "backup_count": "LOG_BACKUP_COUNT", + "retention_days": "LOG_RETENTION_DAYS", + "color": "LOG_COLOR", + "slack_webhook_url": "SLACK_WEBHOOK_URL", + "slack_bot_token": "SLACK_BOT_TOKEN", + "slack_channel": "SLACK_CHANNEL", + "slack_level": "SLACK_LOG_LEVEL", + "slack_env": "SLACK_ENV", +} + _LEVEL_NUMBERS = {"DEBUG": 10, "INFO": 20, "WARNING": 30, "ERROR": 40, "CRITICAL": 50} _LEVEL_ALIASES = {"WARN": "WARNING", "FATAL": "CRITICAL"} _COLOR_MODES = ("auto", "always", "never") @@ -52,6 +67,9 @@ def _as_int(raw, source): raise ConfigError(f"{source}={raw!r} must be a whole number") from None +_CASTS = {"max_bytes": _as_int, "backup_count": _as_int, "retention_days": _as_int} + + class LoggerConfig: """Everything a Logger needs, already validated. See the README for each setting.""" @@ -169,29 +187,17 @@ def from_env(cls, env=None, **overrides): values = {} remaining = dict(overrides) - def pick(field_name, env_key, cast=None): + for field_name, env_key in ENV_KEYS.items(): given = remaining.pop(field_name, None) if given is not None: values[field_name] = given - return + continue raw = env.get(env_key) if raw is None or not raw.strip(): - return + continue + cast = _CASTS.get(field_name) values[field_name] = cast(raw, env_key) if cast else raw.strip() - pick("log_dir", "LOG_DIR") - pick("level", "LOG_LEVEL") - pick("name", "LOG_NAME") - pick("max_bytes", "LOG_MAX_BYTES", _as_int) - pick("backup_count", "LOG_BACKUP_COUNT", _as_int) - pick("retention_days", "LOG_RETENTION_DAYS", _as_int) - pick("color", "LOG_COLOR") - pick("slack_webhook_url", "SLACK_WEBHOOK_URL") - pick("slack_bot_token", "SLACK_BOT_TOKEN") - pick("slack_channel", "SLACK_CHANNEL") - pick("slack_level", "SLACK_LOG_LEVEL") - pick("slack_env", "SLACK_ENV") - check_setting_names(remaining) return cls(**values) diff --git a/tests/test_env_example.py b/tests/test_env_example.py new file mode 100644 index 0000000..9ea1cd5 --- /dev/null +++ b/tests/test_env_example.py @@ -0,0 +1,65 @@ +""" +`.env.example` is what people copy, so a stale name in it is a silent trap. + +These tests keep it in step with what the code actually reads. +""" + +import re +from pathlib import Path + +import pytest + +from loggerhelper import LoggerConfig +from loggerhelper._internal.config import ENV_KEYS, parse_dotenv + +EXAMPLE = Path(__file__).resolve().parents[1] / ".env.example" + +# An assignment, not prose that happens to contain an `=`. +_ASSIGNMENT = re.compile(r"^#?\s*([A-Z][A-Z0-9_]*)=") + + +def mentioned_keys(): + """Every variable the file names, whether commented out or not.""" + found = set() + for line in EXAMPLE.read_text(encoding="utf-8").splitlines(): + match = _ASSIGNMENT.match(line.strip()) + if match: + found.add(match.group(1)) + return found + + +def test_the_file_exists(): + assert EXAMPLE.is_file(), "the README tells people to copy this" + + +def test_every_variable_it_mentions_is_one_we_read(): + unknown = mentioned_keys() - set(ENV_KEYS.values()) + assert not unknown, f"{EXAMPLE.name} documents variables nothing reads: {sorted(unknown)}" + + +def test_every_variable_we_read_is_documented(): + missing = set(ENV_KEYS.values()) - mentioned_keys() + assert not missing, f"{EXAMPLE.name} is missing: {sorted(missing)}" + + +def test_the_active_lines_produce_a_usable_config(): + active = parse_dotenv(EXAMPLE.read_text(encoding="utf-8")) + config = LoggerConfig.from_env(env=active) + assert config.slack_problem() is None + assert config.level in ("DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL") + + +def test_it_carries_no_real_credential(): + """It is committed; the real values belong in .env, which is gitignored.""" + text = EXAMPLE.read_text(encoding="utf-8") + assert "hooks.slack.com/services/T000" in text or "SLACK_WEBHOOK_URL" in text + for line in text.splitlines(): + if line.lstrip().startswith("#"): + continue + _, _, value = line.partition("=") + assert not value.strip().startswith("xox"), "that looks like a real token" + + +@pytest.mark.parametrize("step", ["/invite", "chat:write", "OAuth & Permissions"]) +def test_the_slack_steps_people_skip_are_spelled_out(step): + assert step in EXAMPLE.read_text(encoding="utf-8")