Skip to content
allanninal.dev/build
Collaborate

Part 2 of 7 · Log anomaly spotter series ~5 min read

How a log line becomes a shape

Fingerprinting is the entire system and it fails in two opposite directions. Strip too little and every line is unique, so nothing ever has a history. Strip too much and two genuinely different errors become the same shape, so one of them can never be seen.

Key takeaways

  • Strip numbers, identifiers, timestamps, paths, quoted values and stack line numbers.
  • Never strip the exception type, the message text, or the function name.
  • Structured logs make this nearly free: the fingerprint is the event name plus the level.
  • Too many shapes means something variable is not being stripped.
  • Too few means two different errors have collapsed, which is the dangerous direction.

What gets stripped

before   Order 84412 failed after 1203ms: timeout contacting
         https://api.example.com/v2/rates?zone=EU

after    Order  failed after ms: timeout contacting 

stripped numbers, identifiers, durations, URLs, quoted strings,
         UUIDs, IP addresses, hex blobs, stack line numbers, dates

kept     every word, the exception type, the function name, the level

The rule is that anything which varies between two occurrences of the same event is stripped and everything that identifies which event it is stays. Written down like that it is obvious; the difficulty is entirely in the long tail of things that vary and do not look like numbers.

The two failure modes

The two failure modes of log fingerprintingA vertical chain of five steps entered by a box labelled A log line, raw. Step one strips the variables: numbers, identifiers and paths. Step two hashes what is left, which is the shape. Step three asks whether there are too many shapes, meaning thousands mostly seen once; if so it exits to Under-stripping and the task is to find what varies. Step four asks whether two different errors have become one shape, which is harder to notice; if so it exits to Over-stripping, the dangerous one. Step five is a few hundred shapes, stable week to week. A note says under-stripping is loud and obvious while over-stripping is silent, which is why it is worse.AWS ACCOUNTA log linerawStrip the variablesnumbers, ids, pathsHash what is leftthat is the shapeToo many shapes?thousands, mostly seen onceUnder-strippingfind what variesyesTwo errors, one shape?harder to noticeOver-strippingthe dangerous oneyesA few hundred shapesstable week to weekUnder-stripping is loud and obvious. Over-stripping is silent, which is why it is worse.
Fig 1. The two ways fingerprinting fails. One produces an unusable pile of one-off shapes and announces itself; the other quietly makes an error invisible.
  • App integration
  • Machine learning
  • Security & identity
  • Management
  • Analytics

Under-stripping announces itself

If something variable is not being stripped, the shape count explodes: thousands of shapes, almost all seen exactly once, and every hour brings hundreds of new ones. The digest becomes useless immediately and the cause is easy to find by looking at a handful of the one-off shapes and spotting what they have in common.

Common culprits are session identifiers that do not look like UUIDs, hostnames with a generated suffix, and durations formatted as text rather than numbers — “took 1.2 seconds” survives a numeric strip if the number is spelled differently each time.

Over-stripping is silent

The worse direction. If the strip is aggressive enough that “connection refused to the payment provider” and “connection refused to the mail provider” produce the same shape, then a brand-new payment outage is indistinguishable from the mail warning that happens twice a day, and it will never be reported.

The specific temptation is stripping quoted strings, which is usually right and occasionally catastrophic because the quoted string is the only thing distinguishing two errors. The compromise that works is stripping quoted values longer than a threshold and keeping short ones, since a short quoted string is usually a name and a long one is usually data.

Structured logs make this free

How structured logging simplifies log fingerprintingA horizontal row of five boxes. Text logs: stripped and hashed. Fragile: a reworded message becomes a new shape. Structured logs: JSON carrying an event name. Fingerprint: the event plus the level plus the source. Stable: the wording can change freely. A note says if you control the logging, emit an event name, and everything here becomes a group-by.STRUCTURED LOGGING MAKES THIS TRIVIALText logsstrip and hashFragilea reworded messageis a new shapeStructured logsJSON with an event nameFingerprintevent + level + sourceStablewording can change freelyIf you control the logging, emit an event name. Everything here becomes a group-by.
Fig 2. Why structured logging changes this problem entirely. With an explicit event name the fingerprint stops being a heuristic and becomes a field.
  • Machine learning
  • Security & identity
  • Management

This is worth acting on where you can. If the logs are yours, adding an event field with a stable identifier makes the fingerprint a field lookup rather than a heuristic, and it removes the entire class of problem where somebody improves an error message and the system reports a new shape.

In practice most systems are mixed: your own functions log structured events and every library and runtime they use logs text. So the fingerprinter uses the event name when there is one and falls back to stripping when there is not, and the fallback is where all the care goes.

Next: what happens when a shape is new.

All posts