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 354f013..5dad172 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) --- @@ -270,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 @@ -334,17 +342,21 @@ 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 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 +395,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 +532,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 +542,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 +649,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..8b65594 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,25 @@ 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") +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} -# 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 +37,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 +47,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"): @@ -75,27 +67,12 @@ 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. - - ``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 +88,8 @@ class LoggerConfig: "slack_env", ) + _SECRETS = ("slack_webhook_url", "slack_bot_token") + def __init__( self, log_dir=None, @@ -146,61 +125,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,55 +178,54 @@ 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 = {} 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") - - 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 +248,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) 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")