Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
52 changes: 23 additions & 29 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.

<!-- STAGE-COST:START (generated by scripts/gen-cost-table.py — do not edit by hand) -->

**Cost above baseline: Flash +7,348 B, RAM +7,664 B.**
**Cost above baseline: Flash +7,644 B, RAM +7,688 B.**

<!-- STAGE-COST:END -->

Expand All @@ -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.*

Expand Down
20 changes: 18 additions & 2 deletions app/syslog/Syslog.c
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -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"
Expand All @@ -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)
Expand Down Expand Up @@ -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)),
Expand Down
1 change: 1 addition & 0 deletions measurements/stages.tsv
Original file line number Diff line number Diff line change
Expand Up @@ -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
13 changes: 13 additions & 0 deletions measurements/time-quality.csv
Original file line number Diff line number Diff line change
@@ -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
34 changes: 17 additions & 17 deletions run-report.md
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
# solid-syslog-example — run (tcp)
# solid-syslog-example — run (time-quality)

## Device (self-measured)

Expand All @@ -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
Expand All @@ -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)
Expand All @@ -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)
Expand Down