Log to stdout via the stdlib logging module #5

Merged
drawblank merged 1 commit from feat/logging into main 2026-08-20 10:25:16 +00:00
Owner

A backend service that only prints on failure gives you nothing to read when something goes wrong at 3am.

Four named loggers — bot, commands, throttle, titles — so output can be filtered per subsystem. Everything goes to stdout through stdlib logging; nothing is sent to IRC.

2026-08-20 20:23:43 INFO     commands         !tz from alice args='Australia/Adelaide Europe/Amsterdam'
2026-08-20 20:23:43 INFO     commands         Rejected input from troll: usage: !dice NdS (e.g. 1d6, 2d20)
2026-08-20 20:23:43 WARNING  commands         Muting troll!troll@1.2.3.4 for 60s after repeated bad commands
2026-08-20 20:23:43 DEBUG    commands         Dropping command from muted troll2

INFO — startup config, registration, joins, every command with its args, rejected input, mutes, fetched titles with timings.
DEBUG — every message seen, unknown commands, help requests, per-command completion, mute arithmetic, identity merges.

Two levels, on purpose

log_level     = "INFO"      # DEBUG for full tracing
irc_log_level = "WARNING"   # raise to debug the connection itself

The irc library logs every protocol line at DEBUG. Sharing one level would mean log_level = "DEBUG" drowns the bot's own output in raw traffic. An unknown level name falls back to the default rather than refusing to start over a typo in a log setting.

The password cannot reach the log

BotConfig.summary() builds the startup line without it, and a RedactingFilter on the handler masks it anyway if anything ever logs a config object whole:

INFO  bot  connecting with password ***

Empty secrets are dropped — an empty string would otherwise match between every character and turn a whole message into ***. Tested both ways.

Behaviour changes

Existing prints become log calls: the SASL failure is log.error, a handler crash is log.exception rather than traceback.print_exc. Two tests move from capsys to caplog to match — a deliberate change, not a workaround. The one remaining print is the config-load failure, which happens before logging is configured.

A silent failure fixed along the way

handle_urls' worker is a daemon thread with no exception guard. An unexpected error killed it without a trace and looked identical to a hung fetch. It now logs the traceback and continues to the next URL.

Verification

361 tests, up from 334. 27 new ones cover level parsing (including junk values), per-logger levels, handler replacement on reconfigure, and redaction.

A backend service that only prints on failure gives you nothing to read when something goes wrong at 3am. Four named loggers — `bot`, `commands`, `throttle`, `titles` — so output can be filtered per subsystem. Everything goes to **stdout** through stdlib `logging`; nothing is sent to IRC. ``` 2026-08-20 20:23:43 INFO commands !tz from alice args='Australia/Adelaide Europe/Amsterdam' 2026-08-20 20:23:43 INFO commands Rejected input from troll: usage: !dice NdS (e.g. 1d6, 2d20) 2026-08-20 20:23:43 WARNING commands Muting troll!troll@1.2.3.4 for 60s after repeated bad commands 2026-08-20 20:23:43 DEBUG commands Dropping command from muted troll2 ``` **INFO** — startup config, registration, joins, every command with its args, rejected input, mutes, fetched titles with timings. **DEBUG** — every message seen, unknown commands, help requests, per-command completion, mute arithmetic, identity merges. ## Two levels, on purpose ```toml log_level = "INFO" # DEBUG for full tracing irc_log_level = "WARNING" # raise to debug the connection itself ``` The `irc` library logs every protocol line at DEBUG. Sharing one level would mean `log_level = "DEBUG"` drowns the bot's own output in raw traffic. An unknown level name falls back to the default rather than refusing to start over a typo in a log setting. ## The password cannot reach the log `BotConfig.summary()` builds the startup line without it, and a `RedactingFilter` on the handler masks it anyway if anything ever logs a config object whole: ``` INFO bot connecting with password *** ``` Empty secrets are dropped — an empty string would otherwise match between every character and turn a whole message into `***`. Tested both ways. ## Behaviour changes Existing `print`s become log calls: the SASL failure is `log.error`, a handler crash is `log.exception` rather than `traceback.print_exc`. Two tests move from `capsys` to `caplog` to match — a deliberate change, not a workaround. The one remaining `print` is the config-load failure, which happens before logging is configured. ## A silent failure fixed along the way `handle_urls`' worker is a **daemon thread with no exception guard**. An unexpected error killed it without a trace and looked identical to a hung fetch. It now logs the traceback and continues to the next URL. ## Verification 361 tests, up from 334. 27 new ones cover level parsing (including junk values), per-logger levels, handler replacement on reconfigure, and redaction.
A backend service that only prints on failure gives you nothing to read when
something goes wrong at 3am. Four named loggers -- bot, commands, throttle,
titles -- so output can be filtered per subsystem.

INFO records what a running service should: startup config, registration,
joins, every command with its args, rejected input, mutes, and fetched titles
with timings. DEBUG adds every message seen, unknown commands, help requests,
per-command completion, mute arithmetic, and identity merges.

Two config keys, because the irc library logs every protocol line at DEBUG
and would otherwise bury the bot's own output:

    log_level     = "INFO"      # DEBUG for full tracing
    irc_log_level = "WARNING"   # raise to debug the connection itself

An unknown level name falls back to the default rather than refusing to start
over a typo in a log setting.

The SASL password cannot reach the log. BotConfig.summary() builds the
startup line without it, and a RedactingFilter on the handler masks it anyway
should anything ever log a config object whole. Empty secrets are dropped, as
an empty string would match between every character.

Existing prints become log calls: the SASL failure is log.error, and a
handler crash is log.exception rather than traceback.print_exc. Two tests
move from capsys to caplog to match. The one remaining print is the
config-load failure, which happens before logging is configured.

Also fixes a silent failure in titles: the URL worker is a daemon thread, so
an unexpected error vanished without trace and looked exactly like a hung
fetch. It now logs the traceback and continues to the next URL.

Tests: 361, up from 334.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Sign in to join this conversation.
No reviewers
No labels
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
slopnode/bot!5
No description provided.