Field extraction per log template instead of per event

Why fields should be extracted once per pattern, not on every event.

Share
A log template is a log line with its changing parts blanked out, and 10x attaches field extraction to the template; every matching event inherits it, the bet V8's hidden classes make about JavaScript objects, applied to log lines. An HTTP template finds the status-code slot on first sight, guarded by an HTTP marker within ±5 tokens, while a kafka max.request.size = 200 binds nothing. A template also picks its own name: the run of tokens the engine traces to one source file, the format string that printed the line. Splunk, Datadog, and Elasticsearch grok repeat the work per event because they have no stable address to pin an answer to.

Open any Kubernetes control-plane log and you'll see lines like E1023 14:30:45.123456 controller.go:123 connection refused. That E is the severity. There's no word ERROR in the line. klog glues severity to the front of the timestamp as a single character.

Grep every event for ERROR and you miss all of them. The error-rate dashboard reads zero while the controller fails.

Most of what an event tells you is carried by the shape it came from rather than the values it happens to hold. A 3-digit number could be an HTTP status code, or it could be max.request.size = 200 in a kafka config dump.

The value 200 can't tell you which. The shape can. So attach the work to the shape, not the value.

JavaScript engines already solved a structurally identical problem. Object shape isn't declared in source, so they can't optimize access object by object. V8 records each object's shape as a hidden class (PyPy and CPython 3.11 do the same thing). The V8 docs call this bet intelligent design: there is a mind behind the incoming code, so only a finite set of shapes will ever show up.

On first sight of that class it finds where a property is stored and caches the offset at the access site. Discover once, attach once, every instance inherits.

A template is a log line with its variable parts blanked out

We apply the same architecture to log events. A template is the log line with its changing parts blanked out. E$TIME controller.go:$N connection refused is one template, and every line of that shape matches it.

The fixed words that survive are its structural tokens, and each blanked position is a slot. Knowledge attached to the template is inherited by every matching event.

The klog template reads the E/W/I/F prefix once and tags itself ERROR. Every matching line inherits that severity.

HTTP codes are where the slot has to be found before it can be read. Take a template whose structural tokens include status, GET, HTTP/, Completed. On first sight of the shape, it works out which slot holds the status code, guarded by a rule that a real HTTP marker sits within ±5 tokens of the candidate. Every event after that is a slot read and a range check.

The kafka template clears the word gate: request is in the shipped HTTP keyword list, and the template text max.request.size = $VAR contains it. What refuses the binding is the adjacency rule. The strict marker set (status, HTTP/, code, Completed, the method verbs) leaves request out, and no strict marker sits within ±5 tokens of the candidate, so the template binds no slot and its size = 200 stays an ordinary value. A second guard runs at event time, writing http_code only when the value at a bound slot falls between 100 and 599.

The same value 200 in two shapes. A Spring line with the HTTP marker "Completed" beside the number binds http_code = 200; a kafka "max.request.size = 200" line has no strict HTTP marker within ±5 tokens of the number, so 200 stays an ordinary value.

The hidden-class mapping runs all the way through. Severity, the status-code slot, the datetime format, and the pattern are class fields, worked out once per template; the values sitting in the slots are instance fields, read per event. V8 caches a property's offset on the class and reads the value off each object; the engine caches each answer on the template and reads the values off each line.

The analogy breaks in one place, in the engine's favor. V8 has to infer its classes from the objects alone, since objects are all it ever sees; a template is matched against a vocabulary compiled from the code that prints the lines, so the classes are grounded in source rather than in whatever traffic arrived first.

A template's name is the run of tokens that traces to one source file

A template inherits one more thing beyond fields: its name. 10x names every template with a message pattern, the few tokens that state what the line says with everything variable stripped away. The raw material is the symbol library, the vocabulary a compiler collects ahead of time from source and binary repos. For each known token the library records its file of origin and its role in that file: a log call's string literal, a class name, a string inside an executable.

The pattern is a run of consecutive template tokens that trace to the same file, chosen by coverage: when several source origins could claim the same tokens, the engine ranks the candidates by how well each one pins the line to a single origin and selects deterministically. A rarely occurring symbol narrows the candidates more than a ubiquitous one, which is why the ranking is by coverage rather than by length. Take this Spark executor line:

17/06/09 20:10:42 INFO executor.CoarseGrainedExecutorBackend: Connecting to driver: spark://CoarseGrainedScheduler@10.10.34.11:48069

The winning run is Connecting to driver, and the file is CoarseGrainedExecutorBackend.scala. That run is the format string the developer wrote. Source is optional: a syslog line from sshd gets the pattern authentication failure, with the sshd binary itself as the origin, scanned as an executable.

The selection runs once per template and every matching event inherits the name. A dashboard grouped by message pattern is grouped by the code that printed the lines. Timestamps get the same treatment: the engine works out a template's datetime format once and applies it to every instance instead of re-detecting it per event.

The standard stack does all of this per event, when it should be done once per shape. Splunk sourcetype extractions, Datadog log pipelines, Elasticsearch grok rules: outside the prebuilt integrations, each wants a regex per format, kept current as the code changes. The deeper reason is they have no stable address to pin the answer to. A grouping that drifts between queries forces the work back onto the raw value, which can't separate the kafka 200 from an HTTP 200.

The open question I find more interesting: how much per-event work should move to the shape. Cost attribution has a per-shape answer: bill by template instead of by line. So does retention: decide once whether a shape is worth keeping.

The runtime classifier modules are open source at github.com/log-10x/modules/tree/main/pipelines/run/modules/initialize; the HTTP config and its strict-marker adjacency check are at pipelines/run/initialize/httpCode/config.yaml, and the name selection is message-template.js.


Related: how a line gets assigned to a stable template and where the structural vocabulary comes from. A future post covers how templates also shrink the Bloom filters that route queries across S3-stored event archives.