35г. A log on the device: levels, a ring buffer and binary records instead of printf

Text output has already been covered in the handbook: printf to a port (16.6), ITM and SWO (section 21), RTT (21а), the cost of printf in bytes (74.4). Section 35в saved a snapshot of a failure, section 112 received the log on a server. What is missing is the middle — the log on the device itself. One that you can write to from an interrupt, whose strings do not take up flash, and whose disabled messages cost nothing.

Here is such a log in full: 776 bytes of code on Cortex‑M3. There are four levels; the unneeded ones are cut off at build time. A record is words in a ring buffer in RAM: the message number, the time and the raw arguments; writing it takes from 60 to 93 instructions. Format strings do not get into the firmware. They stay on the computer, in a dictionary built by a Python script. The background loop sends the records to the line in COBS frames with CRC‑16, and a decoder on the computer turns them back into strings. Everything is shown by runs: 5000 random messages checked against the real printf, the stream corrupted and cut, the ring overflowed, the firmware run in QEMU and compared with snprintf by size, bytes on the line and instruction count.

The idea is known from the open-source project Trice (github.com/rokath/trice). Its sources were not used: all the code in this section is our own.

Foundations: section 194 — the COBS frame and CRC‑16/XMODEM, the same algorithm here; section 127 — the ## macros, __LINE__ and _Static_assert; section 21а — the ring and counting instructions in QEMU. Experiments on the computer — the stm-sys:1 image (gcc 12.2.0, Python 3.11.2): the same log file was built for the PC and run against the decoder. Experiments for Cortex‑M — the stm-arm:1 image: arm-none-eabi-gcc 12.2.1 with the -Os option, newlib-nano, QEMU 7.2.22 (stm32vldiscovery for F1 and netduinoplus2 for F4), gdb 13.1. The same code was built with armclang 6.24.

Terms used in the documentation

Term	Meaning
log level	the severity of a log message
compile-time filtering	cutting messages off at build time
ring buffer	a circular buffer
deferred logging	write now, output later
binary (dictionary-based) logging	a binary log with a dictionary
format string	the printf format string
message ID	the message number
drop newest / drop oldest	lose new records / lose old records
frame delimiter	the byte that separates frames
sequence counter	a frame counter

35г.1 What goes to the device and what stays on the computer

In the program a log call looks like printf with a level:

    case 1:
        DLOG_D("adc ch %u raw %u", (unsigned)a & 15u, (unsigned)b & 4095u);
        break;
    case 2:
        DLOG_W("temp %d.%u C over limit %d", a / 10, (unsigned)(a < 0 ? -a : a) % 10u, b);
        break;
    case 3:
        DLOG_E("i2c nack addr 0x%02x reg 0x%02x try %u", (unsigned)a & 0x7Fu, (unsigned)b & 0xFFu, (unsigned)c & 7u);
        break;

printf would do three things on the device: parse the format string, convert the numbers to text and output the characters. All of this is work that can be deferred and handed to the computer. The format string is already known at build time. So it is enough to pass its number to the device, and the arguments as they are, four bytes each.

A record in the ring is 32-bit words: the header, the time and the arguments. The header is laid out like this:

/* Заголовок записи в кольце — одно слово. Младшие 16 бит уходят в линию как есть. */
#define DLOG_ID(h)    ((h) & 0x3FFFu)            /* биты 13:0  — номер сообщения */
#define DLOG_LVL(h)   (((h) >> 14) & 3u)         /* биты 15:14 — уровень */
#define DLOG_NARG(h)  (((h) >> 16) & 7u)         /* биты 18:16 — число аргументов */
#define DLOG_LOST(h)  ((h) >> 19)                /* биты 31:19 — сколько записей потеряно перед этой */
#define DLOG_LOST_MAX 0x1FFFu                    /* 8191 значит «не меньше 8191» */
#define DLOG_ID_LOST  0u                         /* служебные номера: метка потери … */
#define DLOG_ID_START 1u                         /* … и метка запуска с отпечатком словаря */

The number is 14 bits, that is 16384 values; two of them are reserved. The level travels to the line together with the number; the argument count and the loss counter are needed only by the device itself. A record goes to the line as a frame: the number with the level (2 bytes), the frame counter (1), the time (4), the arguments (4 each) and the CRC‑16 (2). That is 9 + 4·n bytes; COBS adds one byte, the delimiter one more. In total 11 + 4·n bytes: 11 without arguments, 19 with two, 27 with four.

Here is the message adc ch 5 raw 1234 from the run in QEMU — how the firmware assembled it and how it sent it to the UART:

frame decoded: 03 c0 02 fa 00 00 00 05 00 00 00 d2 04 00 00 f7 64 (17 bytes)
frame on line: 05 03 c0 02 fa 01 01 02 05 01 01 03 d2 04 01 03 f7 64 00 (19 bytes)

03 c0 — number 3 and level 3 (D) in the upper bits, 02 — the third frame since start-up, fa 00 00 00 — time 250, then 5 and 1234, and the CRC at the end. The string adc ch %u raw %u is not in the frame, and it is not in the firmware image either. The decoder with the dictionary output the start of the log like this:

0 E start, dictionary 2c9c6546 (same)
250 I state idle -> run
250 D adc ch 5 raw 1234
250 D pid e -12 i 3400 d -7 out 3388
1316 D pid e -192621 i 39532774 d 6009 out 39340153

The first number is the time, the letter is the level. The first line is the service record about the start-up; more about it in 35г.4.

This log has three limitations, and all of them are deliberate. Arguments are only integers up to 32 bits: %d, %i, %u, %x, %X, %c with flags and width. There are no %s strings: a string would have to be copied into the ring in full. There are no floating-point values: they are printed as scaled integers (74.4). There are at most seven arguments.

35г.2 Levels: a threshold at build time and a threshold at run time

There are four levels: errors E, warnings W, information I, debug D. There are two thresholds. The first is at build time: the DLOG_BUILD macro says how many levels get into the image at all. The second is at run time: dlog_set_level() cuts off messages that are already built in, without touching the firmware.

/* Только объявление: компилятор сверяет формат с аргументами, кода и строки в образе нет. */
int dlog_fmt_check(const char *fmt, ...) __attribute__((format(printf, 1, 2)));

#define DLOG_CAT_(a, b, c) a##b##_##c
#define DLOG_CAT(a, b, c) DLOG_CAT_(a, b, c)
#define DLOG_HERE(prefix) DLOG_CAT(prefix, DLOG_FILE, __LINE__)   /* DLOG_H_app35g_27 */

#ifndef DLOG_SINK                        /* стенд подменяет приёмник, чтобы сравнить с printf */
#define DLOG_SINK(lvl, fmt, ...) dlog_put(DLOG_HERE(DLOG_H_) | ((lvl) << 14), ##__VA_ARGS__)
#endif

#define DLOG_OFF(fmt, ...) ((void)sizeof(dlog_fmt_check(fmt, ##__VA_ARGS__)))
#define DLOG_ON(lvl, fmt, ...)                                                                  \
    do {                                                                                        \
        _Static_assert(sizeof(fmt) - 1 == DLOG_HERE(DLOG_L_), "dlog_ids.h is stale: run dlog_gen.py"); \
        DLOG_OFF(fmt, ##__VA_ARGS__);                                                           \
        DLOG_SINK(lvl, fmt, ##__VA_ARGS__);                                                     \
    } while (0)

#if DLOG_BUILD > 0
#define DLOG_E(fmt, ...) DLOG_ON(DLOG_ERR, fmt, ##__VA_ARGS__)
#else
#define DLOG_E(fmt, ...) DLOG_OFF(fmt, ##__VA_ARGS__)
#endif

The DLOG_W, DLOG_I, DLOG_D macros are made the same way, with thresholds 1, 2 and 3. The whole trick is in DLOG_OFF. A disabled call turns into sizeof of a call to the function dlog_fmt_check. The sizeof operator does not evaluate its argument, so nothing gets into the image: no code, no string, not even the function itself — it is only declared. But it is declared with the format(printf, …) attribute, and the compiler still checks the format against the arguments. In the experiment the call DLOG_D("x %d y %d", a) gave a -Werror=format error both with DLOG_BUILD=4 and with DLOG_BUILD=0: a disabled message will not rot unnoticed.

What stays in the image is shown by the size. The same test firmware — sixteen messages, twelve of them in app35g.c — was built for Cortex‑M3 with -Os for five values of DLOG_BUILD. Next to it is the same firmware in the text variant, where every message goes to snprintf (35г.6):

At zero, of the twelve calls only 2 bytes remain in app35g.o: the whole function is a single return instruction bx lr. Each enabled level adds only its own calls. For the binary log its core remains at zero: the test firmware still calls dlog_init and dlog_drain.

The arguments disappear together with the code. This is convenient — and it is a trap:

static unsigned calls;

static unsigned next_sample(void)
{
    return ++calls;
}

void dlog_put(uint32_t hdr, ...)
{
    (void)hdr;
}

int main(void)
{
    for (int i = 0; i < 10; i++)
        DLOG_D("sample %u", next_sample());
    printf("DLOG_BUILD=%d next_sample called %u times\n", DLOG_BUILD, calls);
    return 0;
}

DLOG_BUILD=4 next_sample called 10 times
DLOG_BUILD=3 next_sample called 0 times

With DLOG_BUILD=3 the D level is disabled, and next_sample() is never called. Do not put into log arguments anything the program cannot work without.

The run-time threshold is the first check in dlog_put (35г.3): the level from the header is compared with the byte L.level. In the experiment on the computer, out of 5000 events with the threshold DLOG_WARN, 1716 went to the line — only E and W, and all of them matched the reference. The run-time threshold is convenient to change with a command from the computer: a device in the field stays quiet until it is asked to tell more.

35г.3 The ring of records: writing from an interrupt, overflow, deferred output

The log is split into two halves. The fast one, dlog_put, only puts words into the ring; it is called from tasks and from interrupts. The slow one, dlog_drain, encodes and outputs; it is called by the background loop when there is time.

static struct {
    uint32_t ring[DLOG_WORDS];
    uint32_t head;                       /* слов записано за всё время; двигает только dlog_put */
    uint32_t tail;                       /* слов прочитано или выброшено */
    uint32_t pending;                    /* записей отброшено после последней принятой */
    uint8_t level;                       /* порог на ходу */
    uint8_t drop_old;                    /* 0 — терять новые, 1 — терять старые */
    uint8_t seq;                         /* счётчик кадров в линии */
} L;

The ring is an array of words, not bytes: a record is always a multiple of four bytes, and the arguments are copied without packing. head and tail are not indexes but counters of words over all time; the index is obtained with a mask. That is why the ring size must be a power of two — this is enforced by _Static_assert. The number of words in use is simply head - tail, and the counters wrapping through 2³² breaks nothing. This was checked: a test with counters starting at 0xFFFFFF00 produced a stream byte-for-byte equal to the normal one.

static uint32_t add_lost(uint32_t hdr, uint32_t n)
{
    uint32_t v = DLOG_LOST(hdr) + n;
    if (v > DLOG_LOST_MAX)
        v = DLOG_LOST_MAX;
    return (hdr & 0x7FFFFu) | (v << 19);
}

void dlog_put(uint32_t hdr, ...)
{
    uint32_t n = DLOG_NARG(hdr), lost = 0;
    va_list ap;
    if (DLOG_LVL(hdr) > L.level)
        return;                          /* уровень выключен на ходу */
    va_start(ap, hdr);
    uint32_t key = dlog_lock();
    while (DLOG_WORDS - (L.head - L.tail) < n + 2u) {
        if (!L.drop_old) {               /* терять новые: запись не берём, только считаем */
            L.pending++;
            goto out;
        }
        uint32_t old = L.ring[L.tail & MASK];    /* терять старые: выбросить самую старую */
        L.tail += DLOG_NARG(old) + 2u;
        lost += DLOG_LOST(old) + 1u;
    }
    if (lost)                            /* новая самая старая несёт счёт: «передо мной потеряно» */
        L.ring[L.tail & MASK] = add_lost(L.ring[L.tail & MASK], lost);
    uint32_t w = L.head;
    L.ring[w++ & MASK] = add_lost(hdr, L.pending);
    L.pending = 0;
    L.ring[w++ & MASK] = dlog_now();
    while (n--)
        L.ring[w++ & MASK] = va_arg(ap, uint32_t);
    L.head = w;                          /* запись видна читателю только целиком */
out:
    dlog_unlock(key);
    va_end(ap);
}

There may be several writers: a task and an interrupt that preempted it. So reserving space and writing the words are done with interrupts disabled:

static inline uint32_t dlog_lock(void)
{
    uint32_t key;
    __asm volatile("mrs %0, primask\n"
                   "cpsid i" : "=r"(key) :: "memory");
    return key;
}

static inline void dlog_unlock(uint32_t key)
{
    __asm volatile("msr primask, %0" :: "r"(key) : "memory");
}

This is the critical section from 124.4: save PRIMASK, disable, and at the end restore it as it was — so the function can also be called where interrupts are already disabled. The question is for how long. gdb counted the instructions step by step in QEMU:

The numbers are the same for Cortex‑M3 and Cortex‑M4. The time is taken inside the disabled section: otherwise a record with a later time could land in the ring earlier. Hence the requirement on dlog_now(): it must be short and must not wait for anything. head is moved as the last action: the reader sees a record only as a whole.

Overflow. If the background loop cannot keep up, the ring fills up. There are two choices, and the choice is made in dlog_init. Drop newest: the record is not taken, and the pending counter grows; the next accepted record carries it in the upper bits of its header. Drop oldest: the oldest records are thrown out until there is enough space, and their number is written into the header of the record that has become the oldest. In both cases a service message lost N goes to the line before the record — the loss is visible in the log itself, in its proper place.

The experiment on the computer: a ring of 256 words, 5000 events in batches of 100 with no output between them, and after each batch, output until the ring is empty.

The count adds up exactly: not a single record vanished silently. With drop newest there are more markers than batches: a long record no longer fits into a full ring, but a short one may still slip in, and a series of losses breaks into pieces. Which one to choose depends on the question. The start of a batch explains how it all began; the end shows what happened right before the failure, and then the log nicely complements the snapshot from 35в.

A task and an interrupt together. The third step of the test firmware in QEMU: the task writes 300 messages and outputs one record after each, while SysTick meanwhile writes from an interrupt.

void SysTick_Handler(void)
{
    now_ms++;
    ticks++;
    DLOG_W("tick %u from interrupt", (unsigned)ticks);
}

    DLOG_I("task and interrupt write together");
    SYST_RVR = TICK_RELOAD - 1u;
    SYST_CVR = 0;
    SYST_CSR = 7u;                               /* такт ядра, прерывание, включён */
    for (unsigned i = 0; i < TASK_STEPS; i++) {
        DLOG_I("task step %u", i);
        dlog_drain();                            /* фоновый цикл: по одной записи за проход */
    }
    SYST_CSR = 0;
    DLOG_I("done: task %u, interrupt %u",
           TASK_STEPS, (unsigned)ticks);
    drain_all();

The decoder received all 300 task steps in order and all the interrupt records — 41 of them in the run — also in order, with no losses and not a single corrupted frame. Time in the log never goes backwards. For comparison, the same test firmware was built in the text variant, where the interrupt prints its string immediately. There 24 lines out of 471 turned out torn: the interrupt cut into a task's line.

214585 I 214586 W tick 10 from interrupt

With the binary log this cannot happen: only the background loop writes to the line.

35г.4 The dictionary: numbers are assigned by a script

The remaining question is where the number comes from. You cannot write numbers by hand: they will get mixed up on the very first day. The macro builds a name from the file name and the line number: in a file with #define DLOG_FILE app35g a call on line 15 expands to DLOG_H_app35g_15. And the values of these names are written by the dlog_gen.py script: it walks through the sources, finds the calls and creates the header dlog_ids.h. The start of the header in the run:

/* Создан dlog_gen.py — не править. H: номер | число аргументов << 16; L: длина формата. */
#define DLOG_DICT_CRC 0x2c9c6546u
#define DLOG_H_app35g_12 0x00002u
#define DLOG_L_app35g_12 17
#define DLOG_H_app35g_15 0x20003u
#define DLOG_L_app35g_15 16

DLOG_H is the ready-made half of the record header: number 3 and two arguments. DLOG_L is the length of the format string; it is checked by the _Static_assert in the DLOG_ON macro. As a second file, the script writes the dictionary for the computer:

{
 "format": 1,
 "crc": "0x2c9c6546",
 "history": [],
 "messages": [
  {"id": 0, "fmt": "lost %u", "args": 1, "used": true},
  {"id": 1, "fmt": "start, dictionary %08x", "args": 1, "used": true},
  {"id": 2, "fmt": "state idle -> run", "args": 0, "used": true},
  {"id": 3, "fmt": "adc ch %u raw %u", "args": 2, "used": true},
  {"id": 4, "fmt": "temp %d.%u C over limit %d", "args": 3, "used": true},
  {"id": 5, "fmt": "i2c nack addr 0x%02x reg 0x%02x try %u", "args": 3, "used": true},
  {"id": 6, "fmt": "motor %c speed %6d rpm", "args": 2, "used": true},
  {"id": 7, "fmt": "crc %08x len %u", "args": 2, "used": true},
  {"id": 8, "fmt": "load 100%% for %u ms", "args": 1, "used": true},
  {"id": 9, "fmt": "assert line %d: %d != %d", "args": 3, "used": true},
  {"id": 10, "fmt": "queue %-5u of %5u, delta %+d", "args": 3, "used": true},
  {"id": 11, "fmt": "pid e %d i %d d %d out %d", "args": 4, "used": true},
  {"id": 12, "fmt": "mask %#x flags %04X", "args": 2, "used": true},
  {"id": 13, "fmt": "heartbeat", "args": 0, "used": true},
  {"id": 14, "fmt": "tick %u from interrupt", "args": 1, "used": true},
  {"id": 15, "fmt": "task and interrupt write together", "args": 0, "used": true},
  {"id": 16, "fmt": "task step %u", "args": 1, "used": true},
  {"id": 17, "fmt": "done: task %u, interrupt %u", "args": 2, "used": true}
 ]
}

The script itself:

import json, os, re, sys, zlib

SERVICE = ["lost %u", "start, dictionary %08x"]          # номера 0 и 1 — служебные
ID_MAX, ARGS_MAX = 0x3FFF, 7
SKIP = r'//[^\n]*|/\*.*?\*/'                             # комментарии
LIT = r'"(?:\\.|[^"\\\n])*"'                             # строка в кавычках
TOKEN = re.compile(SKIP + '|' + LIT + r"|'(?:\\.|[^'\\\n])*'|\bDLOG_[EWID]\s*\(|[()]", re.S)
FIRST = re.compile(r'(?:\s|' + SKIP + r')*(' + LIT + ')', re.S)
CONV = re.compile(r'%(?:%|[-+ #0]*[0-9]*([diuxXc]))')    # что умеет декодер
ESC = {'n': '\n', 't': '\t', '\\': '\\', '"': '"', "'": "'"}


def count_args(fmt):
    """Сколько аргументов берёт формат; неподдержанное преобразование — ошибка."""
    n = i = 0
    while (i := fmt.find('%', i)) >= 0:
        m = CONV.match(fmt, i)
        if not m:
            raise ValueError("unsupported conversion in \"%s\"" % fmt)
        n += m.group(1) is not None
        i = m.end()
    if n > ARGS_MAX:
        raise ValueError("more than %d arguments in \"%s\"" % (ARGS_MAX, fmt))
    return n


def unquote(lit):
    """Литерал C → текст: тот, что увидит sizeof."""
    def one(m):
        if m.group(1) not in ESC:
            raise ValueError("unsupported escape \\%s" % m.group(1))
        return ESC[m.group(1)]
    return re.sub(r'\\(.)', one, lit[1:-1])


def scan(path):
    """Вызовы в одном файле: [(первая строка, последняя строка, формат)] и имя DLOG_FILE."""
    text = open(path, encoding="utf-8").read()
    name = re.search(r'^[ \t]*#[ \t]*define[ \t]+DLOG_FILE[ \t]+(\w+)', text, re.M)
    line = lambda pos: text.count("\n", 0, pos) + 1
    calls, it = [], TOKEN.finditer(text)
    for m in it:
        if not m.group().startswith("DLOG_"):
            continue
        where = "%s:%d" % (os.path.basename(path), line(m.start()))
        first = FIRST.match(text, m.end())
        if not first:
            raise ValueError("%s: format must be a string literal" % where)
        depth, end = 1, None
        for t in it:                                     # до парной закрывающей скобки
            depth += {"(": 1, ")": -1}.get(t.group(), 0)
            if depth == 0:
                end = t.start()
                break
        if end is None or not name:
            raise ValueError("%s: %s" % (where, "no DLOG_FILE in this file" if end else "unbalanced brackets"))
        calls.append((line(m.start()), line(end), unquote(first.group(1))))
    return name.group(1) if name else None, calls


def fingerprint(msgs):
    """Отпечаток словаря: CRC-32 по всем парам «номер, формат»."""
    return zlib.crc32("".join("%d\t%s\n" % (m["id"], m["fmt"]) for m in msgs).encode("utf-8"))


def dump(d):
    rows = ",\n".join("  " + json.dumps(m, ensure_ascii=False) for m in d["messages"])
    return '{\n "format": 1,\n "crc": "%s",\n "history": %s,\n "messages": [\n%s\n ]\n}\n' % (
        d["crc"], json.dumps(d["history"]), rows)


def main(dict_path, header_path, sources):
    if os.path.exists(dict_path):
        d = json.load(open(dict_path, encoding="utf-8"))
    else:
        d = {"crc": None, "history": [], "messages": [
            {"id": i, "fmt": f, "args": count_args(f), "used": True} for i, f in enumerate(SERVICE)]}
    msgs = d["messages"]
    by_fmt = {m["fmt"]: m for m in msgs}
    for m in msgs[len(SERVICE):]:
        m["used"] = False                                # отметим заново те, что встретятся
    lines, taken, new, ncalls = [], {}, 0, 0
    for path in sources:
        name, calls = scan(path)
        for first, last, fmt in calls:
            ncalls += 1
            if fmt not in by_fmt:                        # новый формат — следующий свободный номер
                by_fmt[fmt] = {"id": msgs[-1]["id"] + 1, "fmt": fmt, "args": count_args(fmt), "used": True}
                msgs.append(by_fmt[fmt])
                new += 1
            m = by_fmt[fmt]
            m["used"] = True
            if m["id"] > ID_MAX:
                raise ValueError("more than %d messages" % ID_MAX)
            for ln in sorted({first, last}):             # gcc берёт __LINE__ первой строки вызова, clang — последней
                if taken.setdefault((name, ln), fmt) != fmt:
                    raise ValueError("%s:%d: two DLOG calls on one line" % (os.path.basename(path), ln))
                lines.append("#define DLOG_H_%s_%d 0x%05Xu\n#define DLOG_L_%s_%d %d\n" % (
                    name, ln, m["id"] | m["args"] << 16, name, ln, len(fmt.encode("utf-8"))))
    crc = "0x%08x" % fingerprint(msgs)
    if d["crc"] not in (None, crc):
        d["history"].append(d["crc"])                    # прошивки со старым отпечатком словарь знает
    d["crc"] = crc
    head = "/* Создан dlog_gen.py — не править. H: номер | число аргументов << 16; L: длина формата. */\n"
    for path, body in ((dict_path, dump(d)), (header_path, head + "#define DLOG_DICT_CRC %su\n" % crc + "".join(lines))):
        if not os.path.exists(path) or open(path, encoding="utf-8").read() != body:
            open(path, "w", encoding="utf-8", newline="\n").write(body)
    used = sum(m["used"] for m in msgs) - len(SERVICE)
    print("dlog_gen: %d calls in %d files; messages: %d used, %d retired, %d new; next id %d; crc %s" % (
        ncalls, len(sources), used, len(msgs) - len(SERVICE) - used, new, msgs[-1]["id"] + 1, crc))

Four decisions in it are worth naming.

The number is bound to the text, not to the location. Lines in the file can be moved, a call can be moved to another file — the number stays. New text gets the next free number. Text that has disappeared stays in the dictionary marked "used": false, and its number is never given to anyone else. The dictionary only grows — that is why it is stored together with the sources and not created anew.

The dictionary fingerprint. crc is a CRC‑32 over all "number, text" pairs. It also gets into the firmware as the constant DLOG_DICT_CRC, and the device reports it as its first record at start-up. The decoder compares: the same dictionary, a dictionary newer than the firmware (the old fingerprint is in history), or firmware unknown to the dictionary.

What the decoder can do is what is allowed. A format with %s, %f or %lld will not pass the script: unsupported conversion in "name %s", exit code 1.

Two lines per call. If a call spans several lines, gcc puts the first one into __LINE__, and armclang the last one: a call on lines 3–5 gave 3 with gcc and 5 with armclang. The script writes names for both lines; in the run this is the call on lines 79–80 of the file main35g.c.

If the dictionary falls behind the sources. The script is run before the compiler on every build. If you forget to, the compiler itself stops the build. In the experiment one line was added at the start of app35g.c without updating the header: 12 errors of the form "DLOG_L_app35g_13 undeclared". Three lines were added — the calls landed on the lines of their neighbours, and the _Static_assert with the text dlog_ids.h is stale: run dlog_gen.py fired 11 times. This protection leaves one hole — see "Pitfalls".

The next firmware version in the experiment: one message removed, the text of another changed, one added, and all the lines of the file shifted. The script replied:

dlog_gen: 16 calls in 2 files; messages: 16 used, 2 retired, 2 new; next id 20; crc 0x1e493416

All 18 previous numbers stayed in place, two texts were marked unused, the new ones got numbers 18 and 19, and the old fingerprint 0x2c9c6546 went into history.

35г.5 The frame on the line: COBS, CRC-16 and recovery after an error

Output is the second half of the log. It takes one record from the ring, builds a frame and hands it to the dlog_out function, which the device provides.

/* CRC-16/XMODEM: полином 0x1021, начальное 0 — как в 194.4. Здесь по полбайта, с таблицей на 16 слов;
 * с ключом -DDLOG_CRC_BITWISE — побитово, как в 194.4: результат тот же, выдача кадра вдвое дольше. */
static uint16_t crc16(const uint8_t *p, uint32_t n)
{
    uint16_t c = 0;
#ifndef DLOG_CRC_BITWISE
    static const uint16_t t[16] = { 0x0000, 0x1021, 0x2042, 0x3063, 0x4084, 0x50A5, 0x60C6, 0x70E7,
                                    0x8108, 0x9129, 0xA14A, 0xB16B, 0xC18C, 0xD1AD, 0xE1CE, 0xF1EF };
    while (n--) {
        c = (uint16_t)((c << 4) ^ t[(c >> 12) ^ (*p >> 4)]);
        c = (uint16_t)((c << 4) ^ t[(c >> 12) ^ (*p++ & 15u)]);
    }
#else
    while (n--) {
        c ^= (uint16_t)(*p++ << 8);
        for (int i = 0; i < 8; i++)
            c = (c & 0x8000u) ? (uint16_t)((c << 1) ^ 0x1021u) : (uint16_t)(c << 1);
    }
#endif
    return c;
}

/* COBS: убирает нули из данных, чтобы ноль означал только «конец кадра» */
static uint32_t cobs_encode(const uint8_t *in, uint32_t n, uint8_t *out)
{
    uint32_t w = 1, code_at = 0;
    uint8_t code = 1;
    for (uint32_t i = 0; i < n; i++) {
        if (in[i] == 0) {
            out[code_at] = code;
            code_at = w++;
            code = 1;
        } else {
            out[w++] = in[i];
            if (++code == 0xFF) {
                out[code_at] = code;
                code_at = w++;
                code = 1;
            }
        }
    }
    out[code_at] = code;
    return w;
}

/* Кадр: номер и уровень (2 байта), счётчик кадров, слова w[0..nw-1] младшим байтом вперёд,
 * CRC-16 старшим байтом вперёд; всё это через COBS и ноль в конце. */
static void frame_out(uint32_t idlvl, const uint32_t *w, uint32_t nw)
{
    uint8_t raw[FRAME_MAX], enc[FRAME_MAX + 2];
    uint32_t k = 0;
    raw[k++] = (uint8_t)idlvl;
    raw[k++] = (uint8_t)(idlvl >> 8);
    raw[k++] = L.seq++;
    for (uint32_t i = 0; i < nw; i++)
        for (uint32_t sh = 0; sh < 32; sh += 8)
            raw[k++] = (uint8_t)(w[i] >> sh);
    uint16_t c = crc16(raw, k);
    raw[k++] = (uint8_t)(c >> 8);
    raw[k++] = (uint8_t)c;
    k = cobs_encode(raw, k, enc);
    enc[k++] = 0;                        /* конец кадра */
    dlog_out(enc, k);
}

int dlog_drain(void)
{
    uint32_t rec[2 + DLOG_MAXARGS], n = 0, lost;
    uint32_t key = dlog_lock();
    if (L.tail != L.head) {
        n = DLOG_NARG(L.ring[L.tail & MASK]) + 2u;
        for (uint32_t i = 0; i < n; i++)
            rec[i] = L.ring[(L.tail + i) & MASK];
        L.tail += n;
        lost = DLOG_LOST(rec[0]);
    } else {                             /* пусто; отброшенные после последней записи — сообщить сейчас */
        lost = L.pending;
        L.pending = 0;
    }
    dlog_unlock(key);                    /* дальше — без запрета прерываний */
    if (lost) {                          /* метка потери: время записи, один аргумент — счёт */
        uint32_t m[2] = { n ? rec[1] : dlog_now(), lost };
        frame_out(DLOG_ID_LOST | (DLOG_WARN << 14), m, 2);
    }
    if (n)
        frame_out(rec[0] & 0xFFFFu, rec + 1, n - 1u);
    return n || lost;                    /* 0 — выдавать было нечего */
}

The frame is the same as in 194.4: data, CRC‑16/XMODEM with the high byte first, COBS, zero. COBS removes zeros from the data, and a zero on the line means only one thing: the end of a frame. cobs_encode is the same as in 194, only the type of the counters differs. Interrupts are disabled only while the record is being copied from the ring — from 30 to 58 instructions; CRC, COBS and output run with them enabled.

The CRC was bitwise at first, as in 194.4. Counting instructions showed the cost: with it output was almost twice as long. It was replaced by a table of 16 words — two steps per byte instead of eight. The result is the same: the stream of 5000 messages with both versions matched byte for byte.

The table cost 56 bytes of code: 1616 versus 1560. The count includes writing the bytes to the UART register by polling; in QEMU the transmitter is always free, so waiting for the line is not included.

At start-up the device first of all sends a single zero and the start-up record:

void dlog_init(uint32_t level, uint32_t drop_old)
{
    static const uint8_t zero = 0;
    L.head = L.tail = DLOG_T0;
    L.pending = 0;
    L.seq = 0;
    L.level = (uint8_t)level;
    L.drop_old = (uint8_t)drop_old;
    dlog_out(&zero, 1);                  /* закрыть то, что осталось в линии до запуска */
    dlog_put(DLOG_ID_START | (1u << 16), DLOG_DICT_CRC);
}

The zero closes off any garbage that may have been left on the line from a previous life; an empty frame is skipped by the decoder. The start-up record carries the dictionary fingerprint.

What happens if the line corrupts bytes. A stream of 5001 frames (96796 bytes) was corrupted in six ways and given to the decoder:

The main column is the last one: not a single corrupted record turned into a plausible line. A frame is either accepted and correct, or rejected — by an impossible COBS code, by a length not equal to 9 + 4·n, or by the CRC. From the next zero, reception is in order again.

How much one corruption costs was shown by 1200 separate trials on a stream of 301 frames. An inserted byte always cost one frame — 400 of 400. A removed byte cost one frame in 382 trials and two in 18: if the delimiter itself was lost, two frames stick together and both fail. A flipped bit cost one in 380 trials and two in 20, for the same reason.

The frame counter — the third byte — is needed so that the computer knows about a loss rather than guessing. The decoder compares it with the expected value and writes into the log how many frames did not arrive: in all four corruption experiments the sum over these notes equals the number of lost frames. The loss of the very first frame after connecting and of the very last one is not shown by the counter — there is nothing to compare with; this is visible in the two bottom rows of the table.

35г.6 The decoder, old firmware and a comparison with printf

The decoder does the reverse path: it cuts the stream at the zeros, removes COBS, checks the length and the CRC, finds the format by the number and prints.

import json, re, struct, sys

LEVELS = "EWID"
ID_LOST, ID_START = 0, 1
CONV = re.compile(r'%(?:%|([-+ #0]*)([0-9]*)([diuxXc]))')


def crc16(data):
    """CRC-16/XMODEM: полином 0x1021, начальное 0 — как в прошивке."""
    c = 0
    for b in data:
        c ^= b << 8
        for _ in range(8):
            c = ((c << 1) ^ 0x1021 if c & 0x8000 else c << 1) & 0xFFFF
    return c


def cobs_decode(enc):
    """Обратное COBS; None — если код блока выводит за конец кадра."""
    out, r = bytearray(), 0
    while r < len(enc):
        code = enc[r]
        if r + code > len(enc):
            return None
        out += enc[r + 1:r + code]
        r += code
        if code != 0xFF and r < len(enc):
            out.append(0)
    return bytes(out)


def c_format(fmt, args):
    """printf для слов по 32 бита: d i u x X c, флаги - + пробел # 0, ширина."""
    it = iter(args)

    def one(m):
        if m.group(3) is None:
            return "%"
        flags, conv, v = m.group(1), m.group(3), next(it)
        if conv in "di":
            v -= (v & 0x80000000) << 1                   # слово как число со знаком
        if conv == "c":
            return ("%" + flags.replace("0", "") + m.group(2) + "c") % chr(v & 0xFF)
        if conv in "xX" and v == 0:
            flags = flags.replace("#", "")               # в C «%#x» от нуля — просто 0
        return ("%" + flags + m.group(2) + conv.replace("u", "d")) % v
    return CONV.sub(one, fmt)


class Decoder:
    def __init__(self, dictionary):
        self.msgs = {m["id"]: m for m in dictionary["messages"]}
        self.known = {dictionary["crc"]: "same"}
        self.known.update((c, "older firmware") for c in dictionary["history"])
        self.buf = bytearray()
        self.seq = None                                  # счётчик следующего кадра; None — ещё не знаем
        self.st = dict(frames=0, empty=0, bad_cobs=0, bad_len=0, bad_crc=0, gaps=0, missed=0,
                       unknown=0, mismatch=0, device_lost=0, starts=0)

    def feed(self, data):
        """Принять кусок потока; вернуть готовые строки."""
        lines = []
        for b in data:
            if b:
                self.buf.append(b)
                continue
            frame, self.buf = bytes(self.buf), bytearray()       # ноль — конец кадра
            if not frame:
                self.st["empty"] += 1                    # два нуля подряд: пустой кадр, не ошибка
                continue
            line = self.frame(frame, lines)
            if line:
                lines.append(line)
        return lines

    def frame(self, enc, lines):
        st = self.st
        raw = cobs_decode(enc)
        if raw is None:
            st["bad_cobs"] += 1
        elif len(raw) < 9 or len(raw) > 37 or (len(raw) - 9) % 4:
            st["bad_len"] += 1
        elif crc16(raw[:-2]) != raw[-2] << 8 | raw[-1]:
            st["bad_crc"] += 1
        else:
            st["frames"] += 1
            idlvl, seq = struct.unpack_from("<HB", raw)
            t, *args = struct.unpack_from("<%dI" % ((len(raw) - 5) // 4), raw, 3)
            mid, lvl = idlvl & 0x3FFF, LEVELS[idlvl >> 14]
            if mid == ID_START and len(args) == 1:       # прибор запустился: счётчик кадров с нуля
                st["starts"] += 1
                self.seq = 0
            if self.seq is not None and seq != self.seq:
                n = (seq - self.seq) & 0xFF              # сколько кадров не дошло (по модулю 256)
                st["gaps"] += 1
                st["missed"] += n
                lines.append("-- line: %d frame(s) missing" % n)
            self.seq = (seq + 1) & 0xFF
            m = self.msgs.get(mid)
            if m is None:                                # формата нет в словаре: аргументы — как есть
                st["unknown"] += 1
                return "%u %s ?id=%u" % (t, lvl, mid) + "".join(" %08x" % a for a in args)
            if m["args"] != len(args):                   # словарь не от этой прошивки
                st["mismatch"] += 1
                return "%u %s ?id=%u wants %u args:" % (t, lvl, mid, m["args"]) + "".join(" %08x" % a for a in args)
            text = c_format(m["fmt"], args)
            if mid == ID_LOST:
                st["device_lost"] += args[0]
            if mid == ID_START:
                text += " (%s)" % self.known.get("0x%08x" % args[0], "unknown to this dictionary")
            return "%u %s %s" % (t, lvl, text)
        return None

The formatting is its own, without C's printf at hand, so the main experiment of the section is the check. The test program on the computer writes every event twice: to the binary log and with an ordinary printf to a file. There are 5000 events, twelve kinds of messages, the arguments are random signed numbers from 1 to 30 bits wide. The decoder produced 5000 lines, and all 5000 matched printf verbatim — with field width, leading zeros, the + sign, left alignment and %#x. On the last one the decoder would have stumbled at first: Python prints %#x of zero as 0x0, while C prints 0; there are 14 such cases in the stream.

Compatibility with old firmware. Devices in the field live longer than a firmware version. All combinations of the two versions from 35г.4 were tested:

The new dictionary reads the old log without a single error: the removed texts have not gone anywhere. The old dictionary with the new firmware decodes everything it knows, and shows what it does not know honestly — the number and the raw arguments:

10929 I ?id=18 00000044 ff55fe85 ffffb303

Parsing does not break because of this: the decoder knows the argument count from the frame length, not from the dictionary.

Comparison with printf. For the comparison the same test firmware was built a second time: the -include tlog35g.h option substitutes the sink, and the same DLOG_x calls go to a function that builds a string with vsnprintf from newlib-nano and immediately outputs it.

static int head(char *p, unsigned room, const char *fmt, ...)    /* начало строки — тем же vsnprintf */
{
    va_list ap;
    va_start(ap, fmt);
    int n = vsnprintf(p, room, fmt, ap);
    va_end(ap);
    return n;
}

void tlog(unsigned lvl, const char *fmt, ...)
{
    char line[96];
    va_list ap;
    if (lvl > level)
        return;
    int n = head(line, sizeof(line) - 1u, "%u %c ", (unsigned)dlog_now(), "EWID"[lvl]);
    va_start(ap, fmt);
    n += vsnprintf(line + n, sizeof(line) - 1u - (unsigned)n, fmt, ap);
    va_end(ap);
    if (n > (int)sizeof(line) - 2)
        n = (int)sizeof(line) - 2;               /* строка не влезла — обрезана */
    line[n++] = '\n';
    dlog_out((const uint8_t *)line, (uint32_t)n);
}

Both firmware variants in QEMU produced the same 203 messages of the first two steps: the decoder's lines matched the text firmware's lines, every single one.

Size (Cortex‑M3, -Os, all levels enabled):

The image is 3.2 times smaller. The log core is 776 bytes: dlog_put 272, frame_out together with CRC and COBS 260, dlog_drain 148, dlog_init 64, the CRC table 32. In the text variant _printf_i (680 bytes), _svfprintf_r (556) and _printf_common (294) alone take more. The twelve format strings are 271 bytes with their terminating zeros; in the binary log their place is taken by twelve numbers. For Cortex‑M4 the picture is the same: 1604 versus 5116 bytes of code. The binary log pays with RAM: a ring of 256 words is 1024 bytes, the whole structure 1040. In the text variant data and bss together are 128 bytes, plus a 96-byte line buffer on the stack; the stack of vsnprintf itself was not measured here.

Bytes on the line (5000 messages on the computer):

The gain is 1.86 times, and it depends on the message. heartbeat is 11 bytes instead of 19.8 on average, pid e %d i %d d %d out %d is 27 instead of 49.9. But adc ch %u raw %u with small numbers is 19 bytes versus 27.6: a four-byte argument saves nothing on a one-digit number. At 115200 baud with 10 bits per byte the average frame occupies the line for 1.7 ms, the average text line for 3.1 ms.

Instructions (gdb, step by step; for the text variant — from entry into tlog to return, including output):

In total the binary log spends 2.6–2.9 times fewer instructions. But the first column matters more. Where the message originates — in an interrupt, in a control loop — the program pays 60–93 instructions instead of 1450–3322, 24–36 times less. The rest is finished by the background loop when it suits it.

This is an instruction count, not time: QEMU does not count clock cycles, and the log was not run on a board. Waiting for the UART transmitter is not included in either variant.

35г.7 Pitfalls

The log is decoded, but the text is wrong. The dictionary was created anew from the new sources instead of continuing the old one. The numbers were handed out in order, and two of them went to other texts. The old log with such a dictionary: 4162 lines correct, 405 flagged by the decoder itself — the dictionary expects a different argument count — and 433 came out plausible and wrong:

16811 I fan pwm 46339%   <- printf: 16811 I load 100% for 46339 ms

The dictionary is a source file just like the code: it lives in version control, and dlog_gen.py only adds to it. The first line of the log warns about a substitution: unknown to this dictionary.

The text was edited, the length is the same, the script was not run. raw was replaced with val in adc ch %u raw %u — the compiler stayed silent: the name by line number is in place, and the length matches. The decoder will show the old text. _Static_assert catches shifted lines, but not such an edit. That is why dlog_gen.py is a build step before the compiler, not a command that you have to remember.

Two calls on one line. The name is built from the line number, and two calls would get the same one. The script stops: two DLOG calls on one line.

The action vanished together with the level. Arguments of a disabled level are not evaluated (35г.2): next_sample() in the experiment was called 0 times instead of 10. Counters, register reads that clear a flag, i++ are not put into log arguments.

A text message from an interrupt tears a task's line. In the text variant of the test firmware 24 lines out of 471 were damaged this way. The binary log outputs only from the background loop, and in an interrupt it only puts words into the ring.

Losses are not visible. A log without a loss counter lies silently: looking at the log it seems that nothing happened between two records. Here the count is kept at two levels. What was lost in the device is shown by the lost N marker, what was lost on the line by the frame counter.

The frame counter is one byte. A gap is counted modulo 256: if exactly 256 frames in a row are lost, the decoder will not notice. And it does not see the loss of the last frame before silence — until the next one arrives.

The background loop stands still while a frame is being sent. dlog_out in the test firmware waits for the transmitter by polling. A 19-byte frame at 115200 baud takes 1.65 ms. If the loop cannot afford to wait that long, dlog_out should only put bytes into the transmitter queue, and the sending should be done by an interrupt or DMA (section 16).

An argument wider than 32 bits. The ring holds 32-bit words. long long and double will not get there: the script will not accept %lld and %f, and the compiler will not accept such an argument for %d — -Werror=format is enabled for a reason.

35г.8 Summary

• A log record is the message number, the time and the raw arguments as 32-bit words; the format string stays on the computer, in the dictionary. On the line a message takes 11 + 4·n bytes.
• Levels are cut off at build time by the DLOG_BUILD macro: a disabled call is sizeof of a declared function, and nothing of it remains in the image (2 bytes instead of 244 for twelve calls), yet the compiler still checks the format. The second threshold is at run time.
• dlog_put takes from 60 to 93 instructions, from 43 to 76 of them with interrupts disabled; it can be called from an interrupt. Encoding and output are in dlog_drain from the background loop: from 442 to 1186 instructions per frame.
• The ring is 256 words; on overflow either new or old records are lost, as you choose, and the number lost goes into the log as a lost N marker: in the experiment 3127 + 1874 and 3137 + 1864 give the same 5001.
• Numbers are assigned by dlog_gen.py: a number is bound to the text, the dictionary only grows, removed texts remain. The new dictionary reads the log of the old firmware: 5000 lines of 5000.
• The frame is COBS and CRC‑16, as in 194. After corruption on the line not a single wrong line; one corruption costs one frame, less often two.
• Versus vsnprintf from newlib-nano on Cortex‑M3: an image of 1620 bytes instead of 5124, 19.4 bytes per message on the line instead of 36.0, at the call site 60–93 instructions instead of 1450–3322. The price is 1040 bytes of RAM for the ring, and a dictionary on the computer without which the log cannot be read.

Full source code

dlog35g.h — the log interface: levels, the DLOG_E/W/I/D macros, writing to the ring.

/* Раздел 35г: журнал на приборе. В кольцо в ОЗУ ложатся номер сообщения, метка времени
 * и сырые аргументы; строки формата остаются на компьютере, в словаре dlog_dict.json.
 * Номера выдаёт dlog_gen.py: он обходит исходники и пишет dlog_ids.h. */
#ifndef DLOG35G_H
#define DLOG35G_H
#include <stdint.h>
#include "dlog_ids.h"

#define DLOG_ERR   0u                    /* уровни: чем больше число, тем подробнее */
#define DLOG_WARN  1u
#define DLOG_INFO  2u
#define DLOG_DBG   3u

#ifndef DLOG_BUILD
#define DLOG_BUILD 4                     /* сколько уровней попадает в образ: 0 — ни одного, 4 — все */
#endif
#ifndef DLOG_WORDS
#define DLOG_WORDS 256u                  /* кольцо, в словах по 4 байта; степень двойки */
#endif
#define DLOG_MAXARGS 7u

/* Заголовок записи в кольце — одно слово. Младшие 16 бит уходят в линию как есть. */
#define DLOG_ID(h)    ((h) & 0x3FFFu)            /* биты 13:0  — номер сообщения */
#define DLOG_LVL(h)   (((h) >> 14) & 3u)         /* биты 15:14 — уровень */
#define DLOG_NARG(h)  (((h) >> 16) & 7u)         /* биты 18:16 — число аргументов */
#define DLOG_LOST(h)  ((h) >> 19)                /* биты 31:19 — сколько записей потеряно перед этой */
#define DLOG_LOST_MAX 0x1FFFu                    /* 8191 значит «не меньше 8191» */
#define DLOG_ID_LOST  0u                         /* служебные номера: метка потери … */
#define DLOG_ID_START 1u                         /* … и метка запуска с отпечатком словаря */

void dlog_init(uint32_t level, uint32_t drop_old);   /* drop_old: 0 — терять новые, 1 — старые */
void dlog_set_level(uint32_t level);                 /* порог на ходу: DLOG_ERR … DLOG_DBG */
void dlog_put(uint32_t hdr, ...);                    /* из задачи и из прерывания */
int dlog_drain(void);                                /* из фонового цикла: одна запись → один кадр */

uint32_t dlog_now(void);                             /* даёт прибор: метка времени */
void dlog_out(const uint8_t *p, uint32_t n);         /* даёт прибор: байты в линию */

/* Только объявление: компилятор сверяет формат с аргументами, кода и строки в образе нет. */
int dlog_fmt_check(const char *fmt, ...) __attribute__((format(printf, 1, 2)));

#define DLOG_CAT_(a, b, c) a##b##_##c
#define DLOG_CAT(a, b, c) DLOG_CAT_(a, b, c)
#define DLOG_HERE(prefix) DLOG_CAT(prefix, DLOG_FILE, __LINE__)   /* DLOG_H_app35g_27 */

#ifndef DLOG_SINK                        /* стенд подменяет приёмник, чтобы сравнить с printf */
#define DLOG_SINK(lvl, fmt, ...) dlog_put(DLOG_HERE(DLOG_H_) | ((lvl) << 14), ##__VA_ARGS__)
#endif

#define DLOG_OFF(fmt, ...) ((void)sizeof(dlog_fmt_check(fmt, ##__VA_ARGS__)))
#define DLOG_ON(lvl, fmt, ...)                                                                  \
    do {                                                                                        \
        _Static_assert(sizeof(fmt) - 1 == DLOG_HERE(DLOG_L_), "dlog_ids.h is stale: run dlog_gen.py"); \
        DLOG_OFF(fmt, ##__VA_ARGS__);                                                           \
        DLOG_SINK(lvl, fmt, ##__VA_ARGS__);                                                     \
    } while (0)

#if DLOG_BUILD > 0
#define DLOG_E(fmt, ...) DLOG_ON(DLOG_ERR, fmt, ##__VA_ARGS__)
#else
#define DLOG_E(fmt, ...) DLOG_OFF(fmt, ##__VA_ARGS__)
#endif
#if DLOG_BUILD > 1
#define DLOG_W(fmt, ...) DLOG_ON(DLOG_WARN, fmt, ##__VA_ARGS__)
#else
#define DLOG_W(fmt, ...) DLOG_OFF(fmt, ##__VA_ARGS__)
#endif
#if DLOG_BUILD > 2
#define DLOG_I(fmt, ...) DLOG_ON(DLOG_INFO, fmt, ##__VA_ARGS__)
#else
#define DLOG_I(fmt, ...) DLOG_OFF(fmt, ##__VA_ARGS__)
#endif
#if DLOG_BUILD > 3
#define DLOG_D(fmt, ...) DLOG_ON(DLOG_DBG, fmt, ##__VA_ARGS__)
#else
#define DLOG_D(fmt, ...) DLOG_OFF(fmt, ##__VA_ARGS__)
#endif

#endif

dlog35g.c — the ring of records in RAM and output in COBS + CRC-16 frames.

/* Раздел 35г: журнал на приборе — кольцо записей в ОЗУ и выдача кадрами COBS + CRC-16.
 * Запись (dlog_put) коротка и годится для прерывания; кодирование и линия — в dlog_drain,
 * которую зовёт фоновый цикл. Кадр тот же, что в разделе 194: данные + CRC → COBS → 0x00. */
#include <stdarg.h>
#include "dlog35g.h"

#define MASK (DLOG_WORDS - 1u)
#define FRAME_MAX (9u + 4u * DLOG_MAXARGS)       /* номер 2, счётчик 1, время 4, аргументы, CRC 2 */
#ifndef DLOG_T0
#define DLOG_T0 0u                               /* откуда стартуют счётчики слов; иное — только для опыта */
#endif

_Static_assert((DLOG_WORDS & MASK) == 0 && DLOG_WORDS >= 32, "DLOG_WORDS: power of two, at least 32");

static struct {
    uint32_t ring[DLOG_WORDS];
    uint32_t head;                       /* слов записано за всё время; двигает только dlog_put */
    uint32_t tail;                       /* слов прочитано или выброшено */
    uint32_t pending;                    /* записей отброшено после последней принятой */
    uint8_t level;                       /* порог на ходу */
    uint8_t drop_old;                    /* 0 — терять новые, 1 — терять старые */
    uint8_t seq;                         /* счётчик кадров в линии */
} L;

#if defined(__arm__)
static inline uint32_t dlog_lock(void)
{
    uint32_t key;
    __asm volatile("mrs %0, primask\n"
                   "cpsid i" : "=r"(key) :: "memory");
    return key;
}

static inline void dlog_unlock(uint32_t key)
{
    __asm volatile("msr primask, %0" :: "r"(key) : "memory");
}
#else                                    /* на компьютере писатель один */
static inline uint32_t dlog_lock(void)
{
    return 0;
}

static inline void dlog_unlock(uint32_t key)
{
    (void)key;
}
#endif

static uint32_t add_lost(uint32_t hdr, uint32_t n)
{
    uint32_t v = DLOG_LOST(hdr) + n;
    if (v > DLOG_LOST_MAX)
        v = DLOG_LOST_MAX;
    return (hdr & 0x7FFFFu) | (v << 19);
}

void dlog_put(uint32_t hdr, ...)
{
    uint32_t n = DLOG_NARG(hdr), lost = 0;
    va_list ap;
    if (DLOG_LVL(hdr) > L.level)
        return;                          /* уровень выключен на ходу */
    va_start(ap, hdr);
    uint32_t key = dlog_lock();
    while (DLOG_WORDS - (L.head - L.tail) < n + 2u) {
        if (!L.drop_old) {               /* терять новые: запись не берём, только считаем */
            L.pending++;
            goto out;
        }
        uint32_t old = L.ring[L.tail & MASK];    /* терять старые: выбросить самую старую */
        L.tail += DLOG_NARG(old) + 2u;
        lost += DLOG_LOST(old) + 1u;
    }
    if (lost)                            /* новая самая старая несёт счёт: «передо мной потеряно» */
        L.ring[L.tail & MASK] = add_lost(L.ring[L.tail & MASK], lost);
    uint32_t w = L.head;
    L.ring[w++ & MASK] = add_lost(hdr, L.pending);
    L.pending = 0;
    L.ring[w++ & MASK] = dlog_now();
    while (n--)
        L.ring[w++ & MASK] = va_arg(ap, uint32_t);
    L.head = w;                          /* запись видна читателю только целиком */
out:
    dlog_unlock(key);
    va_end(ap);
}

/* CRC-16/XMODEM: полином 0x1021, начальное 0 — как в 194.4. Здесь по полбайта, с таблицей на 16 слов;
 * с ключом -DDLOG_CRC_BITWISE — побитово, как в 194.4: результат тот же, выдача кадра вдвое дольше. */
static uint16_t crc16(const uint8_t *p, uint32_t n)
{
    uint16_t c = 0;
#ifndef DLOG_CRC_BITWISE
    static const uint16_t t[16] = { 0x0000, 0x1021, 0x2042, 0x3063, 0x4084, 0x50A5, 0x60C6, 0x70E7,
                                    0x8108, 0x9129, 0xA14A, 0xB16B, 0xC18C, 0xD1AD, 0xE1CE, 0xF1EF };
    while (n--) {
        c = (uint16_t)((c << 4) ^ t[(c >> 12) ^ (*p >> 4)]);
        c = (uint16_t)((c << 4) ^ t[(c >> 12) ^ (*p++ & 15u)]);
    }
#else
    while (n--) {
        c ^= (uint16_t)(*p++ << 8);
        for (int i = 0; i < 8; i++)
            c = (c & 0x8000u) ? (uint16_t)((c << 1) ^ 0x1021u) : (uint16_t)(c << 1);
    }
#endif
    return c;
}

/* COBS: убирает нули из данных, чтобы ноль означал только «конец кадра» */
static uint32_t cobs_encode(const uint8_t *in, uint32_t n, uint8_t *out)
{
    uint32_t w = 1, code_at = 0;
    uint8_t code = 1;
    for (uint32_t i = 0; i < n; i++) {
        if (in[i] == 0) {
            out[code_at] = code;
            code_at = w++;
            code = 1;
        } else {
            out[w++] = in[i];
            if (++code == 0xFF) {
                out[code_at] = code;
                code_at = w++;
                code = 1;
            }
        }
    }
    out[code_at] = code;
    return w;
}

/* Кадр: номер и уровень (2 байта), счётчик кадров, слова w[0..nw-1] младшим байтом вперёд,
 * CRC-16 старшим байтом вперёд; всё это через COBS и ноль в конце. */
static void frame_out(uint32_t idlvl, const uint32_t *w, uint32_t nw)
{
    uint8_t raw[FRAME_MAX], enc[FRAME_MAX + 2];
    uint32_t k = 0;
    raw[k++] = (uint8_t)idlvl;
    raw[k++] = (uint8_t)(idlvl >> 8);
    raw[k++] = L.seq++;
    for (uint32_t i = 0; i < nw; i++)
        for (uint32_t sh = 0; sh < 32; sh += 8)
            raw[k++] = (uint8_t)(w[i] >> sh);
    uint16_t c = crc16(raw, k);
    raw[k++] = (uint8_t)(c >> 8);
    raw[k++] = (uint8_t)c;
    k = cobs_encode(raw, k, enc);
    enc[k++] = 0;                        /* конец кадра */
    dlog_out(enc, k);
}

int dlog_drain(void)
{
    uint32_t rec[2 + DLOG_MAXARGS], n = 0, lost;
    uint32_t key = dlog_lock();
    if (L.tail != L.head) {
        n = DLOG_NARG(L.ring[L.tail & MASK]) + 2u;
        for (uint32_t i = 0; i < n; i++)
            rec[i] = L.ring[(L.tail + i) & MASK];
        L.tail += n;
        lost = DLOG_LOST(rec[0]);
    } else {                             /* пусто; отброшенные после последней записи — сообщить сейчас */
        lost = L.pending;
        L.pending = 0;
    }
    dlog_unlock(key);                    /* дальше — без запрета прерываний */
    if (lost) {                          /* метка потери: время записи, один аргумент — счёт */
        uint32_t m[2] = { n ? rec[1] : dlog_now(), lost };
        frame_out(DLOG_ID_LOST | (DLOG_WARN << 14), m, 2);
    }
    if (n)
        frame_out(rec[0] & 0xFFFFu, rec + 1, n - 1u);
    return n || lost;                    /* 0 — выдавать было нечего */
}

void dlog_set_level(uint32_t level)
{
    L.level = (uint8_t)level;
}

void dlog_init(uint32_t level, uint32_t drop_old)
{
    static const uint8_t zero = 0;
    L.head = L.tail = DLOG_T0;
    L.pending = 0;
    L.seq = 0;
    L.level = (uint8_t)level;
    L.drop_old = (uint8_t)drop_old;
    dlog_out(&zero, 1);                  /* закрыть то, что осталось в линии до запуска */
    dlog_put(DLOG_ID_START | (1u << 16), DLOG_DICT_CRC);
}

main35g.c — the test firmware for QEMU in two variants: binary and text log.

/* Раздел 35г: прошивка-стенд для QEMU. Один и тот же файл собирается в двух вариантах:
 * с dlog35g.c — двоичный журнал, с tlog35g.c и ключом -include tlog35g.h — текстовый.
 * Шаг 1: три сообщения для счёта команд. Шаг 2: 200 случайных событий, время — счётчик.
 * Шаг 3: задача и прерывание SysTick пишут в журнал вперемешку. */
#define DLOG_FILE main35g
#include "dlog35g.h"
#include "app35g.h"
#include "regs35g.h"
#include "rnd35g.h"

#define TASK_STEPS 300u

static volatile uint32_t now_ms, ticks;

uint32_t dlog_now(void)
{
    return now_ms;
}

void dlog_out(const uint8_t *p, uint32_t n)      /* байты в USART1, по опросу */
{
    while (n--) {
        while (!(USART1_SR & USART_SR_TXE)) {
        }
        USART1_DR = *p++;
    }
}

void SysTick_Handler(void)
{
    now_ms++;
    ticks++;
    DLOG_W("tick %u from interrupt", (unsigned)ticks);
}

static void drain_all(void)
{
    while (dlog_drain()) {
    }
}

static void qemu_exit(void)                      /* semihosting SYS_EXIT: закрыть QEMU (раздел 35а) */
{
    register uint32_t r0 __asm("r0") = 0x18u;
    register uint32_t r1 __asm("r1") = 0x20026u;
    __asm volatile("bkpt 0xAB" : : "r"(r0), "r"(r1) : "memory");
}

int main(void)
{
    RCC_APB2ENR |= USART1_EN;
    USART1_BRR = BRR_115200;
    USART1_CR1 = (1u << 13) | (1u << 3);         /* UE, TE */
    dlog_init(DLOG_DBG, 0);

    now_ms = 250u;
    app_event(0, 0, 0, 0);                       /* ЗАМЕР: без аргументов */
    app_event(1, 5, 1234, 0);                    /* ЗАМЕР: два аргумента */
    app_event(9, -12, 3400, -7);                 /* ЗАМЕР: четыре аргумента */
    drain_all();

    for (unsigned i = 0; i < 200u; i++) {
        now_ms += 1u + rnd() % 2000u;
        unsigned kind = rnd() % APP_KINDS;
        int a = rnd_val(), b = rnd_val(), c = rnd_val();
        app_event(kind, a, b, c);
        drain_all();
    }

    DLOG_I("task and interrupt write together");
    SYST_RVR = TICK_RELOAD - 1u;
    SYST_CVR = 0;
    SYST_CSR = 7u;                               /* такт ядра, прерывание, включён */
    for (unsigned i = 0; i < TASK_STEPS; i++) {
        DLOG_I("task step %u", i);
        dlog_drain();                            /* фоновый цикл: по одной записи за проход */
    }
    SYST_CSR = 0;
    DLOG_I("done: task %u, interrupt %u",
           TASK_STEPS, (unsigned)ticks);
    drain_all();
    qemu_exit();
    for (;;) {
    }
}

tlog35g.c — the variant for comparison: the same device writes its log as text through snprintf.

/* Раздел 35г: вариант для сравнения — тот же прибор пишет журнал текстом. Строка собирается
 * snprintf из newlib-nano и сразу уходит в линию; кольца и отложенной выдачи нет. */
#include <stdarg.h>
#include <stdio.h>
#include "dlog35g.h"
#include "tlog35g.h"

static uint8_t level;

static int head(char *p, unsigned room, const char *fmt, ...)    /* начало строки — тем же vsnprintf */
{
    va_list ap;
    va_start(ap, fmt);
    int n = vsnprintf(p, room, fmt, ap);
    va_end(ap);
    return n;
}

void tlog(unsigned lvl, const char *fmt, ...)
{
    char line[96];
    va_list ap;
    if (lvl > level)
        return;
    int n = head(line, sizeof(line) - 1u, "%u %c ", (unsigned)dlog_now(), "EWID"[lvl]);
    va_start(ap, fmt);
    n += vsnprintf(line + n, sizeof(line) - 1u - (unsigned)n, fmt, ap);
    va_end(ap);
    if (n > (int)sizeof(line) - 2)
        n = (int)sizeof(line) - 2;               /* строка не влезла — обрезана */
    line[n++] = '\n';
    dlog_out((const uint8_t *)line, (uint32_t)n);
}

void dlog_init(uint32_t lvl, uint32_t drop_old)
{
    (void)drop_old;
    level = (uint8_t)lvl;
}

int dlog_drain(void)
{
    return 0;                                    /* выдавать нечего: всё уже ушло */
}

void *_sbrk(int incr)                            /* куча не нужна: snprintf пишет в свой буфер */
{
    (void)incr;
    return (void *)-1;
}

app35g.c — the "device" for the experiments: twelve messages of different levels and formats.

/* Раздел 35г: «прибор» для опытов. Двенадцать сообщений: четыре уровня, от нуля до четырёх
 * аргументов, знаковые и беззнаковые, ширина, нули слева, символ и знак процента.
 * Один и тот же файл собирается для компьютера и для Cortex-M. */
#define DLOG_FILE app35g
#include "dlog35g.h"
#include "app35g.h"

void app_event(unsigned kind, int a, int b, int c)
{
    switch (kind % APP_KINDS) {
    case 0:
        DLOG_I("state idle -> run");
        break;
    case 1:
        DLOG_D("adc ch %u raw %u", (unsigned)a & 15u, (unsigned)b & 4095u);
        break;
    case 2:
        DLOG_W("temp %d.%u C over limit %d", a / 10, (unsigned)(a < 0 ? -a : a) % 10u, b);
        break;
    case 3:
        DLOG_E("i2c nack addr 0x%02x reg 0x%02x try %u", (unsigned)a & 0x7Fu, (unsigned)b & 0xFFu, (unsigned)c & 7u);
        break;
    case 4:
        DLOG_I("motor %c speed %6d rpm", 'A' + (a & 3), b);
        break;
    case 5:
        DLOG_D("crc %08x len %u", (unsigned)a, (unsigned)b);
        break;
    case 6:
        DLOG_I("load 100%% for %u ms", (unsigned)c % 60000u);
        break;
    case 7:
        DLOG_E("assert line %d: %d != %d", a & 0xFFF, b, c);
        break;
    case 8:
        DLOG_W("queue %-5u of %5u, delta %+d", (unsigned)a & 1023u, (unsigned)b & 1023u, c);
        break;
    case 9:
        DLOG_D("pid e %d i %d d %d out %d", a, b, c, a + b);
        break;
    case 10:
        DLOG_I("mask %#x flags %04X", (unsigned)a & 0xFFu, (unsigned)b & 0xFFFFu);
        break;
    default:
        DLOG_D("heartbeat");
        break;
    }
}

app35g_v2.c — the next version of the same "device" — for the dictionary experiment.

/* Раздел 35г: тот же «прибор», следующая версия прошивки — для опыта со словарём.
 * Изменено: сообщение «load 100%…» удалено, у «motor…» другой текст и третий аргумент,
 * добавлено «fan pwm…»; из-за этого комментария все строки ещё и сдвинулись.
 * Номера остальных сообщений должны остаться прежними. */
#define DLOG_FILE app35g
#include "dlog35g.h"
#include "app35g.h"

void app_event(unsigned kind, int a, int b, int c)
{
    switch (kind % APP_KINDS) {
    case 0:
        DLOG_I("state idle -> run");
        break;
    case 1:
        DLOG_D("adc ch %u raw %u", (unsigned)a & 15u, (unsigned)b & 4095u);
        break;
    case 2:
        DLOG_W("temp %d.%u C over limit %d", a / 10, (unsigned)(a < 0 ? -a : a) % 10u, b);
        break;
    case 3:
        DLOG_E("i2c nack addr 0x%02x reg 0x%02x try %u", (unsigned)a & 0x7Fu, (unsigned)b & 0xFFu, (unsigned)c & 7u);
        break;
    case 4:
        DLOG_I("motor %c speed %d rpm, torque %d", 'A' + (a & 3), b, c);
        break;
    case 5:
        DLOG_D("crc %08x len %u", (unsigned)a, (unsigned)b);
        break;
    case 6:
        DLOG_I("fan pwm %u%%", (unsigned)c % 101u);
        break;
    case 7:
        DLOG_E("assert line %d: %d != %d", a & 0xFFF, b, c);
        break;
    case 8:
        DLOG_W("queue %-5u of %5u, delta %+d", (unsigned)a & 1023u, (unsigned)b & 1023u, c);
        break;
    case 9:
        DLOG_D("pid e %d i %d d %d out %d", a, b, c, a + b);
        break;
    case 10:
        DLOG_I("mask %#x flags %04X", (unsigned)a & 0xFFu, (unsigned)b & 0xFFFFu);
        break;
    default:
        DLOG_D("heartbeat");
        break;
    }
}

cut35g.c — a disabled level leaves nothing in the program, not even the evaluation of the arguments.

/* Раздел 35г: выключенный уровень не оставляет в программе ничего — даже вычисления аргументов.
 * Собирается дважды: с -DDLOG_BUILD=4 и с -DDLOG_BUILD=3. */
#include <stdio.h>
#define DLOG_FILE cut35g
#include "dlog35g.h"

static unsigned calls;

static unsigned next_sample(void)
{
    return ++calls;
}

void dlog_put(uint32_t hdr, ...)
{
    (void)hdr;
}

int main(void)
{
    for (int i = 0; i < 10; i++)
        DLOG_D("sample %u", next_sample());
    printf("DLOG_BUILD=%d next_sample called %u times\n", DLOG_BUILD, calls);
    return 0;
}

dlog_gen.py — the log dictionary: finds the DLOG_* calls in the sources and assigns message numbers.

#!/usr/bin/env python3
# -*- coding: utf-8 -*-
"""Раздел 35г: словарь журнала. Обходит исходники, находит вызовы DLOG_E/W/I/D("формат", ...),
выдаёт каждой строке формата постоянный номер и пишет два файла: словарь для компьютера (JSON)
и dlog_ids.h для компилятора.

    python3 dlog_gen.py dlog_dict.json dlog_ids.h app35g.c main35g.c

Номер привязан к тексту формата, а не к месту в файле: строки можно двигать. Исчезнувший формат
остаётся в словаре с пометкой "used": false, его номер заново не выдаётся."""
import json, os, re, sys, zlib

SERVICE = ["lost %u", "start, dictionary %08x"]          # номера 0 и 1 — служебные
ID_MAX, ARGS_MAX = 0x3FFF, 7
SKIP = r'//[^\n]*|/\*.*?\*/'                             # комментарии
LIT = r'"(?:\\.|[^"\\\n])*"'                             # строка в кавычках
TOKEN = re.compile(SKIP + '|' + LIT + r"|'(?:\\.|[^'\\\n])*'|\bDLOG_[EWID]\s*\(|[()]", re.S)
FIRST = re.compile(r'(?:\s|' + SKIP + r')*(' + LIT + ')', re.S)
CONV = re.compile(r'%(?:%|[-+ #0]*[0-9]*([diuxXc]))')    # что умеет декодер
ESC = {'n': '\n', 't': '\t', '\\': '\\', '"': '"', "'": "'"}


def count_args(fmt):
    """Сколько аргументов берёт формат; неподдержанное преобразование — ошибка."""
    n = i = 0
    while (i := fmt.find('%', i)) >= 0:
        m = CONV.match(fmt, i)
        if not m:
            raise ValueError("unsupported conversion in \"%s\"" % fmt)
        n += m.group(1) is not None
        i = m.end()
    if n > ARGS_MAX:
        raise ValueError("more than %d arguments in \"%s\"" % (ARGS_MAX, fmt))
    return n


def unquote(lit):
    """Литерал C → текст: тот, что увидит sizeof."""
    def one(m):
        if m.group(1) not in ESC:
            raise ValueError("unsupported escape \\%s" % m.group(1))
        return ESC[m.group(1)]
    return re.sub(r'\\(.)', one, lit[1:-1])


def scan(path):
    """Вызовы в одном файле: [(первая строка, последняя строка, формат)] и имя DLOG_FILE."""
    text = open(path, encoding="utf-8").read()
    name = re.search(r'^[ \t]*#[ \t]*define[ \t]+DLOG_FILE[ \t]+(\w+)', text, re.M)
    line = lambda pos: text.count("\n", 0, pos) + 1
    calls, it = [], TOKEN.finditer(text)
    for m in it:
        if not m.group().startswith("DLOG_"):
            continue
        where = "%s:%d" % (os.path.basename(path), line(m.start()))
        first = FIRST.match(text, m.end())
        if not first:
            raise ValueError("%s: format must be a string literal" % where)
        depth, end = 1, None
        for t in it:                                     # до парной закрывающей скобки
            depth += {"(": 1, ")": -1}.get(t.group(), 0)
            if depth == 0:
                end = t.start()
                break
        if end is None or not name:
            raise ValueError("%s: %s" % (where, "no DLOG_FILE in this file" if end else "unbalanced brackets"))
        calls.append((line(m.start()), line(end), unquote(first.group(1))))
    return name.group(1) if name else None, calls


def fingerprint(msgs):
    """Отпечаток словаря: CRC-32 по всем парам «номер, формат»."""
    return zlib.crc32("".join("%d\t%s\n" % (m["id"], m["fmt"]) for m in msgs).encode("utf-8"))


def dump(d):
    rows = ",\n".join("  " + json.dumps(m, ensure_ascii=False) for m in d["messages"])
    return '{\n "format": 1,\n "crc": "%s",\n "history": %s,\n "messages": [\n%s\n ]\n}\n' % (
        d["crc"], json.dumps(d["history"]), rows)


def main(dict_path, header_path, sources):
    if os.path.exists(dict_path):
        d = json.load(open(dict_path, encoding="utf-8"))
    else:
        d = {"crc": None, "history": [], "messages": [
            {"id": i, "fmt": f, "args": count_args(f), "used": True} for i, f in enumerate(SERVICE)]}
    msgs = d["messages"]
    by_fmt = {m["fmt"]: m for m in msgs}
    for m in msgs[len(SERVICE):]:
        m["used"] = False                                # отметим заново те, что встретятся
    lines, taken, new, ncalls = [], {}, 0, 0
    for path in sources:
        name, calls = scan(path)
        for first, last, fmt in calls:
            ncalls += 1
            if fmt not in by_fmt:                        # новый формат — следующий свободный номер
                by_fmt[fmt] = {"id": msgs[-1]["id"] + 1, "fmt": fmt, "args": count_args(fmt), "used": True}
                msgs.append(by_fmt[fmt])
                new += 1
            m = by_fmt[fmt]
            m["used"] = True
            if m["id"] > ID_MAX:
                raise ValueError("more than %d messages" % ID_MAX)
            for ln in sorted({first, last}):             # gcc берёт __LINE__ первой строки вызова, clang — последней
                if taken.setdefault((name, ln), fmt) != fmt:
                    raise ValueError("%s:%d: two DLOG calls on one line" % (os.path.basename(path), ln))
                lines.append("#define DLOG_H_%s_%d 0x%05Xu\n#define DLOG_L_%s_%d %d\n" % (
                    name, ln, m["id"] | m["args"] << 16, name, ln, len(fmt.encode("utf-8"))))
    crc = "0x%08x" % fingerprint(msgs)
    if d["crc"] not in (None, crc):
        d["history"].append(d["crc"])                    # прошивки со старым отпечатком словарь знает
    d["crc"] = crc
    head = "/* Создан dlog_gen.py — не править. H: номер | число аргументов << 16; L: длина формата. */\n"
    for path, body in ((dict_path, dump(d)), (header_path, head + "#define DLOG_DICT_CRC %su\n" % crc + "".join(lines))):
        if not os.path.exists(path) or open(path, encoding="utf-8").read() != body:
            open(path, "w", encoding="utf-8", newline="\n").write(body)
    used = sum(m["used"] for m in msgs) - len(SERVICE)
    print("dlog_gen: %d calls in %d files; messages: %d used, %d retired, %d new; next id %d; crc %s" % (
        ncalls, len(sources), used, len(msgs) - len(SERVICE) - used, new, msgs[-1]["id"] + 1, crc))


if __name__ == "__main__":
    if len(sys.argv) < 4:
        sys.exit(__doc__)
    try:
        main(sys.argv[1], sys.argv[2], sys.argv[3:])
    except ValueError as e:
        sys.exit("dlog_gen: error: %s" % e)

dlog_decode.py — the decoder: a byte stream from the line → lines of text using the dictionary.

#!/usr/bin/env python3
# -*- coding: utf-8 -*-
"""Раздел 35г: декодер журнала. Поток байтов из линии → строки текста по словарю dlog_gen.py.

    python3 dlog_decode.py dlog_dict.json uart.bin

Кадр: COBS(номер и уровень 2 байта, счётчик кадров 1, время 4, аргументы по 4, CRC-16 2) + 0x00."""
import json, re, struct, sys

LEVELS = "EWID"
ID_LOST, ID_START = 0, 1
CONV = re.compile(r'%(?:%|([-+ #0]*)([0-9]*)([diuxXc]))')


def crc16(data):
    """CRC-16/XMODEM: полином 0x1021, начальное 0 — как в прошивке."""
    c = 0
    for b in data:
        c ^= b << 8
        for _ in range(8):
            c = ((c << 1) ^ 0x1021 if c & 0x8000 else c << 1) & 0xFFFF
    return c


def cobs_decode(enc):
    """Обратное COBS; None — если код блока выводит за конец кадра."""
    out, r = bytearray(), 0
    while r < len(enc):
        code = enc[r]
        if r + code > len(enc):
            return None
        out += enc[r + 1:r + code]
        r += code
        if code != 0xFF and r < len(enc):
            out.append(0)
    return bytes(out)


def c_format(fmt, args):
    """printf для слов по 32 бита: d i u x X c, флаги - + пробел # 0, ширина."""
    it = iter(args)

    def one(m):
        if m.group(3) is None:
            return "%"
        flags, conv, v = m.group(1), m.group(3), next(it)
        if conv in "di":
            v -= (v & 0x80000000) << 1                   # слово как число со знаком
        if conv == "c":
            return ("%" + flags.replace("0", "") + m.group(2) + "c") % chr(v & 0xFF)
        if conv in "xX" and v == 0:
            flags = flags.replace("#", "")               # в C «%#x» от нуля — просто 0
        return ("%" + flags + m.group(2) + conv.replace("u", "d")) % v
    return CONV.sub(one, fmt)


class Decoder:
    def __init__(self, dictionary):
        self.msgs = {m["id"]: m for m in dictionary["messages"]}
        self.known = {dictionary["crc"]: "same"}
        self.known.update((c, "older firmware") for c in dictionary["history"])
        self.buf = bytearray()
        self.seq = None                                  # счётчик следующего кадра; None — ещё не знаем
        self.st = dict(frames=0, empty=0, bad_cobs=0, bad_len=0, bad_crc=0, gaps=0, missed=0,
                       unknown=0, mismatch=0, device_lost=0, starts=0)

    def feed(self, data):
        """Принять кусок потока; вернуть готовые строки."""
        lines = []
        for b in data:
            if b:
                self.buf.append(b)
                continue
            frame, self.buf = bytes(self.buf), bytearray()       # ноль — конец кадра
            if not frame:
                self.st["empty"] += 1                    # два нуля подряд: пустой кадр, не ошибка
                continue
            line = self.frame(frame, lines)
            if line:
                lines.append(line)
        return lines

    def frame(self, enc, lines):
        st = self.st
        raw = cobs_decode(enc)
        if raw is None:
            st["bad_cobs"] += 1
        elif len(raw) < 9 or len(raw) > 37 or (len(raw) - 9) % 4:
            st["bad_len"] += 1
        elif crc16(raw[:-2]) != raw[-2] << 8 | raw[-1]:
            st["bad_crc"] += 1
        else:
            st["frames"] += 1
            idlvl, seq = struct.unpack_from("<HB", raw)
            t, *args = struct.unpack_from("<%dI" % ((len(raw) - 5) // 4), raw, 3)
            mid, lvl = idlvl & 0x3FFF, LEVELS[idlvl >> 14]
            if mid == ID_START and len(args) == 1:       # прибор запустился: счётчик кадров с нуля
                st["starts"] += 1
                self.seq = 0
            if self.seq is not None and seq != self.seq:
                n = (seq - self.seq) & 0xFF              # сколько кадров не дошло (по модулю 256)
                st["gaps"] += 1
                st["missed"] += n
                lines.append("-- line: %d frame(s) missing" % n)
            self.seq = (seq + 1) & 0xFF
            m = self.msgs.get(mid)
            if m is None:                                # формата нет в словаре: аргументы — как есть
                st["unknown"] += 1
                return "%u %s ?id=%u" % (t, lvl, mid) + "".join(" %08x" % a for a in args)
            if m["args"] != len(args):                   # словарь не от этой прошивки
                st["mismatch"] += 1
                return "%u %s ?id=%u wants %u args:" % (t, lvl, mid, m["args"]) + "".join(" %08x" % a for a in args)
            text = c_format(m["fmt"], args)
            if mid == ID_LOST:
                st["device_lost"] += args[0]
            if mid == ID_START:
                text += " (%s)" % self.known.get("0x%08x" % args[0], "unknown to this dictionary")
            return "%u %s %s" % (t, lvl, text)
        return None


def decode(data, dictionary):
    d = Decoder(dictionary)
    return d.feed(data), d.st


if __name__ == "__main__":
    if len(sys.argv) != 3:
        sys.exit(__doc__)
    out, st = decode(open(sys.argv[2], "rb").read(), json.load(open(sys.argv[1], encoding="utf-8")))
    sys.stdout.write("".join(s + "\n" for s in out))
    sys.stderr.write("frames %(frames)d, bad crc %(bad_crc)d, bad cobs %(bad_cobs)d, bad length %(bad_len)d, "
                     "missing %(missed)d, lost on device %(device_lost)d, unknown id %(unknown)d\n" % st)

Next: section 35д "How the debugger controls the core: SWD, the DP and AP ports, halting the core and FPB breakpoints" — what travels over the two SWD wires when the debugger reads memory, halts the core and sets a breakpoint.