From 8bc522423260fa5407f011acc86b8b937f9a9fe7 Mon Sep 17 00:00:00 2001 From: David Cozens Date: Wed, 29 Jul 2026 08:43:07 +0100 Subject: [PATCH] feat: tell the collector how far to trust the timestamp MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit timeQuality (RFC 5424 section 7.1) joins the record, and meta gains sysUpTime. Store-and-forward is the next stage, and it breaks the assumption that a record's timestamp is close to when the collector saw it — so the device says what its clock is actually worth before that assumption goes. wire ... BOOT [meta sequenceId="1" sysUpTime="362"][timeQuality tzKnown="1" isSynced="0"] device started Flash +7,612 B (+292 on the previous stage) RAM +5,880 B (+24) Log stack +448 B (unchanged) Service +672 B (unchanged) isSynced is 0 and stays 0. This device reads the host clock once at boot and then free-runs on the FreeRTOS tick: enough to stamp a record, not synchronisation, and an operator is better served by being told so than by an unqualified timestamp. RFC 5424 section 7.1.3 forbids syncAccuracy when isSynced is 0, so it is omitted rather than guessed. tzKnown is 1 — the device works in UTC throughout and knows it. sysUpTime lands here rather than beside sequenceId because it answers the same question the clock does: after a reboot the sequence restarts at 1, and an uptime near zero is what distinguishes that from a counter wrap. Adding it is one more field on a config struct that already existed, which is the point — an SD-ID grows a PARAM at a time and nothing downstream notices. One constraint worth knowing: SolidSyslogFreeRtosSysUpTime_Get is guarded at compile time, and with a 32-bit TickType_t it rejects any configTICK_RATE_HZ that does not divide 100. This device runs at 100 Hz and builds; a 1000 Hz device would not, and the escape is to supply your own SolidSyslogSysUpTimeFunction. Co-Authored-By: Claude Opus 5 (1M context) --- README.md | 11 ++++++----- app/syslog/Syslog.c | 20 ++++++++++++++++++-- measurements/stages.tsv | 1 + measurements/time-quality.csv | 13 +++++++++++++ run-report.md | 30 +++++++++++++++--------------- 5 files changed, 53 insertions(+), 22 deletions(-) create mode 100644 measurements/time-quality.csv diff --git a/README.md b/README.md index 0ff8562..834b954 100644 --- a/README.md +++ b/README.md @@ -10,15 +10,15 @@ It builds on a baseline that simulates the sort of device you might be adding th measures itself: see [docs/baseline.md](docs/baseline.md) for what the baseline is, how the figures are made, and how to run it. -## This stage — TCP +## This stage — Time quality -The sender is a TCP stream to the collector on 5601 instead of a UDP datagram, with records framed -by octet count as a receiver on a stream expects. A record the network drops is retransmitted -rather than lost, and a send to a collector that is not there fails instead of quietly succeeding. +The record gains a `timeQuality` SD-ELEMENT and a `sysUpTime` PARAM on `meta`. This device's clock +free-runs on the tick after one reading at boot, so it reports `isSynced="0"` and the collector +knows how far to trust the timestamp. -**Cost above baseline: Flash +7,320 B, RAM +5,856 B.** +**Cost above baseline: Flash +7,612 B, RAM +5,880 B.** @@ -41,6 +41,7 @@ committed as [`run-report.md`](run-report.md), and rewritten by every stage. | Message cap | a bounded record size, so a long message truncates instead of being dropped | +6,032 | +1,956 | | Buffered | logging that returns immediately, with the send moved off the logging task | +6,788 | +5,676 | | TCP | records the network retransmits instead of dropping, and a send that fails when the collector is gone | +7,320 | +5,856 | +| Time quality | a timestamp the collector knows how far to trust, and an uptime that tells a reboot from a counter wrap | +7,612 | +5,880 | *Deltas are bytes above the baseline, which is itself Flash 350,308 B, RAM 111,192 B.* diff --git a/app/syslog/Syslog.c b/app/syslog/Syslog.c index c571c98..3b7043f 100644 --- a/app/syslog/Syslog.c +++ b/app/syslog/Syslog.c @@ -14,6 +14,7 @@ #include "SolidSyslogEndpoint.h" #include "SolidSyslogEndpointHost.h" #include "SolidSyslogFreeRtosMutex.h" +#include "SolidSyslogFreeRtosSysUpTime.h" #include "SolidSyslogLwipRawAddress.h" #include "SolidSyslogLwipRawMarshal.h" #include "SolidSyslogLwipRawResolver.h" @@ -22,6 +23,8 @@ #include "SolidSyslogNullStore.h" #include "SolidSyslogStdAtomicCounter.h" #include "SolidSyslogStreamSender.h" +#include "SolidSyslogTimeQuality.h" +#include "SolidSyslogTimeQualitySd.h" #include "SyslogFields.h" #include "lwip/tcpip.h" @@ -47,7 +50,16 @@ static struct SolidSyslog* s_logger = NULL; static uint8_t s_ring[SOLIDSYSLOG_CIRCULAR_BUFFER_RING_BYTES(SYSLOG_BUFFER_RECORDS)]; /* The logger reads these on every record, so they outlive Syslog_Start. */ -static struct SolidSyslogStructuredData* s_sd[1]; +static struct SolidSyslogStructuredData* s_sd[2]; + +/* One reading at boot, then free-running on the tick — enough to stamp a record, + * not synchronisation. */ +static void SyslogTimeQuality(struct SolidSyslogTimeQuality* timeQuality) +{ + timeQuality->TzKnown = true; + timeQuality->IsSynced = false; + timeQuality->SyncAccuracyMicroseconds = SOLIDSYSLOG_SYNC_ACCURACY_OMIT; +} /* Bounds the connect spin so it yields instead of busy-waiting. */ static void SyslogSleep(int milliseconds) @@ -96,8 +108,12 @@ void Syslog_Start(void) /* One counter Increment per record formatted, so a record that never reaches * the collector leaves a gap in the sequence rather than no trace at all. */ - struct SolidSyslogMetaSdConfig metaConfig = {.Counter = SolidSyslogStdAtomicCounter_Create()}; + struct SolidSyslogMetaSdConfig metaConfig = { + .Counter = SolidSyslogStdAtomicCounter_Create(), + .GetSysUpTime = SolidSyslogFreeRtosSysUpTime_Get, + }; s_sd[0] = SolidSyslogMetaSd_Create(&metaConfig); + s_sd[1] = SolidSyslogTimeQualitySd_Create(SyslogTimeQuality); struct SolidSyslogConfig config = { .Buffer = SolidSyslogCircularBuffer_Create(SolidSyslogFreeRtosMutex_Create(), s_ring, sizeof(s_ring)), diff --git a/measurements/stages.tsv b/measurements/stages.tsv index 3e57072..e2dc788 100644 --- a/measurements/stages.tsv +++ b/measurements/stages.tsv @@ -19,3 +19,4 @@ sequence-id Sequence numbers every record numbered, so a gap in the sequence is message-cap Message cap a bounded record size, so a long message truncates instead of being dropped buffered Buffered logging that returns immediately, with the send moved off the logging task tcp TCP records the network retransmits instead of dropping, and a send that fails when the collector is gone +time-quality Time quality a timestamp the collector knows how far to trust, and an uptime that tells a reboot from a counter wrap diff --git a/measurements/time-quality.csv b/measurements/time-quality.csv new file mode 100644 index 0000000..d1b6d46 --- /dev/null +++ b/measurements/time-quality.csv @@ -0,0 +1,13 @@ +# time-quality figures (bytes) — captured by scripts/run.sh (CAPTURE=1). +# The device reads measurements/Baseline.csv as its frozen baseline and reports current-minus-Baseline. +flash_text,357424 +flash_data,496 +static_bss,116576 +heap_used,4440 +mbedtls_peak,21352 +mbedtls_free,11416 +lwip_mem_free,7576 +lwip_pbufs_free,13 +stack_log,568 +stack_service,724 +stack_harness,2848 diff --git a/run-report.md b/run-report.md index d9c97ab..5156d1c 100644 --- a/run-report.md +++ b/run-report.md @@ -1,4 +1,4 @@ -# solid-syslog-example — run (tcp) +# solid-syslog-example — run (time-quality) ## Device (self-measured) @@ -10,12 +10,12 @@ [device] first record logged: yes [report] --- SolidSyslog cost above baseline (simulated existing application) --- [report] key,current,baseline,used_above_baseline -[report] flash_text,357140,349992,7148 -[report] flash_data,488,316,172 -[report] static_bss,116560,110876,5684 +[report] flash_text,357424,349992,7432 +[report] flash_data,496,316,180 +[report] static_bss,116576,110876,5700 [report] heap_used,4440,4440,0 -[report] mbedtls_peak,21328,21332,-4 -[report] mbedtls_free,11440,11436,4 +[report] mbedtls_peak,21352,21332,20 +[report] mbedtls_free,11416,11436,-20 [report] lwip_mem_free,7576,7576,0 [report] lwip_pbufs_free,13,14,-1 [report] stack_log,568,120,448 @@ -29,7 +29,7 @@ ```text text data bss dec hex filename - 357132 496 116560 474188 73c4c /w/build/baseline-cross/baseline.elf + 357416 504 116576 474496 73d80 /w/build/baseline-cross/baseline.elf ``` ## Listeners (proved before the device ran) @@ -47,19 +47,19 @@ ## Collector (syslog-ng) received ```text -wire <134>1 2026-07-29T07:30:26.440000Z 10.0.2.15 solid-syslog-example - BOOT [meta sequenceId="1"] device started -parsed PRIORITY=134 TIMESTAMP=2026-07-29T07:30:26+00:00 HOSTNAME=10.0.2.15 APP_NAME=solid-syslog-example PROCID= MSGID=BOOT STRUCTURED_DATA=[meta sequenceId="1"] MSG=device started +wire <134>1 2026-07-29T07:42:02.620000Z 10.0.2.15 solid-syslog-example - BOOT [meta sequenceId="1" sysUpTime="362"][timeQuality tzKnown="1" isSynced="0"] device started +parsed PRIORITY=134 TIMESTAMP=2026-07-29T07:42:02+00:00 HOSTNAME=10.0.2.15 APP_NAME=solid-syslog-example PROCID= MSGID=BOOT STRUCTURED_DATA=[meta sequenceId="1" sysUpTime="362"][timeQuality tzKnown="1" isSynced="0"] MSG=device started ``` -## Self-check (vs measurements/tcp.csv) +## Self-check (vs measurements/time-quality.csv) ```text - OK flash_text: 357140 (expected 357140, Δ0) - OK flash_data: 488 (expected 488, Δ0) - OK static_bss: 116560 (expected 116560, Δ0) + OK flash_text: 357424 (expected 357424, Δ0) + OK flash_data: 496 (expected 496, Δ0) + OK static_bss: 116576 (expected 116576, Δ0) OK heap_used: 4440 (expected 4440, Δ0) - OK mbedtls_peak: 21328 (expected 21328, Δ0) - OK mbedtls_free: 11440 (expected 11440, Δ0) + OK mbedtls_peak: 21352 (expected 21352, Δ0) + OK mbedtls_free: 11416 (expected 11416, Δ0) OK lwip_mem_free: 7576 (expected 7576, Δ0) OK lwip_pbufs_free: 13 (expected 13, Δ0) OK stack_log: 568 (expected 568, Δ0)