---
title: 'Log Parsing and Structuring'
source: 'https://academia.sh/en/courses/devops-observability/log-parsing-and-structuring'
course: 'Observability and Operations'
language: en
updated: '2026-09-13T05:08:22+00:00'
license: 'CC BY-SA 4.0'
objectives:
    - 'Parses real log lines into fields and counts two store formats against the question set'
    - 'Measures the line the rule misses and the fields left silently empty when the format changes'
    - 'Separates the question that is answerable from the question that is answered correctly and writes the cost of the gap'
---

# Log Parsing and Structuring

Real log lines are parsed and turned into searchable fields, and two store formats are counted against the question set: how many questions unstructured text answers, how many questions open up once fields are produced. When the format changes, the line the parsing rule silently misses is counted, and the cost of the wrong answer that results is written down.

The previous lesson counted the line as a whole: how many lines produced, how many lines dropped,
how many bytes stored. But the line that reaches the store is still **text**. On text, you can
search for a string and count how many lines it appears in; you cannot ask which region's readings
failed validation in which environment, because that requires the line to be broken into parts.

This lesson measures that step. Real lines are run through a parsing rule, turned into searchable
fields, and two store formats — raw text and fields — are counted against the same question set.
The third measure is the line the rule **misses**: when a service changes format, fields stay
silently empty, and a query returns the wrong answer without raising an error.

The lines come from the **regional measurement network's** nightly validation stream and are
**fictional**; the ground truth for every line is kept separately, and the measurement is made
against it.

**ML25.** The 900 lines of the validation stream are produced with our own generator, seed
`20260903`; the structured ground truth for every line is stored separately, and correctness is
checked against it.
**ML26.** The validator service switches to a new version after the quarter mark of the lines and
changes its field names: `zone` instead of `region`, `status` instead of `result`,
`duration_ms=…` instead of `duration=…ms`.
**ML27.** The parsing rule is written against the old format and is not changed after the version
switch.
**ML28.** Most of region 07's failed readings are written by the validator; region 13's failures
are written by the other services.
**ML29.** Unstructured text can only count a single string known in advance; grouping and numeric
operations require a field.
**ML30.** A field must be filled in at least 80% of lines to be usable in a grouping or numeric
question.

## Real Log Lines

```js
// lines.mjs — real log lines are produced; each line's ground truth is kept separately.
export const makeRng = (t) => () => (t = (t * 1103515245 + 12345) % 2147483648) / 2147483648;
export const REGION = ["01", "03", "05", "07", "09", "11", "13", "15", "17", "19", "21"];
export const DROP = { "07": [0.80, 0.10], "13": [0.12, 0.26] };
export const SERVICE = ["reading-collector", "validator", "billing", "work-order"];
const two = (n) => String(n).padStart(2, "0");

// the validator changes its field names after switching to the new version: region->zone, result->status
export const generate = (count = 900, seed = 20260903) => {
  const rand = makeRng(seed), lines = [], records = [];
  for (let i = 0; i < count; i++) {
    const service = SERVICE[Math.floor(rand() * SERVICE.length)];
    const newFormat = service === "validator" && i > count * 0.25;   // version switch
    const r = REGION[Math.floor(rand() * REGION.length)];
    // drop rate by region: [at the validator, at the other services]
    const [dv, do_] = DROP[r] ?? [0.10, 0.07];
    const failed = rand() < (service === "validator" ? dv : do_);
    const duration = 60 + Math.floor(rand() * 320), instance = `u${two(Math.floor(rand() * 29))}`;
    const time = `2026-08-02T02:${two(Math.floor(i / 15))}:${two(i % 60)}Z`;
    records.push({ service, region: r, result: failed ? "failed" : "passed", duration, instance, newFormat });
    lines.push(newFormat
      ? `${time} environment=production service=${service} instance=${instance} level=info event=reading` +
        ` zone=${r} status=${failed ? "failed" : "passed"} duration_ms=${duration}`
      : `${time} production ${service}[${instance}] INFO reading processed region=${r}` +
        ` result=${failed ? "failed" : "passed"} duration=${duration}ms`);
  }
  return { lines, records };
};
```

Both formats carry the same information; the only difference is in the names. This is the most
common outcome of a logging convention change, and it is not an error for either service — both
lines are valid.

## Parsing and the Missed Line

```js
// parse.mjs — unstructured text versus searchable fields, compared against the question set.
import { generate, SERVICE } from "./lines.mjs";

const { lines, records } = generate();
console.log(`log lines produced: ${lines.length}`);
console.log("sample lines");
for (const i of [0, 1, 227, 232]) console.log(`  ${lines[i]}`);

// parsing rule written against the old format
const RULE = /^(\S+) (\w+) ([\w-]+)\[(\w+)\] (\w+) (.*?) region=(\d+) result=(\w+) duration=(\d+)ms$/;
const fields = lines.map((s) => {
  const m = RULE.exec(s);
  return m ? { time: m[1], environment: m[2], service: m[3], instance: m[4], region: m[7], result: m[8], duration: +m[9] }
    : { time: s.slice(0, 20).trim(), environment: "", service: "", instance: "", region: "", result: "", duration: null };
});
const matched = fields.filter((a) => a.region).length;
console.log(`\nparsing rule matched ${matched}/${lines.length} lines;` +
  ` ${lines.length - matched} lines have silently empty fields (${(100 * (lines.length - matched) / lines.length).toFixed(1)}%)`);

// Q7: which region's readings were not validated
const tally = (source, regionOf, resultOf) => {
  const t = {};
  for (const k of source) { const r = regionOf(k); if (!r) continue; t[r] ??= [0, 0]; t[r][0]++; if (resultOf(k) === "failed") t[r][1]++; }
  return t;
};
const worst = (t) => Object.entries(t).sort((a, b) => b[1][1] - a[1][1])[0];
const actual = tally(records, (k) => k.region, (k) => k.result), parsed = tally(fields, (a) => a.region, (a) => a.result);
const [actualRegion, actualCounts] = worst(actual), [parsedRegion, parsedCounts] = worst(parsed);
console.log("\nQ7 'which region's readings were not validated'");
console.log(`  actual        region ${actualRegion}  ${actualCounts[1]} failed / ${actualCounts[0]} readings`);
console.log(`  from parsing  region ${parsedRegion}  ${parsedCounts[1]} failed / ${parsedCounts[0]} readings` +
  `   deviation ${(100 * Math.abs(parsedCounts[1] - actualCounts[1]) / actualCounts[1]).toFixed(1)}%   same answer: ${actualRegion === parsedRegion ? "yes" : "no"}`);
console.log(`  the rule never saw ${actual[actualRegion][1] - (parsed[actualRegion]?.[1] ?? 0)} failed readings for region ${actualRegion}`);

// unstructured text can only count a single known phrase
const PHRASE = "reading processed", matchCount = lines.filter((x) => x.includes(PHRASE)).length;
console.log(`\nQ5 'how many readings did the nightly job process'`);
console.log(`  actual ${records.length}   lines containing "${PHRASE}" in raw text ${matchCount}` +
  `   deviation ${(100 * (records.length - matchCount) / records.length).toFixed(1)}%`);

// Q1: does the service average come out correctly from the fields
const avgDuration = (l, s, f) => { const g = l.filter((x) => x.service === s).map(f); return g.reduce((a, b) => a + b, 0) / g.length; };
const slowest = (l, f) => SERVICE.map((s) => [s, avgDuration(l, s, f)]).sort((a, b) => b[1] - a[1])[0];
const [actualSlow, actualSlowVal] = slowest(records, (k) => k.duration), [parsedSlow, parsedSlowVal] = slowest(fields.filter((a) => a.service), (a) => a.duration);
console.log(`Q1 'which service slowed down'   actual ${actualSlow} ${actualSlowVal.toFixed(0)} ms` +
  `   from parsing ${parsedSlow} ${parsedSlowVal.toFixed(0)} ms   same answer: ${actualSlow === parsedSlow ? "yes" : "no"}`);

// the six questions within this stream's scope; the others sit on other line types
const QUESTIONS = [["Q1", ["service", "duration"], "numeric", actualSlow === parsedSlow], ["Q2", ["duration"], "numeric", true],
  ["Q3", ["environment", "result"], "group", true], ["Q5", ["phrase"], "count", matchCount === records.length],
  ["Q7", ["region", "result"], "group", actualRegion === parsedRegion], ["Q8", ["instance"], "group", true]];
const coverage = (a) => fields.filter((x) => x[a] !== "" && x[a] !== null).length / fields.length;
const bytes = lines.reduce((t, x) => t + x.length, 0);
const fieldBytes = fields.reduce((t, a) => t + Object.values(a).join("").length + Object.keys(a).length * 2, 0);
console.log("\nstore format          bytes     answerable  correct answer  bytes/correct question   answered wrong");
const print = (name, b, y) => {
  const correct = y.filter(([, , , ok]) => ok);
  console.log(`${name.padEnd(18)}${b.toLocaleString("en-US").padStart(9)}${`${y.length}/6`.padStart(15)}` +
    `${`${correct.length}/6`.padStart(16)}${(correct.length ? Math.round(b / correct.length).toLocaleString("en-US") : "-").padStart(24)}   ` +
    (y.filter((q) => !correct.includes(q)).map(([k]) => k).join(" ") || "-"));
};
print("raw text", bytes, QUESTIONS.filter(([, , i]) => i === "count"));
print("fields + index", bytes + fieldBytes, QUESTIONS.filter(([, req, , ]) =>
  req.every((g) => g === "phrase" || coverage(g) >= 0.80)));
```

```
log lines produced: 900
sample lines
  2026-08-02T02:00:00Z production validator[u02] INFO reading processed region=11 result=passed duration=210ms
  2026-08-02T02:00:01Z production reading-collector[u21] INFO reading processed region=01 result=passed duration=217ms
  2026-08-02T02:15:47Z environment=production service=validator instance=u21 level=info event=reading zone=05 status=passed duration_ms=250
  2026-08-02T02:15:52Z environment=production service=validator instance=u08 level=info event=reading zone=11 status=passed duration_ms=83

parsing rule matched 736/900 lines; 164 lines have silently empty fields (18.2%)

Q7 'which region's readings were not validated'
  actual        region 07  29 failed / 97 readings
  from parsing  region 13  18 failed / 51 readings   deviation 37.9%   same answer: no
  the rule never saw 21 failed readings for region 07

Q5 'how many readings did the nightly job process'
  actual 900   lines containing "reading processed" in raw text 736   deviation 18.2%
Q1 'which service slowed down'   actual validator 225 ms   from parsing validator 238 ms   same answer: yes

store format          bytes     answerable  correct answer  bytes/correct question   answered wrong
raw text            103,440            1/6             0/6                       -   Q5
fields + index      159,828            6/6             4/6                  39,957   Q5 Q7
```

The rule matches 736 of the 900 lines. The remaining 164 lines are **not rejected**; when parsing
fails, the line is not discarded, only its fields stay empty. The store holds 900 records, all
searchable, all with their timestamp in place. Only in 164 of them are the region, result,
service, and duration fields empty, and that leaves no trace in a query's result.

## The Answer That Changes Silently

Q7 carries this lesson's most expensive number. In reality, the region with the most failed
readings is **07**: twenty-nine of ninety-seven readings failed validation. The answer that comes
out of the parsed fields is **13**. The deviation is not merely 37.9 percent — **the answer is
different**.

The reason lies in the design from the first section. Most of region 07's failed readings are
written by the validator, which has switched to the new format that does not match the rule; the
rule has **never seen** twenty-one failed readings for region 07. Region 13's failures are written
by the other services, still on the old format, and all get counted. The field crew goes to the
wrong region: work orders open for region 13, region 07's meters stay unread, and no bill is
issued.

This is a loss type not seen on the metric side. A missing metric breaks the series, visibly. An
empty field lets **the query still run** — over fewer lines, without saying so. The signal of the
loss disappears along with the loss itself.

Q5 shows the same phenomenon in a plainer form. How many readings the nightly job processed can be
answered by counting the string `reading processed` in the raw text — the only kind of question
unstructured text can genuinely answer. But the new format does not write that string; the count
comes out to 736 instead of 900, 18.2 percent short, wrong by the same amount whether taken by
grep or from parsing.

Q1, by contrast, gives the correct answer: the slowest service is the validator in both
calculations. But its value shifts — 225 in the actual average, 238 milliseconds from parsing. The
same missing data changes the answer to one question and only shifts the number in another; which
of the two happens depends on the data's distribution and is not known while the query is written.

## Text, Fields, and Cost

The last table places the two store formats side by side. Raw text is 103,440 bytes and can
answer **one** of the six questions — and it answers it wrong. Once fields are produced, the bytes
rise to 159,828, a 54.5 percent increase, and **all six of the six questions** become answerable.
What grows is not the lines, it is the field names, the separated values, and the search index.

But the table's real column is the third one: only **four** of the six answerable questions are
answered **correctly**. This two-question gap between "answerable" and "correct" is what this
lesson measures. The cost per correct answer is 39,957 bytes; if all six questions had been
correct, it would have been 26,638 bytes. The difference is the price of the rule being left
unmaintained, and there is no alert that would trigger on it — the 18.2 percent non-matching line
share appears nowhere unless it is collected as a metric in its own right.

## Five Ways to Fix the Rule

Five parsing options are applied to the same set of lines; matched lines, correct answers, and
bytes are measured together.

```js
// options.mjs — the lines matched, the correct answers, and the byte cost of each parsing option.
import { generate } from "./lines.mjs";

const { lines, records } = generate();
const OLD = /^(\S+) (\w+) ([\w-]+)\[(\w+)\] \w+ .*? region=(\d+) result=(\w+) duration=(\d+)ms$/;
const NEW = /^(\S+) environment=(\w+) service=([\w-]+) instance=(\w+) .*? zone=(\d+) status=(\w+) duration_ms=(\d+)$/;
const keyValue = (s) => Object.fromEntries([...s.matchAll(/(\w+)=(\S+)/g)].map((m) => [m[1], m[2]]));
const FIELD_MAP = { zone: "region", status: "result", duration_ms: "duration" };
const remap = (o) => Object.fromEntries(Object.entries(o).map(([k, v]) => [FIELD_MAP[k] ?? k, v]));
const fromMatch = (m) => ({ environment: m[2], service: m[3], instance: m[4], region: m[5], result: m[6], duration: +m[7] });
const empty = { environment: "", service: "", instance: "", region: "", result: "", duration: null };

const OPTIONS = [
  ["single rule (old format)", (s) => { const m = OLD.exec(s); return m ? fromMatch(m) : empty; }],
  ["two rules (old + new)", (s) => { const m = OLD.exec(s) || NEW.exec(s); return m ? fromMatch(m) : empty; }],
  ["key-value, unmapped", (s) => ({ ...empty, ...keyValue(s) })],
  ["key-value + field map", (s) => ({ ...empty, ...remap(keyValue(s)) })],
  ["structured at the source", null],                  // every line is written under a single convention
];
const structured = records.map((k) => `time=2026-08-02T02:00:00Z environment=production service=${k.service}` +
  ` instance=${k.instance} event=reading region=${k.region} result=${k.result} duration=${k.duration}`);
const worst = (l) => {
  const t = {};
  for (const a of l) { if (!a.region) continue; t[a.region] ??= [0, 0]; t[a.region][0]++; if (a.result === "failed") t[a.region][1]++; }
  return Object.entries(t).sort((a, b) => b[1][1] - a[1][1])[0];
};
const [actualRegion] = worst(records), rawBytes = lines.reduce((t, x) => t + x.length, 0);

console.log("option                           matched  Q7 answer  Q7 correct  Q5 correct    bytes  bytes/correct question");
for (const [name, f] of OPTIONS) {
  const source = f ? lines : structured;
  const fields = f ? lines.map(f) : structured.map((s) => ({ ...empty, ...keyValue(s) }));
  const filled = fields.filter((a) => a.region).length;
  const [region] = worst(fields), q7 = region === actualRegion, q5 = filled === records.length;
  const bytes = source.reduce((t, x) => t + x.length, 0) +
    fields.reduce((t, a) => t + Object.values(a).join("").length + Object.keys(a).length * 2, 0);
  const correct = 4 + (q7 ? 1 : 0) + (q5 ? 1 : 0);       // Q1 Q2 Q3 Q8 correct under every option
  console.log(`${name.padEnd(31)}${String(`${filled}/900`).padStart(9)}${String(region).padStart(11)}` +
    `${(q7 ? "yes" : "no").padStart(12)}${(q5 ? "yes" : "no").padStart(12)}` +
    `${bytes.toLocaleString("en-US").padStart(9)}${Math.round(bytes / correct).toLocaleString("en-US").padStart(24)}`);
}
console.log(`\nraw text ${rawBytes.toLocaleString("en-US")} bytes; actual worst region ${actualRegion}`);
```

```
option                           matched  Q7 answer  Q7 correct  Q5 correct    bytes  bytes/correct question
single rule (old format)         736/900         13          no          no  140,028                  35,007
two rules (old + new)            900/900         07         yes         yes  145,424                  24,237
key-value, unmapped              736/900         13          no          no  132,560                  33,140
key-value + field map            900/900         07         yes         yes  131,576                  21,929
structured at the source         900/900         07         yes         yes  188,368                  31,395

raw text 103,440 bytes; actual worst region 07
```

The third row is the unexpected one. The key-value parser reads both formats and rejects no line;
even so, the Q7 answer is still 13. The gap is between parsing succeeding and the field coming out
under **the right name**: the new format writes the region under the `zone` key, the query looks
for `region`, and the two do not match. A format-independent parser solves the format problem, it
**does not solve the naming problem**.

The fourth row is the cheapest correct option: a three-line field map is added to the same parser,
and the cost per correct answer drops from 35,007 bytes to 21,929. The two-rule option is also
correct, but every new format demands one more rule; the mapping table only grows by one line.

The fifth row solves the problem at the source: every service writes under a single convention,
and no parsing rule is needed at all. It cannot break, and it needs no maintenance — and it is
**the most expensive**: because the field names repeat on every line, the bytes rise from 131,576
to 188,368, a 43.2 percent increase. Parsing is a byte saving, and the price of that saving is
maintenance load; which one is cheaper depends on line volume and how often the format changes.

## Summary

- The parsing rule matches 736 of the 900 lines; the remaining 164 lines are not discarded, only
  their fields stay empty (18.2%), and this leaves no trace in any query result.
- Unstructured text can answer only one of six questions (counting a single known string); once
  fields are produced, all six become answerable, and bytes rise by 54.5%.
- Being answerable is not the same as being correct: four of the six questions are answered
  correctly. On Q7, the answer comes out as region 13 instead of region 07 — the rule has never
  seen 21 failed readings for region 07.
- The same missing data does not change the answer on Q1, it only shifts the value from 225 to 238
  milliseconds; which question breaks depends on the distribution of the data, and it is not known
  while the query is being written.
- The cost per correct answer is 39,957 bytes; if the rule had been kept up to date, it would have
  been 26,638 bytes. The 18.2% non-matching line share appears nowhere unless it is collected as a
  metric.
- A format-independent parser solves the format problem, not the naming problem (still 736/900);
  once a field map is added, the cost per correct answer comes to 21,929 bytes. Writing structured
  at the source cannot break, but it takes 43.2% more bytes.

## Next Step

Up to this point, metrics and logs were collected, parsed, and counted against the question set
separately. But in every measurement, retention was held fixed, and cost was computed at a single
level of detail. A real pipeline does not work that way: as data ages, its detail is reduced, it is
downsampled, summarized, and eventually discarded. The next lesson scans through these tiers and
counts, at every tier, the number of questions answerable together with the bytes: where the cost
per question goes tier by tier, and which question the cheapest tier loses.