diff --git a/README.md b/README.md index 95c1355..a3d1d67 100644 --- a/README.md +++ b/README.md @@ -10,49 +10,42 @@ 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 -UDP to TCP, by putting a `SolidSyslogStreamSender` over an lwIP TCP stream. The network -retransmits rather than dropping, and a send fails when the collector is gone instead of succeeding -into a void. Records are framed by octet count per RFC 6587, which is what a receiver expects on a -stream transport. +Add `SolidSyslogTimeQualitySd`, and give `MetaSd` an uptime source alongside its counter. ```c -struct SolidSyslogLwipRawTcpStreamConfig tcpConfig = {.Sleep = SyslogSleep}; - -struct SolidSyslogStreamSenderConfig senderConfig = { - .Resolver = SolidSyslogLwipRawResolver_Create(), - .Stream = SolidSyslogLwipRawTcpStream_Create(&tcpConfig), - .Address = SolidSyslogLwipRawAddress_Create(), - .Endpoint = CollectorEndpoint, +struct SolidSyslogMetaSdConfig metaConfig = { + .Counter = SolidSyslogStdAtomicCounter_Create(), + .GetSysUpTime = SolidSyslogFreeRtos_GetSysUpTime, /* new */ }; -struct SolidSyslogSender* sender = SolidSyslogStreamSender_Create(&senderConfig); +sd[1] = SolidSyslogTimeQualitySd_Create(SyslogTimeQuality); ``` -Taken with the sequence number, this completes the loss story: the transport detects loss where it -happens, and the sequence reveals afterwards anything the transport could not. It is also what -makes the delivery-failed and delivery-restored events from the error-handler stage meaningful. +```text +... BOOT [meta sequenceId="1" sysUpTime="385"][timeQuality tzKnown="1" isSynced="0"] device started +``` -The store is still the Null object, so a record whose send fails is reported but not kept. The -device learns that delivery is failing without yet being able to do anything about it; retaining -the record is the store stage's job. +Time quality states how far the clock can be trusted, which matters when comparing events from +different devices. -TCP before TLS is deliberate. It is the smaller step — a stream, a connect and a framing rule, with -no certificates in the picture — and it is what a later store-and-forward stage will spool onto. +This device reads the host clock once at boot and then free-runs on the FreeRTOS tick, so `isSynced` +is `0` and the callback writes no `syncAccuracy`. `tzKnown` is `1`; the device works in UTC +throughout. -The stream takes a `Sleep` callback because a connect is not instantaneous and the library will not -pick a blocking primitive on your behalf; one `vTaskDelay` is the whole of it. +`sysUpTime` accompanies the sequence number. After a reboot the sequence restarts at one, and an +uptime near zero distinguishes that from a counter wrap. -**When you need it.** If the device must know that delivery is failing — to raise an alarm, to fall -back, to start storing. Over UDP it never finds out. +The element lands before the store because store-and-forward breaks the assumption that a record +reaches the collector shortly after it was raised. A record can arrive hours later, so the device +states what its clock is worth first. -> RFC 6587 is Historic, and the IESG recommends TLS over plain TCP for new deployments. Plain TCP -> is here for collectors you do not control, and as the step a later storage stage will spool onto, -> before cryptography arrives. +**When you need it.** If events from this device will be ordered against events from others, or if a +record's timestamp will be relied on after a delay. -**Cost above baseline: Flash +7,348 B, RAM +7,664 B.** +**Cost above baseline: Flash +7,644 B, RAM +7,688 B.** @@ -74,6 +67,7 @@ committed as [`run-report.md`](run-report.md), and rewritten by every stage. | Sequence numbers | every record numbered, so a gap in the sequence is visible | +6,052 | +1,972 | | Buffered | logging that returns immediately, with the send moved off the logging task | +6,804 | +7,484 | | TCP | records the network retransmits instead of dropping, and a send that fails when the collector is gone | +7,348 | +7,664 | +| Time quality | a timestamp the collector knows how far to trust, and an uptime that tells a reboot from a counter wrap | +7,644 | +7,688 | *Deltas are bytes above the baseline, which is itself Flash 350,124 B, RAM 111,192 B.* diff --git a/app/syslog/Syslog.c b/app/syslog/Syslog.c index c571c98..f76416b 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. RFC 5424 section 7.1.3 forbids syncAccuracy alongside an + * unsynced clock, so none is written. */ +static void SyslogTimeQuality(struct SolidSyslogTimeQuality* timeQuality) +{ + timeQuality->TzKnown = true; + timeQuality->IsSynced = false; +} /* 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 = SolidSyslogFreeRtos_GetSysUpTime, + }; 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 b3b7d3c..657708e 100644 --- a/measurements/stages.tsv +++ b/measurements/stages.tsv @@ -18,3 +18,4 @@ header-fields Header fields a timestamped record naming the device, instead of n sequence-id Sequence numbers every record numbered, so a gap in the sequence is visible 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..cf3773f --- /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,357272 +flash_data,496 +static_bss,118384 +heap_used,4440 +mbedtls_peak,21316 +mbedtls_free,11452 +lwip_mem_free,7576 +lwip_pbufs_free,14 +stack_log,792 +stack_service,948 +stack_harness,2848 diff --git a/run-report.md b/run-report.md index a2ca7b5..8917ad3 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,14 +10,14 @@ [device] first record logged: yes [report] --- SolidSyslog cost above baseline (simulated existing application) --- [report] key,current,baseline,used_above_baseline -[report] flash_text,356984,349808,7176 -[report] flash_data,488,316,172 -[report] static_bss,118368,110876,7492 +[report] flash_text,357272,349808,7464 +[report] flash_data,496,316,180 +[report] static_bss,118384,110876,7508 [report] heap_used,4440,4440,0 -[report] mbedtls_peak,21328,21328,0 -[report] mbedtls_free,11440,11440,0 +[report] mbedtls_peak,21344,21328,16 +[report] mbedtls_free,11424,11440,-16 [report] lwip_mem_free,7576,7576,0 -[report] lwip_pbufs_free,14,13,1 +[report] lwip_pbufs_free,13,13,0 [report] stack_log,792,120,672 [report] stack_service,948,52,896 [report] stack_harness,2848,2840,8 @@ -29,7 +29,7 @@ ```text text data bss dec hex filename - 356976 496 118368 475840 742c0 /w/build/baseline.elf + 357264 504 118384 476152 743f8 /w/build/baseline.elf ``` ## Listeners (proved before the device ran) @@ -47,21 +47,21 @@ ## Collector (syslog-ng) received ```text -wire <134>1 2026-08-16T19:31:24.850000Z 10.0.2.15 solid-syslog-example - BOOT [meta sequenceId="1"] device started -parsed PRIORITY=134 TIMESTAMP=2026-08-16T19:31:24+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-08-16T19:33:31.370000Z 10.0.2.15 solid-syslog-example - BOOT [meta sequenceId="1" sysUpTime="237"][timeQuality tzKnown="1" isSynced="0"] device started +parsed PRIORITY=134 TIMESTAMP=2026-08-16T19:33:31+00:00 HOSTNAME=10.0.2.15 APP_NAME=solid-syslog-example PROCID= MSGID=BOOT STRUCTURED_DATA=[meta sequenceId="1" sysUpTime="237"][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: 356984 (expected 356984, Δ0) - OK flash_data: 488 (expected 488, Δ0) - OK static_bss: 118368 (expected 118368, Δ0) + OK flash_text: 357272 (expected 357272, Δ0) + OK flash_data: 496 (expected 496, Δ0) + OK static_bss: 118384 (expected 118384, Δ0) OK heap_used: 4440 (expected 4440, Δ0) - OK mbedtls_peak: 21328 (expected 21288, Δ40) - OK mbedtls_free: 11440 (expected 11480, Δ40) + OK mbedtls_peak: 21344 (expected 21316, Δ28) + OK mbedtls_free: 11424 (expected 11452, Δ28) OK lwip_mem_free: 7576 (expected 7576, Δ0) - OK lwip_pbufs_free: 14 (expected 13, Δ1) + OK lwip_pbufs_free: 13 (expected 14, Δ1) OK stack_log: 792 (expected 792, Δ0) OK stack_service: 948 (expected 948, Δ0) OK stack_harness: 2848 (expected 2848, Δ0)