One post tagged with "Logging"

Chasing a monitoring gap: server-monitor filters alert-grade logs by the level name warn, but 38 rows in the shared logs table carried level='warning'. The filter didn't match by one character — and in the monitor's eyes, those 38 rows did not exist.

Encountered this while building AI Analytics — an LLM-powered analytics platform that surfaces market trends, user behavior, and sales data; server-monitor is its alerting module, consuming one logs table written by four services.

TL;DR​

The cross-language logging contract defines lowercase warn/fatal; Python's stdlib record.levelname produces WARNING/CRITICAL — written raw or with a bare .lower() you get warning/critical, which contract-name filters never match. Two principles fix it: normalize at a single point in the write boundary (WARNING→warn, CRITICAL/FATAL→fatal) so no consumer ever has to juggle spellings; and write the contract doc as the intended implementation, not a snapshot of the current one — this drift survived so long precisely because the contract's Python column documented the buggy code.

Symptoms​

Four services write one logs table; the contract specifies level values: debug / info / warn / error / fatal. A reconciliation query:

SELECT service, level, count(*)
FROM logs
GROUP BY service, level ORDER BY 1, 2;

turns up spellings that don't exist in the contract:

 service    | level    | count
------------+----------+-------
 ai-dag     | warning  |    21   ← not in the contract
 rag-service| warning  |    17   ← not in the contract
 ...        | warn     |   ...   ← the actual contract name

The monitor filters level = 'warn'; these 38 alert-grade rows silently vanish.

Root Cause​

Layer one is literal mismatch: Python's stdlib levels are DEBUG / INFO / WARNING / ERROR / CRITICAL — there is no WARN (a deprecated alias) and no FATAL. Both services pushed record.levelname into the table: one raw (uppercase WARNING), one lowercased (warning). Neither matches the contract's warn.

Layer two is the one worth losing sleep over: the contract document itself specified the wrong implementation. In the cross-service contract's field table, the Python services' level column literally read "record.levelname" and "record.levelname.lower()". The doc was describing reality instead of prescribing it — so the buggy implementations carried the contract's endorsement, and nobody questioned them. This is the same harm shape as try/except swallowing exceptions into silent failures: nothing crashes, things just quietly go missing — by the time anyone looks, dozens of alert rows were never seen.

Solution​

Step 1: Single-point mapping at the write boundary​

Each service defines one normalization function; every write path (formatter and DB sink) goes through it:

_LEVEL_NAME_MAP = {"WARNING": "warn", "CRITICAL": "fatal", "FATAL": "fatal"}

def normalize_level(levelname: str) -> str:
    """WARNING→warn, CRITICAL/FATAL→fatal, everything else lowercased."""
    return _LEVEL_NAME_MAP.get(levelname.upper(), levelname.lower())

payload = {"level": normalize_level(record.levelname)}   # always emits a contract name

The keyword is "single point": the JSON formatter and the DB handler share one function, so the mapping changes in exactly one place and no second implementation can appear.

Step 2: Rewrite the contract doc as the intended implementation​

The field table's Python columns now read normalize_level(record.levelname), and a new "level name mapping" section documents the rules, the anti-patterns (no raw writes, no bare lowercasing), and each service's function entry point. A contract is a spec — not a snapshot of whatever happens to be deployed.

Step 3: Add a reconciliation query so drift is discoverable​

SELECT level, count(*) FROM logs
WHERE service IN ('ai-dag', 'rag-service')
GROUP BY level ORDER BY 2 DESC;

Any spelling besides warn is drift. This query belongs in routine inspection, turning "contract vs implementation" from a verbal promise into an assertable check.

Step 4: Clean up存量 (optional)​

New writes no longer produce off-contract names; handle the existing 38 rows as needed:

UPDATE logs SET level = 'warn' WHERE level = 'warning';

Small volumes can be left to age out; large ones, or anything feeding historical statistics, deserves the UPDATE.

FAQ​

Why can't Python's WARNING be written straight into the logs table?​

The stdlib literals are WARNING/CRITICAL, while cross-language contracts define warn/fatal. Raw or lowercased values (warning/critical) are unknown levels in contract-land — every consumer filtering by contract names silently drops them. The Python side must map at the write boundary.

Are WARNING and WARN the same level?​

Same semantics, different literals. Python logging has no WARN level (deprecated alias; the emitted name is always WARNING) and no FATAL (it's CRITICAL). That's why lowercasing doesn't help — you need an explicit mapping: WARNING→warn, CRITICAL→fatal.

How do I detect that a logging contract and its implementation have drifted?​

Periodically reconcile by contract level names (GROUP BY level); any off-contract spelling is drift. More importantly, the contract doc should specify the intended implementation and name the mapping function — when the doc copies the current implementation, the bug gets an endorsement, which is exactly why this drift survived so long.