LogTTY: live unified-log streaming — root cause, fix, and the instrumentation gap it exposed
Host: rdmbair15m5 · Session: Claude
Code richh-69 · Window: 2026-08-22 22:38 →
22:51 EDT Trigger: Rich — "logtty still doesn't collect
much… should be firing thousands of messages… I believe we needed to
implement monitoring of a specific library."
Verdict: Rich was right on both counts. Volume was wrong by three orders of magnitude, and the fix does hinge on a different library/API than the one in use.
Measurement first (macOS 27.0, rdmbair15m5)
A methodology note that mattered: log is shadowed by a
shell function in this environment
((eval):log:2: too many arguments), which made a first pass
report all zeros. Every number below comes from
/usr/bin/log invoked by absolute path. The initial zeros
were an artifact and were discarded, not reported.
Same 2-minute window, persisted store:
| Query | Entries |
|---|---|
OSLogSystemCollector's actual predicate |
566 |
| error+fault, all processes | 2,395 |
| all persisted messageTypes | 90,011 |
LogTTY was seeing 0.63% of the persisted store. Live
stream rates, same host: --level default 886/sec ·
--level info 1,225/sec · --level debug
9,557/sec.
Three independent causes
- Wrong API.
OSLogStorereads the persisted store. macOS does not persistinfo/debugby default — they live in an in-memory ring buffer and are discarded. No predicate can recover them. - Extremely narrow predicate.
process IN <17 hardcoded names> AND (messageType == error OR fault). The 17 are WindowServer/networkd/cloudd/Dropbox/Safari-class processes — a cloud-sync debugging list. Not one is an app under development. PlusmaximumRawEntries = 512per poll. - The apps are silent. See the instrumentation gap below.
The "specific library" — located by probe, not assumption
os_activity_stream_for_pid /
_set_event_handler / _resume /
_cancel / _set_filter are absent from
libsystem_trace.dylib on macOS 27.0 (the commonly
cited location) and present in
/System/Library/PrivateFrameworks/ktrace.framework
and LoggingSupport.framework.
otool -L /usr/bin/log confirms log links
ktrace.framework.
Design choice: shell out to
log stream --style ndjson rather than link the private
SPI. Same fidelity, stable documented contract, process
isolation, and no dependence on private struct layouts that drift
between releases. The SPI remains available if the subprocess ever
proves inadequate.
The cost rule — this is the "without constraint on the system" part
Measured on a 10-core host:
| Mode | Lines/5s | CPU |
|---|---|---|
--level debug, no predicate |
128,739 | 57.7% of a core |
--level info, no predicate |
23,398 | 17.1% |
--level default, no predicate |
9,318 | 8.8% |
--level debug with source-side
predicate |
1 | ~0% |
The expensive variable is how many events cross into the
process, not the subscription. Filtering must happen inside
logd. OSLogLiveStreamCollector.start()
therefore throws predicateRequired at
.info/.debug when given no predicate — the
firehose is unreachable by accident. Two tests enforce it.
What was built
Sources/LogTTYApp/Collectors/OSLogLiveStreamCollector.swift— NDJSON live subscriber, bounded buffer that drops oldest past cap and counts drops, mandatory-predicate guard, pure-static decode for testability.Sources/LogTTYApp/Collectors/OSLogLiveStreamSource.swift— adapts push→poll for the worker.DesktopLogCollectionWorker— live stream wired in behind the same Direct consent gate: stopped on every unconsented poll, stopped/restarted across a grant-ID change, never polled after revoke.
Tests: 214 across 4 targets, 0 failures (201 before;
13 added). Includes a live end-to-end proof that emits 50
os_log messages and asserts the collector receives them
through a real subprocess — independently re-confirmed outside the test
by streaming subsystem BEGINSWITH "net.dataroo" during the
run: 50 of 50 captured. The NDJSON schema is pinned as
a verbatim fixture so a future macOS change fails a test rather than
silently collecting nothing.
The gap this exposed — and it is not LogTTY's
rdDB contains ZERO os_log usage: 0
import OSLog, 0 Logger instances, and
93 print() calls across 4 files.
print() never reaches the unified log. A debug-level stream
filtered to
rdDB/xctest/swift-frontend/agy
returned 0 log events.
RTTy is the control: it uses
Logger(subsystem: "net.dataroo.RTTy") correctly and was the
only dev app producing volume — 649 entries in 30
minutes.
So real-world yield for the dev apps is still zero, and a perfect collector cannot change that. The remaining work is instrumentation in the apps. Directive sent to the agy sessions and broadcast on the fleet bus.
Published
https://dev.dataroo.net/p/logtty.html updated via
rdmsm4x:~/dev/data/products.json + gen_site.py
(verified HTTP 200, 75,987 B over the tailnet). tested
carries only reproducible measurements; untested states
plainly that real-world yield is still zero, that the SPI path was
probed but not implemented, that the new predicate has never been seen
yielding real dev-app data, and that neither LogTTY nor rdDB is a git
repository.
Undo
Delete the two new Collectors files and revert the
DesktopLogCollectionDependencies additions — the three new
closures default to no-ops, so the worker behaves exactly as before
without them.