logging

name	logging
description	Logging conventions for Plex Watchlist Maintainer — the literal line formats, UTC timestamps, the X-Plex-Token masking filter, what belongs at each level, the greppable summary line, and the rule never to raise the plexapi logger.
user-invocable	false

Logging — MANDATORY

The logs are the only interface this program has. There is no UI, so a question like "why was this show removed?" has to be answerable from one line of output.

Setup

• One handler, on stdout. setup_logging() clears the root handlers and installs it.
• Format, exactly: %(asctime)s %(levelname)-5s [watchlist] %(message)s
• Timestamps in UTC with a Z suffix: %Y-%m-%dT%H:%M:%SZ. Never the container's local time — the formatter's converter is time.gmtime for this reason.
• print() is forbidden in production code. Everything goes through logging, or the masking filter does not apply.

Never log the token

Not even truncated. TokenMaskingFilter is not optional:

• It replaces X-Plex-Token=<value> with X-Plex-Token=***, and the configured token with ***, everywhere — in the formatted message, in the arguments, and in rendered exception text.
• It interpolates first, then masks. Masking the format string would eat the %s placeholders themselves, because X-Plex-Token=%s matches the value pattern.
• Exception text goes through exc_text, masked once rendered, and exc_info is then cleared so nothing re-renders it unmasked downstream.
• At startup, log only token present (N characters). Never the value, never a prefix.

The plexapi logger never rises above WARNING, not even with LOG_LEVEL=DEBUG: it builds URLs containing ?X-Plex-Token=... and docker logs is no place to keep an account token. urllib3, requests and charset_normalizer are capped for the same reason plus noise — charset_normalizer chatters at DEBUG on every single response, which on a 177-show watchlist buries the diagnostic output that LOG_LEVEL=DEBUG exists to produce.

The summary line

One per iteration, and the prefix is load-bearing: summary: is what makes months of history greppable with a single command.

summary: watchlist=44 matched=177 pending=43 tracked=177 +1 -2 dropped=0 duration=4.2s

Field	Meaning
watchlist	Shows in the watchlist right now
matched	Shows that got a verdict (found in a configured library)
pending	Of those, how many still have something to watch
tracked	Shows in the state file after the pass
+N	Added back to the watchlist
-N	Removed from the watchlist
dropped	Forgotten because the user removed them by hand
duration	Seconds for the whole pass

A failed iteration keeps the same prefix, with a stable slug so the grep can be narrowed:

summary: state=failed reason=server-unreachable attempts=3 duration=95.1s
summary: state=auth-wait remaining=6h

Slugs are a closed set: server-unreachable, watchlist-unreachable, partial-iteration, removal-brake, unexpected-exception. Adding one means adding it to the documentation too.

+N and -N report the plan, not confirmed writes. A removal that fails with BadRequest is logged at DEBUG and produces a line identical to a successful one. Do not use the summary to prove a write landed; read the watchlist back.

What belongs at each level

Level	Use for
DEBUG	Per-show diagnosis: title, GUID, match method, ratingKey, episode counts, verdict. Why a show was excluded. Idempotent no-ops (already on the watchlist)
INFO	Startup configuration, the resolved server and libraries, each add/remove/drop, no changes, the summary line
WARNING	Retried transient failures, a slow iteration, a duplicate show whose chosen copy has less progress, a webhook that would not deliver
ERROR	Authentication failure, invalid configuration, the removal brake tripping, an unexpected exception (with exc_info=True)

Rules that matter more than the table:

• Every except logs. except: pass and except Exception: return None are forbidden.
• A normal condition is not a warning. A watchlist show that is not on the server is expected and goes to DEBUG. A show existing in several libraries is normal on servers with separate HD/4K/Remux libraries and is DEBUG unless the copy picked has less progress than another, which can change the verdict — that one is a WARNING.
• no changes is an INFO line and must be emitted, so a quiet iteration is distinguishable from a broken one.
• Six silent hours look identical to a dead container. During the authentication backoff, emit the state=auth-wait line about once an hour.

Messages

• English, lower case, no trailing period, no emojis.
• Use %s lazy formatting, never f-strings, so the filter sees the arguments.
• Name the thing that failed and what happens next: reading the watchlist failed (attempt 1/3): 500 — retrying in 5s beats error.
• Say what was not done when a failure is non-destructive: — watchlist untouched is the part the reader needs.