Edge Geospatial IoT Gateway Processing

Black-box flight recorder logs for post-crash analysis

The most useful minute of logs on a field device is the minute before it stopped working, and it is the one minute conventional logging reliably loses: it was buffered, or the log file was rotated, or the process died before it flushed. A flight recorder is a small circular file written with the same crash-safety discipline as a spool, holding the last few thousand structured events, readable after any restart. This guide builds one, inside field diagnostics and recovery and the Edge Operations & Observability guide.

Why not just log to a file

Ordinary logging fails at exactly this task for four independent reasons, and fixing any one of them does not help.

It is buffered. A logging handler writes into a buffer flushed on a boundary; a process killed by the OOM reaper takes that buffer with it, which is precisely the incident being investigated.

It is unbounded, then rotated. Rotation keeps size under control by discarding whole files, and the file discarded is usually the one that spans the interesting moment.

It is expensive. Formatting a string, acquiring a lock and writing it costs tens of microseconds and allocates, which is why the noisy paths — the ones you most want a record of — are usually logged at a level that is disabled.

It is not structured. Reconstructing a sequence of state transitions from prose lines requires parsing text written by someone who did not anticipate the question.

A flight recorder inverts every one of those: fixed-size binary records, a bounded circular file, an append that costs under a microsecond, and a schema that makes the sequence machine-readable.

What survives a crash under each logging arrangement Three arrangements against three failure modes. A buffered text log survives a clean shutdown, loses the last buffer on a process crash and loses it on a power cut. An unbuffered text log with a flush per line survives all three but costs about forty microseconds and a flash write per line, which makes it unusable on the hot paths. A circular binary recorder with a periodic sync survives a clean shutdown and a process crash entirely, and loses at most the last sync interval on a power cut, at under a microsecond per record. Three arrangements, three failures, one cost column clean shutdownprocess crashpower cutcost per record buffered text log keptlast buffer lostlost≈8 µs flush-per-line text keptkeptkept≈40 µs + a flash write circular binary recorder keptkept≤ one sync interval<1 µs The middle row is correct and unaffordable; the bottom row trades a bounded, known loss for two orders of magnitude of cost.
Only the bottom row is cheap enough to leave enabled on the paths that matter, which is the whole point — a recorder nobody dares call is not a recorder.

The recorder 

# recorder.py — fixed-size circular event recorder.
# 32-byte records in a preallocated file, mmap'd, with an explicit head index.
# Append costs one struct.pack_into and one integer increment: no allocation,
# no lock beyond a cheap one, safe to call from the hot path.
import mmap
import os
import struct
import time
import zlib

REC = struct.Struct("<IHHQiiI")     # crc, kind, code, mono_ns, a, b, seq
REC_LEN = REC.size                   # 32 bytes
CAPACITY = 8192                      # 256 KB of file
HEADER = struct.Struct("<4sIII")     # magic, version, capacity, head
HEADER_LEN = 32                      # padded


class Recorder:
    __slots__ = ("mm", "fh", "head", "seq", "sync_every", "since_sync")

    def __init__(self, path: str, sync_every: int = 64):
        size = HEADER_LEN + CAPACITY * REC_LEN
        new = not os.path.exists(path) or os.path.getsize(path) != size
        self.fh = open(path, "r+b" if not new else "w+b")
        if new:
            self.fh.truncate(size)
        self.mm = mmap.mmap(self.fh.fileno(), size)
        magic, version, cap, head = HEADER.unpack_from(self.mm, 0)
        if new or magic != b"FLTR" or cap != CAPACITY:
            HEADER.pack_into(self.mm, 0, b"FLTR", 1, CAPACITY, 0)
            head = 0
        self.head = head
        self.seq = 0
        self.sync_every = sync_every
        self.since_sync = 0

    def record(self, kind: int, code: int, a: int = 0, b: int = 0) -> None:
        """One event. `kind` is a subsystem, `code` an event within it, and
        `a`/`b` are two integers whose meaning is defined per (kind, code) —
        deliberately not a string, because formatting is what makes logging
        expensive enough to disable."""
        off = HEADER_LEN + (self.head % CAPACITY) * REC_LEN
        mono = time.monotonic_ns()
        self.seq += 1
        body = struct.pack("<HHQiiI", kind, code, mono, a, b, self.seq)
        crc = zlib.crc32(body) & 0xFFFFFFFF
        REC.pack_into(self.mm, off, crc, kind, code, mono, a, b, self.seq)
        self.head += 1
        HEADER.pack_into(self.mm, 0, b"FLTR", 1, CAPACITY, self.head)

        self.since_sync += 1
        if self.since_sync >= self.sync_every:
            # Flush the dirty pages. On a 256 KB mapping this is a handful of
            # pages and costs about 200 µs, amortised over 64 records.
            self.mm.flush()
            self.since_sync = 0

    def dump(self):
        """Yield records oldest-first. Skips slots whose CRC does not verify,
        which is how a torn write during a power cut is handled."""
        _magic, _v, cap, head = HEADER.unpack_from(self.mm, 0)
        start = max(0, head - cap)
        for i in range(start, head):
            off = HEADER_LEN + (i % cap) * REC_LEN
            crc, kind, code, mono, a, b, seq = REC.unpack_from(self.mm, off)
            body = struct.pack("<HHQiiI", kind, code, mono, a, b, seq)
            if (zlib.crc32(body) & 0xFFFFFFFF) != crc:
                continue
            yield {"kind": kind, "code": code, "mono_ns": mono,
                   "a": a, "b": b, "seq": seq}

Two decisions define the design. The record carries integers rather than text, so an append is a pack into a mapped page rather than a format, a lock and a write. And the head index is updated in the header after the record, so a crash between the two leaves a complete record that the next dump will read — the ordering is deliberately biased toward keeping data rather than toward a perfectly consistent counter.

Making integers readable

A recorder full of kind=3 code=17 a=482 b=0 is only useful if something can name those. The decoder lives off-device, in the same repository as the firmware, and is versioned with it.

# decode.py — the schema that makes a dump readable. Ships with the tooling,
# not with the device: the device's job is to record, not to explain.
KINDS = {1: "pipeline", 2: "spool", 3: "uplink", 4: "power", 5: "geo"}

EVENTS = {
    (1, 1): ("fix_parsed",        "sats={a} hdop_x10={b}"),
    (1, 2): ("fix_rejected",      "reason={a}"),
    (1, 9): ("worker_stalled",    "ms={a}"),
    (2, 1): ("spool_append",      "partition={a} bytes={b}"),
    (2, 7): ("spool_dropped",     "partition={a} count={b}"),
    (3, 1): ("uplink_connected",  "rssi_dbm={a}"),
    (3, 4): ("uplink_failed",     "errno={a} attempt={b}"),
    (4, 2): ("brownout_detected", "mv={a}"),
    (5, 3): ("fence_crossed",     "zone={a} inside={b}"),
}


def render(rec: dict) -> str:
    name, fmt = EVENTS.get((rec["kind"], rec["code"]), ("unknown", "a={a} b={b}"))
    return (f"{rec['mono_ns'] / 1e9:12.3f}  {KINDS.get(rec['kind'], '?'):9s} "
            f"{name:18s} " + fmt.format(a=rec["a"], b=rec["b"]))

Keeping the schema off-device is what allows the record to stay at 32 bytes. It also means a decoder can be improved after the fact — a dump collected last year can be re-rendered with today’s understanding, which is not possible when the device baked its interpretation into a text string.

The 32-byte record and how much history 256 KB buys A record of four bytes of checksum, two of kind, two of code, eight of monotonic nanoseconds, two four-byte integer payloads and four bytes of sequence number, totalling 32 bytes. At 8192 slots the file is 256 kilobytes. On a device recording about 6 events a second in normal operation that covers 22 minutes; on one recording 40 a second during a fault it covers 3.4 minutes, which is the interval that matters. A note observes that the recorder deliberately holds less history when the device is busiest, which is the correct bias. 32 bytes a record, 8 192 slots, 256 KB of flash crc · 4 kind · 2 code · 2 monotonic ns · 8 a · 4 b · 4 seq · 4 normal operation · ≈6 events/s 22 minutes of history during a fault · ≈40 events/s 3.4 minutes — the interval that matters The recorder deliberately holds less history when the device is busiest, which is the correct bias: a fault generates events, and the events immediately before the failure are the ones worth keeping. Size the file from the fault-rate figure, not the idle one.
Sizing from the idle rate produces a recorder that looks generous and holds four minutes of the only traffic anyone will read.

Constraint validation

Constraint Expected impact Mitigation built into the code
CPU A recorder too expensive to call is not called Integer pack into a mapped page; under a microsecond, no allocation
Flash Continuous writing wears the card A fixed 256 KB region rewritten in place; the flush is amortised over 64 records
Power loss A torn record must not break the dump Per-record CRC; dump skips what does not verify
RAM Must not grow with event volume A fixed mapping; the file is the buffer
Restart The record must survive the crash being investigated Mapped file with periodic flush; a process crash loses nothing

Gotchas and edge cases

  • mmap.flush() is not free and is not per record. Flushing on every append turns a sub-microsecond call into a syscall and a page write. Amortise it, and accept the bounded loss on a power cut — the process-crash case, which is the common one, loses nothing regardless.
  • Monotonic time does not cross a reboot. The dump from before a restart cannot be interleaved with the one after by timestamp. Record a boot marker as the first event after every start, and treat each boot’s records as an independent sequence.
  • Do not record inside the recorder’s own failure path. A recorder that logs its own errors through itself will fill the file with them during exactly the fault you are trying to capture. Fail silently and expose a counter instead.
  • Reserve the low kind and code numbers. A schema that renumbers events between firmware versions makes historical dumps unreadable. Treat (kind, code) pairs as permanent once shipped; add new ones rather than reusing old ones.
  • The dump has to be reachable without a network. Expose it through the serial console described in serial console health endpoints, and as a file a technician can copy to a USB stick. A recorder that can only be read by uploading it is useless in the case where the uplink is the fault.

Using it

The value shows up in three situations. After an unexplained restart, the last records before the boot marker say what the device was doing — a stalled worker, a spool that filled, a brownout. After a field report of odd behaviour, the sequence of state transitions distinguishes a device that behaved correctly from one that did not, without reproducing anything. And during a rollout, comparing dumps from a device that took an update badly against one that took it well isolates the difference far faster than reasoning about the diff.

Sync a compressed dump on demand rather than continuously: a command that requests it, and the device attaches the last N records to the event stream. At 32 bytes a record, 2 000 records compress to a few kilobytes, which is affordable on any link when someone has asked for it and unaffordable as a routine push.

Choosing what to record

A recorder that captures everything fills with noise, and one that captures only errors misses the sequence that explains them. The useful discipline is to record state transitions and decisions, not activity.

Record when a component changes state — the pipeline entering degraded mode, the uplink connecting or dropping, a partition starting to drop records, the thermal governor throttling. Record when a decision is taken that a human might later question: a fix rejected, a zone crossing suppressed because uncertainty was too high, a bundle refused. And record the boundaries — boot, shutdown, configuration reload, layer swap — because they anchor everything between them.

Do not record per-fix activity at full rate. A device processing forty fixes a second and recording each one exhausts a 8 192-slot buffer in three minutes, which is exactly the history someone will want. Record a periodic summary instead — one record a second carrying the counts — and let the individual events stay in the metrics.

What belongs in the recorder and what does not Four categories. State transitions — mode changes, connection changes, throttling — always belong, at a few per minute. Decisions a human might question, such as a rejected fix or a suppressed crossing, belong at a few per minute. Boundaries such as boot, shutdown and configuration reload always belong and are rare. Per-fix activity does not belong at full rate, because forty a second exhausts the buffer in three minutes; a one-per-second summary carrying counts belongs instead. Transitions and decisions, not activity state transitions mode changes, link up/down, throttling a few per minute questionable decisions fix rejected, crossing suppressed, bundle refused a few per minute boundaries boot, shutdown, config reload, layer swap rare, and they anchor everything per-fix activity summarise once a second instead — 40/s exhausts the buffer in 3 minutes
The bottom row is the one that turns a useful recorder into a very fast way of discarding the history you needed.

Related in Field Diagnostics & Recovery