Fleet changelogs · dev.ecs0.net
rdmbair15m5-changelog-20260822-2251-logtty-live-unified-log-stream-collector

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

  1. Wrong API. OSLogStore reads the persisted store. macOS does not persist info/debug by default — they live in an in-memory ring buffer and are discarded. No predicate can recover them.
  2. 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. Plus maximumRawEntries = 512 per poll.
  3. 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

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.