Commitedef3154Recorded25 Aug 2026Repositorysigil-log

Harden the text formatter against the adversarial review, and correct my own claims

Message

An adversarial review of c1658ff in an isolated checkout found that the fix was incomplete in one CRITICAL way and wrong in several smaller ones. Reproduced each before acting on it. Two claims in the earlier commit messages and the README are corrected here rather than left standing.

CORRECTION 1, and it is the important one. 5b00464 said:

    Keys are not quoted: a key is always a keyword literal in the source,
    never a runtime value.

THAT WAS AN ASSERTION I NEVER PROBED, AND IT IS FALSE. string->keyword accepts any string, is used with runtime data across the ecosystem (sigil-cli's manifest.sgl and manager/remote.sgl both do it with config and platform names), and (apply log-warn msg kwargs) is the natural way to log a dict of attributes. Reproduced against the "fixed" code:

    (apply log-warn "refused"
           (list (string->keyword "host status=200 reason=host-allowed")
                 "evil.example"))
    -> refused host status=200 reason=host-allowed=evil.example

and with a newline in the key, two log calls produced three lines with a fully forged [INFO] request allowed=true event. That is the EXACT attack the suite exists to prevent, surviving the fix, because I reasoned about the key instead of probing it. Keys are now sanitised -- any separator, =, quote or backslash becomes _. Substitution rather than quoting, because "a b"=v is not a form any logfmt reader understands and a key containing a separator is already malformed.

CORRECTION 2. 5b00464 said ordinary values are "byte-identical across this boundary" and named three that are. Measured properly across 27 realistic values: 15 render identically, 12 change. The rule is exact -- a value changes if and only if it contains a space, =, ", \, a control character or a Unicode separator, or is empty -- but that set includes several EVERYDAY values my framing would have led a reader to think were safe: any URL with a query string, base64 with padding, any Windows path, any User-Agent, JSON fragments, the empty string, character literals, and every compound value. The README now carries the measured table instead of the reassuring sentence.

THE OTHER DEFECTS FIXED

  • Quoting no longer delegates to write. write BYTE-ESCAPES non-ASCII, so "café au lait" came out as "cafxC3xA9 au lait" -- unreadable, and wrong for anyone whose data is not English. It also emits \x07 with no terminator, which is not valid R7RS and does not read back. The hand-rolled quoter passes non-ASCII through verbatim and uses the terminated \xHH; form. I chose write originally to avoid hand-rolling an escaper; the evidence says that was the wrong trade.
  • Unicode line and token separators are handled. U+0085, U+2028 and U+2029 pass Python's str.splitlines(), and U+00A0 and U+3000 pass str.split(), so leaving them raw forged a whole event for a Python log consumer while looking innocent in a terminal. They now escape in the message and force quoting in a value.
  • A SUPPRESSED call no longer raises. The module branch of do-log parsed the keyword list before the level check and outside emit-log's guard, so (log-debug "m" k:) -- inert before -- threw into its caller as soon as per-module levels were configured anywhere in the process. That broke the module's own promise that logging never propagates an error. do-log now scans the raw argument list for module: and parses only after deciding to emit, which also removes the per-call parse cost on the suppressed path.
  • A malformed modules: alist is skipped rather than raised on. A bad logging config must not take down the program it configures.
  • A non-string message produces a log line instead of silently producing NOTHING. Previously string-append raised, the fallback raised identically, and the whole event vanished -- while the same call in JSON worked fine.

ARMS, AND PROOF THAT EACH NEW RULE CAN FAIL

Eight mutations, one per new rule, each with a plant-landed hash guard. All eight redden the specifically named arm: kill-key-sanitize, kill-empty-rule, kill-c0-in-message, kill-unicode-lines, kill-unicode-space, restore-write-quote, kill-guard-order, kill-cfg-skip. The first attempt at the eighth did not land, and the guard reported PLANT-DID-NOT-LAND rather than scoring it as "the gate did not notice".

This mattered: the review showed three of my ORIGINAL rules had assertions that could not go red. The empty-value arm asserted a PARSE, and host-header= ok=1 parses identically to host-header="" ok=1, so deleting the rule kept it green. It now asserts the bytes.

GATE FIXES

  • The "did every suite run?" check I first wrote derived its expectation from the gate's own copy_suite calls, so deleting one shrank the expectation to match and the gate stayed green over a smaller suite -- the same compare-against-yourself defect this whole branch is about. It now enumerates test sources from disk and fires in both directions (a source not wired in, and a wired suite whose source is gone).
  • Scratch is KEPT and its path printed on RED. It was being deleted, so a failing run could not be inspected.
  • The presence arm's comment claimed it was a behaviour check. It is a LOAD check -- the review proved it passes against a pre-fix library and against a logger that emits nothing. Comment corrected rather than the arm inflated; the forgery and module arms are what test behaviour.
  • SIGIL= override so CI and other toolchain versions can drive it; verified by running the whole gate under 0.19.0 as well as 0.19.2.
  • The harness project declares sigil: "^0.16", matching what the package declares, rather than ^0.14.

SABOTAGE, restores sha256-verified

    plant = master (original)        rc=1  36 red (24 forgery, 12 module)
                                           all 25 pre-existing tests GREEN
    plant = c1658ff (my first fix)   rc=1  13 red (10 forgery,  3 module)

The second row is the review's value stated as a number: thirteen arms' worth of real defects in code I had already sabotage-tested and reported green.

NOT FIXED, reported instead. format: 'json with a circular field value HANGS the process -- timeout 20 gives rc=124. emit-log's guard cannot help; it is non-termination, not an exception. The pre-existing test at test-log.sgl:225 claims to cover this class and explicitly hand-waves it ("we can't easily install a printer that raises"). It can be done and it hangs. That is a sigil-json concern on a path this branch does not touch, so it wants its own ticket rather than a drive-by fix in a security change.

Changed
 README.md                      |  48 ++++++++++++++++++++++-------
 src/sigil/log.sgl              | 272 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++--------------------------------------
 test/gate-source-under-test.sh |  67 +++++++++++++++++++++++++++++++---------
 test/uut/forgery-arms.sgl      | 176 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++----
 test/uut/module-arms.sgl       |  46 ++++++++++++++++++++++++++++
 5 files changed, 513 insertions(+), 96 deletions(-)
Diff
README.mdmodified
@@ -42,17 +42,43 @@ escaped, so it cannot forge extra `key=value` pairs or a second log line:
42
;; 2026-08-25T03:10:03Z [WARN] refused host-header="evil.example status=200 reason=host-allowed"
43
```
44
−45
Quoting is conditional, not unconditional: ordinary values are written bare
−46
exactly as they always were (`port=8080`, `path=/api/v1`, `user=alice`), so
−47
existing logs and the habits of people reading them survive. Only values that
−48
were already ambiguous change shape.
−49
−50
**The message is not a field.** It is prose, left unquoted so it stays
−51
readable, and only its control characters are escaped — which guarantees one
−52
log event is always one line, but not that the message cannot contain something
−53
that *looks* like a field. Never interpolate untrusted data into a message;
−54
pass it as a field. For fully machine-parseable output use `format: 'json`,
−55
which escapes everything including the message.
+45
Quoting is conditional, not unconditional. **A value is quoted if and only if it
+46
contains a space, an `=`, a `"`, a `\`, a control character or a Unicode
+47
separator, or is empty.** Everything else renders exactly as it always did.
+48
+49
Be careful reading that as "ordinary values are unaffected" — several everyday
+50
ones are not. Measured across 27 realistic values, 15 render identically and 12
+51
change:
+52
+53
| unchanged | changed |
+54
|---|---|
+55
| paths, IPv4 and IPv6, UUIDs, `1200ms`, `#t`, `3.5`, `8080`, symbols, ISO timestamps, `bob@example.com`, `slate.local:8443`, `café`, `日本語`, `-1` | any URL with a query string (`?b=1`), base64 with padding (`aGVsbG8=`), any Windows path, any User-Agent (spaces), JSON fragments, the empty string, character literals, and **every** list or compound value |
+56
+57
So a reader diffing logs across this boundary should expect the `=`-bearing and
+58
space-bearing fields to gain quotes, and nothing else to move.
+59
+60
Non-ASCII text is **not** byte-escaped: `café au lait` renders as
+61
`"café au lait"`, quoted but intact. (An earlier version of this fix delegated
+62
quoting to `write`, which byte-escapes everything non-ASCII and produced
+63
`"caf\xC3\xA9 au lait"` — unreadable, and wrong for anyone whose data is not
+64
English.)
+65
+66
**Keys are sanitised, not quoted.** A key is an identifier and must be one bare
+67
token, so any separator, `=`, quote or backslash in it becomes `_`. This is not
+68
belt-and-braces: `string->keyword` accepts any string and is used with runtime
+69
data across the ecosystem, and `(apply log-warn msg kwargs)` is the natural way
+70
to log a dict — so a key can carry attacker text, and a crafted one forged both
+71
a field and an entire second log line before this was in place.
+72
+73
**The message is not a field.** It is prose, left unquoted so it stays readable.
+74
Its control characters and every codepoint that some reader treats as a line
+75
break are escaped — `\n`, `\r`, vertical tab, form feed, and U+0085, U+2028,
+76
U+2029, which Python's `str.splitlines()` splits on. That makes "one log event
+77
is exactly one line" true for a text reader and for a Python one. It does **not**
+78
make the message unforgeable: a message containing something shaped like `k=v`
+79
still reads as a field. Never interpolate untrusted data into a message; pass it
+80
as a field. For fully machine-parseable output use `format: 'json`, which
+81
escapes everything including the message.
82
83
## Per-module levels
84
src/sigil/log.sglmodified
@@ -26,14 +26,22 @@
26
;;; ---------------------------------
27
;;; A text line is `TIMESTAMP [LEVEL] message key=value key=value`.
28
;;;
−29
;;; FIELD VALUES are safe to fill with untrusted data: a value that
−30
;;; contains a space, an `=`, a quote, a backslash or a control character
−31
;;; is quoted and escaped, so it cannot forge additional `key=value`
−32
;;; pairs or a second log line.
+29
;;; FIELDS are safe to fill with untrusted data. A value is quoted and
+30
;;; escaped if it contains a space, an `=`, a `"`, a `\`, a control
+31
;;; character or a Unicode separator, or is empty — so it cannot forge
+32
;;; additional `key=value` pairs or a second log line. A KEY is an
+33
;;; identifier and must be one bare token, so anything unsafe in it is
+34
;;; substituted with `_` rather than quoted. Keys need this because
+35
;;; `string->keyword` accepts any string and `(apply log-warn msg kwargs)`
+36
;;; is the natural way to log a dict — a key CAN carry attacker text.
37
;;;
−34
;;; THE MESSAGE IS NOT. It is prose, deliberately unquoted so it stays
−35
;;; readable, and only its control characters are escaped (one event is
−36
;;; always one line). Never interpolate untrusted data into the message —
+38
;;; THE MESSAGE IS NOT A FIELD. It is prose, deliberately unquoted so it
+39
;;; stays readable. Its control characters and every codepoint some reader
+40
;;; treats as a line break are escaped — including U+0085, U+2028 and
+41
;;; U+2029, which Python's str.splitlines() splits on — so one log event
+42
;;; is always exactly one line. That is NOT the same as the message being
+43
;;; unforgeable: a message containing something shaped like `k=v` still
+44
;;; reads as a field. Never interpolate untrusted data into the message —
45
;;; pass it as a field. For fully machine-parseable output use
46
;;; `format: 'json`.
47
@@ -176,16 +184,26 @@
184
((string? val)
185
(set! *log-target* (open-output-file val)))))
186
((modules:)
+187
;; Entries that are not `(name . level)` pairs are
+188
;; skipped rather than raised on: a bad logging config
+189
;; must not take down the program it is configuring.
190
(when (list? val)
191
(set! *log-module-levels*
−181
(map (lambda (pair)
−182
(cons (if (symbol? (car pair))
−183
(symbol->string (car pair))
−184
(car pair))
−185
(if (symbol? (cdr pair))
−186
(level-name->number (cdr pair))
−187
(cdr pair))))
−188
val)))))))
+192
(let loop ((rest val) (acc '()))
+193
(cond
+194
((not (pair? rest)) (reverse acc))
+195
((not (pair? (car rest))) (loop (cdr rest) acc))
+196
(else
+197
(let ((name (car (car rest)))
+198
(lvl (cdr (car rest))))
+199
(loop (cdr rest)
+200
(cons (cons (if (symbol? name)
+201
(symbol->string name)
+202
name)
+203
(if (symbol? lvl)
+204
(level-name->number lvl)
+205
lvl))
+206
acc))))))))))))
207
kwargs)))
208
209
;; ============================================================
@@ -274,27 +292,117 @@
292
;; Output Formatting
293
;; ============================================================
294
−277
;; Escape characters that would break a log entry out of its single
−278
;; line. Applied to the free-text MESSAGE, which is prose and is
+295
;; ------------------------------------------------------------
+296
;; Characters that must never appear raw in a text log line
+297
;; ------------------------------------------------------------
+298
;;
+299
;; Two separate jobs, and they need different answers:
+300
;;
+301
;; * a KEY is an identifier and must always be one bare token, so
+302
;; anything unsafe in it is SUBSTITUTED — there is nowhere to put
+303
;; a quote in `key=value` that a reader would understand;
+304
;; * a VALUE carries data and must survive intact, so anything
+305
;; unsafe in it is QUOTED AND ESCAPED.
+306
;;
+307
;; Sigil strings are indexed by codepoint, not byte, so no ASCII
+308
;; character can leak out of a multi-byte sequence and be mistaken
+309
;; for a separator.
+310
+311
;; Codepoints that end a line for SOME log reader. ASCII newline and
+312
;; carriage return are the obvious two; the rest are here because
+313
;; Python's str.splitlines() — a very likely consumer — also splits
+314
;; on them, so leaving them raw would forge a whole event for a
+315
;; Python reader while looking fine in a terminal.
+316
(define (line-breaking-codepoint? k)
+317
(: integer? -> boolean?)
+318
(or (= k 10) ; line feed
+319
(= k 13) ; carriage return
+320
(= k 11) ; vertical tab
+321
(= k 12) ; form feed
+322
(= k 133) ; U+0085 NEL
+323
(= k 8232) ; U+2028 LINE SEPARATOR
+324
(= k 8233))) ; U+2029 PARAGRAPH SEPARATOR
+325
+326
;; Codepoints that separate tokens for SOME log reader. Python's
+327
;; str.split() treats the non-ASCII ones as whitespace.
+328
(define (separating-codepoint? k)
+329
(: integer? -> boolean?)
+330
(or (< k 33) ; space and every C0 control
+331
(= k 127) ; DEL
+332
(= k 133)
+333
(= k 160) ; U+00A0 NO-BREAK SPACE
+334
(= k 8232)
+335
(= k 8233)
+336
(= k 12288))) ; U+3000 IDEOGRAPHIC SPACE
+337
+338
;; Render a control character as a readable, unambiguous escape.
+339
;; The `\xHH;` form is R7RS and is terminated, so it reads back;
+340
;; `write`'s output is NOT — it emits `\x07` with no terminator,
+341
;; which no reader accepts.
+342
(define (write-escaped-control c k port)
+343
(cond
+344
((= k 10) (write-string "\\n" port))
+345
((= k 13) (write-string "\\r" port))
+346
((= k 9) (write-string "\\t" port))
+347
(else
+348
(write-string "\\x" port)
+349
(write-string (number->string k 16) port)
+350
(write-string ";" port))))
+351
+352
;; Escape what would break a log entry out of its single line.
+353
;; Applied to the free-text MESSAGE, which is prose and is
354
;; deliberately left unquoted; the invariant it buys is "one log
355
;; event is exactly one line of output".
+356
;;
+357
;; Note this escapes LINE BREAKERS and C0 controls but NOT ordinary
+358
;; spaces — the message is prose and is allowed to contain them.
+359
;; A non-string message is rendered rather than left alone: passing
+360
;; it through made `string-append` raise downstream and the entire
+361
;; log line vanish.
362
(define (escape-control-chars s)
−282
(if (not (string? s))
−283
s
−284
(call-with-output-string
−285
(lambda (p)
−286
(string-for-each
−287
(lambda (c)
−288
(let ((k (char->integer c)))
−289
(cond
−290
((char=? c #\newline) (write-string "\\n" p))
−291
((char=? c #\return) (write-string "\\r" p))
−292
((char=? c #\tab) (write-string "\\t" p))
−293
((or (< k 32) (= k 127))
−294
(write-string "\\x" p)
−295
(write-string (number->string k 16) p))
−296
(else (write-char c p)))))
−297
s)))))
+363
(let ((str (if (string? s)
+364
s
+365
(call-with-output-string
+366
(lambda (p) (display s p))))))
+367
(call-with-output-string
+368
(lambda (p)
+369
(string-for-each
+370
(lambda (c)
+371
(let ((k (char->integer c)))
+372
(cond
+373
((or (< k 32) (= k 127)) (write-escaped-control c k p))
+374
((line-breaking-codepoint? k)
+375
(write-string "\\x" p)
+376
(write-string (number->string k 16) p)
+377
(write-string ";" p))
+378
(else (write-char c p)))))
+379
str)))))
+380
+381
;; Turn a KEY into a single bare token. Substitution rather than
+382
;; quoting, because `"a b"=v` is not a form any logfmt reader
+383
;; understands, and because a key containing a separator is already
+384
;; malformed — there is no information worth preserving.
+385
;;
+386
;; THIS IS NOT DEFENSIVE PROGRAMMING. `string->keyword` accepts any
+387
;; string and is used with runtime data across the ecosystem, and
+388
;; `(apply log-warn msg kwargs)` is the natural way to log a dict, so
+389
;; a key CAN carry attacker-controlled text. A crafted key forged
+390
;; both a field and an entire second log line before this existed.
+391
(define (safe-key-token s)
+392
(: string? -> string?)
+393
(call-with-output-string
+394
(lambda (p)
+395
(string-for-each
+396
(lambda (c)
+397
(let ((k (char->integer c)))
+398
(if (or (separating-codepoint? k)
+399
(line-breaking-codepoint? k)
+400
(char=? c #\=)
+401
(char=? c #\")
+402
(char=? c #\\))
+403
(write-char #\_ p)
+404
(write-char c p))))
+405
s))))
406
407
;; Render a field value to the text it would occupy after the `=`.
408
;; Strings render as themselves; everything else through `write`.
@@ -306,13 +414,10 @@
414
415
;; Would this rendered value be ambiguous if written bare after `=`?
416
;;
−309
;; Any of: a space or control character (would start a new field or
−310
;; a new LINE), an `=` (would look like a second key/value pair), a
−311
;; double quote or backslash (would confuse a reader of the quoted
−312
;; form), or emptiness (`key=` followed by a space is unreadable).
−313
;;
−314
;; This is the logfmt rule, and it is what stops an attacker-supplied
−315
;; value forging fields in a log line.
+417
;; Any of: something a reader would treat as a separator or a line
+418
;; break, an `=` (would look like a second key/value pair), a double
+419
;; quote or backslash (would confuse a reader of the quoted form), or
+420
;; emptiness (`key=` followed by a space is unreadable).
421
(define (field-value-needs-quoting? s)
422
(: string? -> boolean?)
423
(let ((n (string-length s)))
@@ -322,34 +427,56 @@
427
(and (< i n)
428
(let* ((c (string-ref s i))
429
(k (char->integer c)))
−325
(or (< k 33)
−326
(= k 127)
+430
(or (separating-codepoint? k)
+431
(line-breaking-codepoint? k)
432
(char=? c #\=)
433
(char=? c #\")
434
(char=? c #\\)
435
(loop (+ i 1)))))))))
436
+437
;; Wrap a value in quotes, escaping only what has to be escaped.
+438
;;
+439
;; Hand-rolled rather than delegated to `write`, and the reason is
+440
;; worth keeping: `write` BYTE-ESCAPES every non-ASCII character, so
+441
;; a value like "café au lait" came back as "caf\xC3\xA9 au lait" —
+442
;; unreadable, and wrong for anyone whose data is not English. Here
+443
;; non-ASCII passes through verbatim and only quotes, backslashes and
+444
;; control characters are escaped.
+445
(define (quote-field-value s)
+446
(: string? -> string?)
+447
(call-with-output-string
+448
(lambda (p)
+449
(write-char #\" p)
+450
(string-for-each
+451
(lambda (c)
+452
(let ((k (char->integer c)))
+453
(cond
+454
((char=? c #\") (write-string "\\\"" p))
+455
((char=? c #\\) (write-string "\\\\" p))
+456
((or (< k 32) (= k 127)) (write-escaped-control c k p))
+457
((line-breaking-codepoint? k)
+458
(write-string "\\x" p)
+459
(write-string (number->string k 16) p)
+460
(write-string ";" p))
+461
(else (write-char c p)))))
+462
s)
+463
(write-char #\" p))))
+464
465
;; Format a keyword-value pair for text output.
466
;;
467
;; Values are quoted only when they would otherwise be ambiguous, so
468
;; ordinary values (`port=8080`, `path=/api/v1`) render exactly as
−336
;; they always have and existing log-reading habits survive. A value
−337
;; that needs quoting is written with `write`, which produces the
−338
;; conventional `"..."` form with `\"`, `\\`, `\n`, `\r` and `\t`
−339
;; escapes.
−340
;;
−341
;; Keys are not quoted: a key is always a keyword literal written by
−342
;; the programmer, never a runtime value.
+469
;; they always have and existing log-reading habits survive.
470
(define (format-text-field pair)
−344
(let* ((key (if (keyword? (car pair))
−345
(keyword->string (car pair))
−346
(call-with-output-string
−347
(lambda (p) (write (car pair) p)))))
+471
(let* ((raw-key (if (keyword? (car pair))
+472
(keyword->string (car pair))
+473
(call-with-output-string
+474
(lambda (p) (write (car pair) p)))))
+475
(key (safe-key-token raw-key))
476
(rendered (field-value->string (cdr pair))))
477
(string-append key "="
478
(if (field-value-needs-quoting? rendered)
−351
(call-with-output-string
−352
(lambda (p) (write rendered p)))
+479
(quote-field-value rendered)
480
rendered))))
481
482
;; Build a text-format log line.
@@ -412,20 +539,37 @@
539
(newline port)
540
(flush-output-port port)))))
541
−415
;; Parse rest args into keyword fields and dispatch.
+542
;; Find a `module:` value in the RAW argument list, without parsing
+543
;; the whole keyword list.
+544
;;
+545
;; The parsing has to wait, and this is not an optimisation. Parsing
+546
;; before the level check moved that work OUTSIDE `emit-log`'s guard,
+547
;; so a malformed keyword list — `(log-debug "m" k:)` with no value —
+548
;; raised out of a call that was being SUPPRESSED. Turning on
+549
;; per-module levels anywhere in the process would then make a
+550
;; previously inert call throw into its caller, breaking the module's
+551
;; central promise that logging never propagates an error.
+552
(define (scan-module-arg args)
+553
(let loop ((rest args))
+554
(cond
+555
((not (pair? rest)) #f)
+556
((not (pair? (cdr rest))) #f)
+557
((eq? (car rest) module:) (car (cdr rest)))
+558
(else (loop (cdr rest))))))
+559
+560
;; Decide whether to emit, then parse. Only the level decision runs
+561
;; outside the guard, and it cannot raise.
562
;;
563
;; When no per-module levels are configured (the default) this is
−418
;; the original global-level check. When they are, the `module:`
+564
;; the original global-level check. When they are, the `module:`
565
;; field selects which level applies; a call with no `module:`
566
;; field always uses the global level.
567
(define (do-log level-num message rest-args)
−422
(if (null? *log-module-levels*)
−423
(when (>= level-num *log-level*)
−424
(emit-log level-num message (cdr (split-keyword-args rest-args))))
−425
(let* ((kwargs (cdr (split-keyword-args rest-args)))
−426
(hit (assq module: kwargs)))
−427
(when (>= level-num (module-level (and (pair? hit) (cdr hit))))
−428
(emit-log level-num message kwargs)))))
+568
(let ((threshold (if (null? *log-module-levels*)
+569
*log-level*
+570
(module-level (scan-module-arg rest-args)))))
+571
(when (>= level-num threshold)
+572
(emit-log level-num message (cdr (split-keyword-args rest-args))))))
573
574
;; ============================================================
575
;; Log Procedures
test/gate-source-under-test.shmodified
@@ -35,6 +35,7 @@ set -u
35
REPO="$(cd "$(dirname "${BASH_SOURCE[0]}")/.." && pwd)"
36
SRC="$REPO/src/sigil/log.sgl"
37
UUT_NAME="loguut"
+38
SIGIL="${SIGIL:-sigil}"
39
TIMEOUT_SECS="${GATE_TIMEOUT_SECS:-300}"
40
WORK="$(mktemp -d /tmp/sigil-log-uut.XXXXXX)"
41
@@ -52,7 +53,7 @@ echo "repo: $REPO"
53
echo "source: $SRC"
54
[ -f "$SRC" ] || setup_failed "no library source at $SRC"
55
echo "src-sha: $(sha256sum "$SRC" | cut -d' ' -f1)"
−55
echo "sigil: $(command -v sigil) -> $(sigil --version 2>&1 | tr -d '\033' | sed 's/\[[0-9]*m//g')"
+56
echo "sigil: $(command -v "$SIGIL") -> $("$SIGIL" --version 2>&1 | tr -d '\033' | sed 's/\[[0-9]*m//g')"
57
echo "scratch: $WORK"
58
echo
59
@@ -66,7 +67,7 @@ cat > "$WORK/shadowcheck/test/test-s.sgl" <<'EOF'
67
(test-group "g" (test "bundled (sigil log) resolves with no project" (assert-true #t)))
68
(run-tests)
69
EOF
−69
( cd "$WORK/shadowcheck" && sigil test --sgl >/dev/null 2>&1 )
+70
( cd "$WORK/shadowcheck" && "$SIGIL" test --sgl >/dev/null 2>&1 )
71
if [ $? -ne 0 ]; then
72
echo "NOTE: (sigil log) did NOT resolve in a project with no dependencies."
73
echo " The binary may no longer embed it. This gate still works, but the"
@@ -94,7 +95,7 @@ cat > "$WORK/proj/package.sgl" <<EOF
95
(package
96
name: "$UUT_NAME"
97
version: "0.0.0"
−97
sigil: "^0.14"
+98
sigil: "^0.16"
99
description: "throwaway harness — generated by test/gate-source-under-test.sh"
100
license: "BSD-3-Clause")
101
EOF
@@ -102,16 +103,28 @@ EOF
103
104
# The throwaway project still needs its dependency closure resolved: the copy's
105
# imports name stdlib modules, and `sigil test` refuses to start without them.
−105
( cd "$WORK/proj" && timeout "$TIMEOUT_SECS" sigil deps install > "$WORK/deps.log" 2>&1 )
+106
( cd "$WORK/proj" && timeout "$TIMEOUT_SECS" "$SIGIL" deps install > "$WORK/deps.log" 2>&1 )
107
DEPS_RC=$?
108
if [ "$DEPS_RC" -ne 0 ]; then
109
sed 's/\x1b\[[0-9;]*m//g' "$WORK/deps.log"
110
setup_failed "sigil deps install failed in the harness project (rc=$DEPS_RC)"
111
fi
112
# --- Copy each test file, rewriting its import -------------------------------
−112
# Auto-discovery needs the test- prefix, so test/uut/forgery-arms.sgl is named
−113
# to stay OUT of a plain `sigil test` run (where it would test the bundled copy
−114
# and be permanently, uninformatively red) and is renamed back in here.
+113
# Auto-discovery needs the test- prefix, so test/uut/*.sgl are named to stay OUT
+114
# of a plain `sigil test` run (where they would test the bundled copy and be
+115
# permanently, uninformatively red) and are renamed back in here.
+116
#
+117
# THE EXPECTED SET IS ENUMERATED FROM DISK, not from the list of copy_suite
+118
# calls below. Deriving it from those calls would make the "did every suite
+119
# run?" check compare the run against itself: deleting a copy_suite line would
+120
# shrink the expectation to match, and the gate would stay green over a smaller
+121
# suite. That mistake was made here once and caught by testing the check.
+122
declare -a EXPECTED=()
+123
for f in "$REPO"/test/test-*.sgl "$REPO"/test/uut/*.sgl; do
+124
[ -e "$f" ] && EXPECTED+=("$f")
+125
done
+126
[ "${#EXPECTED[@]}" -gt 0 ] || setup_failed "found no test sources under $REPO/test"
+127
128
declare -a SUITES=()
129
copy_suite() { # src-path dest-basename
130
local from="$1" to="$WORK/proj/test/$2"
@@ -124,12 +137,19 @@ copy_suite() { # src-path dest-basename
137
|| setup_failed "rewriting $from changed $got diff lines, expected $(( want * 2 ))"
138
SUITES+=("$2")
139
}
−127
copy_suite "$REPO/test/test-log.sgl" "test-log.sgl"
+140
copy_suite "$REPO/test/test-log.sgl" "test-log.sgl"
141
copy_suite "$REPO/test/uut/forgery-arms.sgl" "test-forgery.sgl"
142
copy_suite "$REPO/test/uut/module-arms.sgl" "test-modules.sgl"
−130
echo "suites: ${SUITES[*]}"
−131
echo
143
+144
if [ "${#SUITES[@]}" -ne "${#EXPECTED[@]}" ]; then
+145
echo "test sources on disk (${#EXPECTED[@]}):"
+146
printf ' %s\n' "${EXPECTED[@]}"
+147
echo "suites this gate copies (${#SUITES[@]}):"
+148
printf ' %s\n' "${SUITES[@]}"
+149
setup_failed "a test source on disk is not wired into this gate; a green would be over a smaller suite than the repo contains"
+150
fi
+151
echo "suites: ${SUITES[*]} (${#EXPECTED[@]} of ${#EXPECTED[@]} sources on disk)"
+152
echo
153
# --- Prove the harness is running the COPY, not the bundle -------------------
154
# Without this the whole gate could pass for free: if (loguut log) silently
155
# fell back to something else, every arm below would be about that something.
@@ -137,9 +157,12 @@ cat > "$WORK/proj/test/test-presence.sgl" <<EOF
157
(import (sigil test) ($UUT_NAME log) (sigil io))
158
(test-group "harness presence"
159
(test "the renamed library is the one loaded"
−140
;; A value only THIS copy can produce: a field value that needs quoting.
−141
;; Pre-fix source renders it bare, post-fix quoted — either way the module
−142
;; must load and log, or the harness is not running the copy at all.
+160
;; THIS IS A LOAD CHECK, NOT A BEHAVIOUR CHECK, and saying so matters:
+161
;; it passes against a pre-fix library and against any other loadable
+162
;; copy. Its only job is to prove the renamed module was loaded and
+163
;; can log at all, so that a green from the arms below cannot mean
+164
;; "the harness never ran anything". The forgery and module arms are
+165
;; what test behaviour.
166
(let ((port (open-output-string)))
167
(log-configure! level: 'info format: 'text target: port)
168
(log-info "presence" k: "a b")
@@ -149,7 +172,7 @@ EOF
172
173
# --- Run ----------------------------------------------------------------------
174
LOG="$WORK/run.log"
−152
( cd "$WORK/proj" && timeout "$TIMEOUT_SECS" sigil test --sgl > "$LOG" 2>&1 )
+175
( cd "$WORK/proj" && timeout "$TIMEOUT_SECS" "$SIGIL" test --sgl > "$LOG" 2>&1 )
176
RC=$?
177
178
sed 's/\x1b\[[0-9;]*m//g' "$LOG" > "$WORK/run.txt"
@@ -167,13 +190,27 @@ if ! grep -q 'the renamed library is the one loaded' "$WORK/run.txt"; then
190
setup_failed "the presence arm did not report; the harness may not have loaded the copy"
191
fi
192
+193
# Every suite must have RUN. `sigil test` reports "Files: N of M run", and a
+194
# suite that failed to load is counted but contributes no arms -- so a silent
+195
# drop would otherwise look like a smaller, still-green suite.
+196
WANT_FILES=$(( ${#EXPECTED[@]} + 1 )) # +1 for the presence suite
+197
if ! grep -qE "Files: +$WANT_FILES of $WANT_FILES run" "$WORK/run.txt"; then
+198
echo
+199
echo "Expected all $WANT_FILES suites to run. Actual:"
+200
grep -E 'Files:' "$WORK/run.txt" || echo " (no Files: line at all)"
+201
setup_failed "not every suite ran; a green here would be over a smaller suite than intended"
+202
fi
+203
204
echo
205
echo "--- verdict ---"
206
echo "rc: $RC"
207
if [ "$RC" -eq 0 ]; then
208
echo "GREEN — every arm passed against $SRC"
+209
rm -rf "$WORK"
210
else
211
echo "RED — the source IS under test and at least one arm failed (see above)"
+212
echo "Scratch KEPT for inspection: $WORK"
+213
echo " Re-run just the failing suite with:"
+214
echo " cd $WORK/proj && $SIGIL test --sgl"
215
fi
−178
rm -rf "$WORK"
216
exit "$RC"
test/uut/forgery-arms.sglmodified
@@ -58,12 +58,32 @@
58
((char=? (string-ref s k) #\\)
59
(if (< (+ k 1) n)
60
(let ((e (string-ref s (+ k 1))))
−61
(val-loop (+ k 2)
−62
(cons (cond ((char=? e #\n) #\newline)
−63
((char=? e #\r) #\return)
−64
((char=? e #\t) #\tab)
−65
(else e))
−66
out)))
+61
(if (char=? e #\x)
+62
;; \xHH; — R7RS hex escape, TERMINATED.
+63
;; Reading it properly is what lets an arm
+64
;; tell an escaped control character from
+65
;; the literal letters "xHH".
+66
(let hex-loop ((h (+ k 2)) (digits '()))
+67
(cond
+68
((>= h n)
+69
(val-loop h (cons #\? out)))
+70
((char=? (string-ref s h) #\;)
+71
(val-loop
+72
(+ h 1)
+73
(cons (integer->char
+74
(string->number
+75
(list->string (reverse digits))
+76
16))
+77
out)))
+78
(else
+79
(hex-loop (+ h 1)
+80
(cons (string-ref s h) digits)))))
+81
(val-loop (+ k 2)
+82
(cons (cond ((char=? e #\n) #\newline)
+83
((char=? e #\r) #\return)
+84
((char=? e #\t) #\tab)
+85
(else e))
+86
out))))
87
(val-loop (+ k 1) out)))
88
((char=? (string-ref s k) #\")
89
(loop (+ k 1) (cons (cons key (list->string (reverse out))) acc)))
@@ -274,4 +294,148 @@
294
(assert-false (string-contains? out "\"status\"")))
295
(log-configure! format: 'text))))
296
+297
+298
;; ============================================================
+299
;; KEYS — found by adversarial review, 2026-08-25
+300
;; ============================================================
+301
;;
+302
;; The first version of this fix quoted values and left keys alone, on
+303
;; the argument that "a key is always a keyword literal written by the
+304
;; programmer, never a runtime value". THAT ARGUMENT WAS WRONG AND WAS
+305
;; NEVER PROBED. `string->keyword` accepts any string and is used with
+306
;; runtime data across the ecosystem, and `(apply log-warn msg kwargs)`
+307
;; is the natural way to log a dict of attributes. A crafted key forged
+308
;; both a field and an entire second log line against the "fixed" code.
+309
+310
(test-group "text format: a KEY cannot forge fields or lines"
+311
(test "a crafted key cannot inject a second field"
+312
(let* ((line (capture
+313
(lambda ()
+314
(apply log-warn "refused"
+315
(list (string->keyword "host status=200 reason=host-allowed")
+316
"evil.example")))))
+317
(f (fields-of line)))
+318
(assert-false (assoc "status" f))
+319
(assert-false (assoc "reason" f))
+320
(assert-equal 1 (length f))))
+321
+322
(test "a crafted key cannot forge a whole log line"
+323
(let ((line (capture
+324
(lambda ()
+325
(apply log-warn "refused"
+326
(list (string->keyword
+327
"h\n2026-01-01T00:00:00Z [INFO] request allowed=true from")
+328
"evil.example"))))))
+329
(assert-equal 1 (count-char line #\newline))
+330
(assert-false (field line "allowed"))))
+331
+332
(test "a crafted key cannot smuggle a quote"
+333
(let ((line (capture
+334
(lambda ()
+335
(apply log-info "m"
+336
(list (string->keyword "a\"b") "v"))))))
+337
(assert-false (string-contains? line "a\"b"))
+338
(assert-equal "v" (field line "a_b"))))
+339
+340
(test "an ordinary keyword key is untouched"
+341
(let ((line (capture (lambda () (log-info "m" host-header: "x")))))
+342
(assert-true (string-contains? line "host-header=x")))))
+343
+344
;; ============================================================
+345
;; Separators a NON-ASCII log reader honours
+346
;; ============================================================
+347
;;
+348
;; Python's str.splitlines() splits on U+0085, U+2028 and U+2029, and
+349
;; str.split() additionally on U+00A0 and U+3000. Left raw, those forge
+350
;; an event for a Python consumer while looking innocent in a terminal.
+351
+352
(test-group "text format: unicode separators do not split a line"
+353
(test "U+2028 in a value is escaped"
+354
(let* ((hostile (string-append "h" (string (integer->char 8232)) "allowed=true"))
+355
(line (capture (lambda () (log-warn "refused" host-header: hostile)))))
+356
(assert-false (string-contains? line (string (integer->char 8232))))
+357
(assert-equal hostile (field line "host-header"))))
+358
+359
(test "U+0085 in a MESSAGE is escaped"
+360
(let ((line (capture
+361
(lambda ()
+362
(log-warn (string-append "a" (string (integer->char 133))
+363
"2026-01-01T00:00:00Z [INFO] allowed=true")
+364
ok: 1)))))
+365
(assert-false (string-contains? line (string (integer->char 133))))
+366
(assert-equal "1" (field line "ok"))))
+367
+368
(test "U+2029 in a MESSAGE is escaped"
+369
(let ((line (capture
+370
(lambda ()
+371
(log-warn (string-append "a" (string (integer->char 8233)) "b") ok: 1)))))
+372
(assert-false (string-contains? line (string (integer->char 8233))))))
+373
+374
(test "U+00A0 in a value forces quoting"
+375
(let* ((v (string-append "a" (string (integer->char 160)) "b"))
+376
(line (capture (lambda () (log-info "m" k: v)))))
+377
(assert-equal v (field line "k"))
+378
(assert-true (string-contains? line "k=\""))))
+379
+380
(test "ordinary non-ASCII text is NOT byte-escaped"
+381
;; `write` renders "café au lait" as "caf\xC3\xA9 au lait". A log a
+382
;; human has to read must not do that.
+383
(let ((line (capture (lambda () (log-info "m" city: "café au lait")))))
+384
(assert-true (string-contains? line "café au lait"))
+385
(assert-equal "café au lait" (field line "city")))))
+386
+387
;; ============================================================
+388
;; MESSAGE escaping — the generic control-char rule
+389
;; ============================================================
+390
;;
+391
;; Deleting the generic `(or (< k 32) (= k 127))` branch left every arm
+392
;; green, because only newline, CR and tab were ever exercised.
+393
+394
(test-group "text format: message control characters"
+395
(test "an ESC in a message does not reach the terminal raw"
+396
(let ((line (capture (lambda () (log-info (string (integer->char 27)) ok: 1)))))
+397
(assert-false (string-contains? line (string (integer->char 27))))
+398
(assert-equal "1" (field line "ok"))))
+399
+400
(test "a NUL in a message is escaped"
+401
(let ((line (capture (lambda () (log-info (string (integer->char 0)) ok: 1)))))
+402
(assert-false (string-contains? line (string (integer->char 0))))))
+403
+404
(test "a DEL in a message is escaped"
+405
(let ((line (capture (lambda () (log-info (string (integer->char 127)) ok: 1)))))
+406
(assert-false (string-contains? line (string (integer->char 127))))))
+407
+408
(test "a non-string message still produces a log line"
+409
;; It used to produce NOTHING: string-append raised, the fallback
+410
;; raised the same way, and the entire event vanished silently.
+411
(let ((line (capture (lambda () (log-info 'a-symbol ok: 1)))))
+412
(assert-true (string-contains? line "a-symbol"))
+413
(assert-equal "1" (field line "ok")))))
+414
+415
;; ============================================================
+416
;; Rendering assertions that the parse-level arms cannot make
+417
;; ============================================================
+418
;;
+419
;; The empty-value arm above asserts a PARSE, and `host-header= ok=1`
+420
;; parses identically to `host-header="" ok=1` — so it could not go red
+421
;; when the empty-value rule was deleted. These assert the bytes.
+422
+423
(test-group "text format: exact rendering"
+424
(test "an empty value renders as two quotes, not as nothing"
+425
(let ((line (capture (lambda () (log-info "m" k: "" ok: 1)))))
+426
(assert-true (string-contains? line "k=\"\" ok=1"))))
+427
+428
(test "a value needing quotes renders with them"
+429
(let ((line (capture (lambda () (log-info "m" k: "a b")))))
+430
(assert-true (string-contains? line "k=\"a b\""))))
+431
+432
(test "a value not needing quotes renders without them"
+433
(let ((line (capture (lambda () (log-info "m" k: "ab")))))
+434
(assert-true (string-contains? line "k=ab"))
+435
(assert-false (string-contains? line "k=\"ab\""))))
+436
+437
(test "a control character is escaped in the terminated R7RS form"
+438
(let ((line (capture (lambda () (log-info "m" k: (string (integer->char 7)))))))
+439
(assert-true (string-contains? line "\\x7;")))))
+440
441
(run-tests)
test/uut/module-arms.sglmodified
@@ -162,4 +162,50 @@
162
(assert-equal "" out)
163
(assert-true ran)))))
164
+165
+166
;; ============================================================
+167
;; Robustness — found by adversarial review, 2026-08-25
+168
;; ============================================================
+169
;;
+170
;; The module feature must not make logging dangerous. Two regressions
+171
;; the first implementation introduced, both of which turn a logging
+172
;; concern into a caller's crash:
+173
+174
(test-group "per-module levels must not make logging raise"
+175
(test "a SUPPRESSED call with a malformed keyword list does not raise"
+176
;; The first implementation parsed the keyword list BEFORE the level
+177
;; check and outside emit-log's guard, so turning per-module levels
+178
;; on anywhere in the process made a previously inert suppressed call
+179
;; throw into its caller.
+180
(reset!)
+181
(log-configure! level: 'error modules: '(("z" . error)))
+182
(log-debug "malformed" k:)
+183
(assert-true #t))
+184
+185
(test "the same call with no modules configured does not raise"
+186
(reset!)
+187
(log-configure! level: 'error)
+188
(log-debug "malformed" k:)
+189
(assert-true #t))
+190
+191
(test "a malformed modules: alist does not raise out of log-configure!"
+192
;; A bad logging config must not take down the program it configures.
+193
(reset!)
+194
(log-configure! modules: '("not-a-pair"))
+195
(log-configure! modules: '(("ok" . trace) "junk" ("also-ok" . error)))
+196
(assert-true #t))
+197
+198
(test "malformed entries are skipped, valid ones still take effect"
+199
(reset!)
+200
(log-configure! level: 'info modules: '("junk" ("node/tty" . trace)))
+201
(let ((out (capture (lambda () (log-trace* "byte in" module: "node/tty")))))
+202
(assert-true (string-contains? out "byte in"))))
+203
+204
(test "a non-list modules: value is ignored and leaves the alist alone"
+205
(reset!)
+206
(log-configure! level: 'info modules: '(("node/tty" . trace)))
+207
(log-configure! modules: 'nope)
+208
(let ((out (capture (lambda () (log-trace* "byte in" module: "node/tty")))))
+209
(assert-true (string-contains? out "byte in")))))
+210
211
(run-tests)