Merge pull request 'fix(plugins): plugin output reaches the console's log page, and /tmp is no longer hidden from the runner' (#27) from worktree-plugin-logs-and-vh-fixes into main
ci / rust (push) Canceled after 23s
ci / rust-arm64 (push) Canceled after 24s
ci / web (push) Canceled after 24s
ci / docs-site (push) Canceled after 24s
docker / builders (--build-arg FEDORA_VERSION=44, ci/fedora-rpm.Dockerfile, punktfunk-fedora44-rpm, -f44) (push) Canceled after 0s
docker / builders (ci/android-ci.Dockerfile, punktfunk-android-ci) (push) Canceled after 0s
docker / builders (ci/arch-ci.Dockerfile, punktfunk-arch-ci) (push) Canceled after 0s
docker / builders (ci/fedora-rpm.Dockerfile, punktfunk-fedora-rpm) (push) Canceled after 0s
docker / builders (ci/rust-ci-noble.Dockerfile, punktfunk-rust-ci-noble) (push) Canceled after 0s
docker / builders (ci/rust-ci.Dockerfile, punktfunk-rust-ci) (push) Canceled after 0s
docker / builders-arm64cross (push) Canceled after 0s
docker / apps (., web/Dockerfile, punktfunk-web) (push) Canceled after 0s
docker / apps (docs-site, docs-site/Dockerfile, punktfunk-docs) (push) Canceled after 0s
docker / deploy-docs (push) Canceled after 0s
apple / swift (push) Successful in 1m16s
deb / build-publish-client-arm64 (push) Successful in 1m12s
deb / build-publish (push) Successful in 3m52s
deb / build-publish-host (push) Successful in 4m45s
android / android (push) Successful in 5m24s
apple / screenshots (push) Successful in 5m57s
arch / build-publish (push) Successful in 8m4s
windows-host / package (push) Successful in 17m44s
windows-host / winget-source (push) Skipped
windows-host / canary-manifest (push) Successful in 28s
rpm / build-publish (43, bazzite, punktfunk-fedora-rpm) (push) Successful in 17m34s
rpm / build-publish (44, fedora-44, punktfunk-fedora44-rpm) (push) Successful in 22m42s

Reviewed-on: #27
This commit was merged in pull request #27.
This commit is contained in:
2026-08-03 16:44:31 +00:00
18 changed files with 1262 additions and 45 deletions
+90 -1
View File
@@ -10,7 +10,7 @@
"name": "MIT OR Apache-2.0",
"identifier": "MIT OR Apache-2.0"
},
"version": "0.22.3"
"version": "0.23.0"
},
"paths": {
"/api/v1/clients": {
@@ -2170,6 +2170,51 @@
}
}
},
"/api/v1/plugins/logs": {
"post": {
"tags": [
"plugins"
],
"summary": "Ingest runner log lines",
"description": "The plugin/script runner ships its output here so the console's **Logs** page can show it.\n\nPlugins are not host child processes — the runner is a separate `bun` process that `import()`s\neach plugin in-process — so nothing a plugin logs passes through the host's own `tracing`, and\nbefore this endpoint the console's log page could not show a single plugin line. On Linux the\nfallback was `journalctl --user -u punktfunk-scripting`; on Windows the runner task writes no\nlog file at all, so a failing plugin was diagnosable only by stopping the scheduled task and\nre-running the runner by hand. Both are shell access on the host box, which is exactly what the\nconsole exists to avoid.\n\nLines land in the same ring as the host's own, sharing one `seq` cursor, targeted\n`plugin:<source>` — so `GET /logs` needs no second cursor and the console needs no second poll.",
"operationId": "ingestPluginLogs",
"requestBody": {
"content": {
"application/json": {
"schema": {
"$ref": "#/components/schemas/PluginLogBatch"
}
}
},
"required": true
},
"responses": {
"204": {
"description": "Lines ingested"
},
"400": {
"description": "Batch too large",
"content": {
"application/json": {
"schema": {
"$ref": "#/components/schemas/ApiError"
}
}
}
},
"401": {
"description": "Missing or invalid bearer token",
"content": {
"application/json": {
"schema": {
"$ref": "#/components/schemas/ApiError"
}
}
}
}
}
}
},
"/api/v1/plugins/{id}": {
"put": {
"tags": [
@@ -6238,6 +6283,50 @@
"gamestream"
]
},
"PluginLogBatch": {
"type": "object",
"description": "A batch of runner log lines.",
"required": [
"entries"
],
"properties": {
"entries": {
"type": "array",
"items": {
"$ref": "#/components/schemas/PluginLogLine"
}
}
}
},
"PluginLogLine": {
"type": "object",
"description": "One log line produced by the runner or a plugin inside it (`POST /plugins/logs`).",
"required": [
"ts_ms",
"level",
"source",
"msg"
],
"properties": {
"level": {
"type": "string",
"description": "`ERROR` | `WARN` | `INFO` | `DEBUG` | `TRACE`. Anything else is coerced to `INFO`."
},
"msg": {
"type": "string"
},
"source": {
"type": "string",
"description": "Which unit emitted it — a plugin's `definePlugin` name, a package name, or `runner`.\nSurfaced in the console's target column as `plugin:<source>`."
},
"ts_ms": {
"type": "integer",
"format": "int64",
"description": "When the line was produced, unix milliseconds. Kept verbatim — see\n[`crate::log_capture::LogRing::push_remote`].",
"minimum": 0
}
}
},
"PluginRegistration": {
"type": "object",
"description": "Register/renew body for `PUT /plugins/{id}`.",
+95 -11
View File
@@ -77,6 +77,32 @@ impl LogRing {
.duration_since(UNIX_EPOCH)
.map(|d| d.as_millis() as u64)
.unwrap_or(0);
self.push_entry(level.to_string(), target.to_string(), msg, ts_ms);
}
/// Ingest a line that was produced in **another process** — the plugin/script runner, via
/// `POST /plugins/logs` (see `mgmt::plugins::ingest_plugin_logs`).
///
/// Plugins are not host child processes: the runner is a separate bun process that `import()`s
/// each plugin in-process, so a plugin's output never passes through this process's `tracing`
/// and [`RingLayer`] can't see it. Without this door the console's log page shows nothing about
/// the plugins at all, and on Windows nothing else does either — the runner task writes no log
/// file, so a failing plugin was diagnosable only by stopping the task and re-running it by
/// hand (field report 2026-08-03, the VirtualHere plugin).
///
/// The caller's `ts_ms` is kept — the line was stamped when it happened, and re-stamping it on
/// arrival would collapse a whole batch onto the moment it was flushed. `seq` stays ours: it is
/// the cursor for a single ring with several producers, so only the ring can mint it.
pub fn push_remote(&self, level: &str, target: &str, msg: &str, ts_ms: u64) {
self.push_entry(
normalize_level(level).to_string(),
target.to_string(),
truncate_msg(msg.to_string()),
ts_ms,
);
}
fn push_entry(&self, level: String, target: String, msg: String, ts_ms: u64) {
let mut inner = self.inner.lock().unwrap_or_else(|e| e.into_inner());
let seq = inner.next_seq;
inner.next_seq += 1;
@@ -86,8 +112,8 @@ impl LogRing {
inner.entries.push_back(LogEntry {
seq,
ts_ms,
level: level.to_string(),
target: target.to_string(),
level,
target,
msg,
});
}
@@ -125,6 +151,33 @@ pub fn ring() -> &'static LogRing {
RING.get_or_init(LogRing::new)
}
/// Coerce an externally-supplied level to the five the console's filter ranks. Anything else —
/// a plugin inventing `NOTICE`, a truncated line, empty — becomes `INFO` rather than being
/// rejected: an unfamiliar level is not a reason to drop the operator's diagnostics on the floor,
/// and an unranked string would sort as `0` in the console's `RANK` map and hide under every filter.
fn normalize_level(level: &str) -> &'static str {
match level.trim().to_ascii_uppercase().as_str() {
"ERROR" | "FATAL" | "SEVERE" => "ERROR",
"WARN" | "WARNING" => "WARN",
"DEBUG" => "DEBUG",
"TRACE" | "VERBOSE" => "TRACE",
_ => "INFO",
}
}
/// Cap a message at [`MAX_MSG`], cutting on a char boundary and marking the elision.
fn truncate_msg(mut msg: String) -> String {
if msg.len() > MAX_MSG {
let mut end = MAX_MSG;
while !msg.is_char_boundary(end) {
end -= 1;
}
msg.truncate(end);
msg.push('…');
}
msg
}
/// Targets whose DEBUG/TRACE output is steady-state chatter, not diagnostics — left in, they evict
/// the entire ring tail: `mdns_sd` DEBUG-logs every multicast packet it can't parse (one chatty
/// AirPlay/HomePod device on the LAN floods thousands of entries per hour), and `wasapi` DEBUG-logs
@@ -223,15 +276,7 @@ impl FieldFmt {
} else {
self.msg.push_str(&self.fields);
}
if self.msg.len() > MAX_MSG {
let mut end = MAX_MSG;
while !self.msg.is_char_boundary(end) {
end -= 1;
}
self.msg.truncate(end);
self.msg.push('…');
}
self.msg
truncate_msg(self.msg)
}
}
@@ -360,6 +405,45 @@ mod tests {
assert!(page.entries.iter().any(|e| e.target == "mdns_sdx"));
}
#[test]
fn remote_entries_keep_their_own_timestamp_and_share_the_cursor() {
let ring = LogRing::new();
ring.push(&tracing::Level::INFO, "punktfunk_host", "local".into());
ring.push_remote("WARN", "plugin:virtualhere", "remote", 1_700_000_000_123);
let page = ring.since(0, 10);
assert_eq!(page.entries.len(), 2);
// One sequence across both producers — the console's cursor cannot see two rings.
assert_eq!(page.entries[0].seq, 1);
assert_eq!(page.entries[1].seq, 2);
let remote = &page.entries[1];
assert_eq!(remote.level, "WARN");
assert_eq!(remote.target, "plugin:virtualhere");
assert_eq!(remote.msg, "remote");
// Stamped when it happened, not when the batch arrived.
assert_eq!(remote.ts_ms, 1_700_000_000_123);
}
#[test]
fn remote_levels_are_coerced_not_rejected() {
assert_eq!(normalize_level("error"), "ERROR");
assert_eq!(normalize_level(" Warning "), "WARN");
assert_eq!(normalize_level("TRACE"), "TRACE");
// An unranked level would sort as 0 in the console's filter and hide under every setting.
assert_eq!(normalize_level("NOTICE"), "INFO");
assert_eq!(normalize_level(""), "INFO");
}
#[test]
fn remote_messages_are_truncated_like_local_ones() {
let ring = LogRing::new();
ring.push_remote("INFO", "plugin:x", &"ä".repeat(MAX_MSG), 1);
let page = ring.since(0, 10);
let msg = &page.entries[0].msg;
assert!(msg.ends_with('…'));
assert!(msg.len() <= MAX_MSG + '…'.len_utf8());
}
#[test]
fn message_truncation_keeps_char_boundary() {
let f = FieldFmt {
+1
View File
@@ -253,6 +253,7 @@ fn api_router_parts() -> (Router<Arc<MgmtState>>, utoipa::openapi::OpenApi) {
.routes(routes!(plugins::list_plugins))
.routes(routes!(plugins::register_plugin, plugins::delete_plugin))
.routes(routes!(plugins::get_ui_credential))
.routes(routes!(plugins::ingest_plugin_logs))
.routes(routes!(store::get_catalog))
.routes(routes!(store::refresh_catalog))
.routes(routes!(store::list_installed))
+103
View File
@@ -29,6 +29,12 @@ use std::time::{Duration, Instant};
/// this tolerates two missed ticks before a plugin drops out of the listing.
const LEASE_TTL: Duration = Duration::from_secs(90);
/// Lines accepted per `POST /plugins/logs`. The runner batches on a short timer, so a batch this
/// size means a plugin is logging faster than the ring can usefully hold — the shipper drops its
/// own backlog (and says so in a line of its own) rather than letting one chatty plugin evict the
/// whole ring in a single request.
const MAX_LOG_BATCH: usize = 256;
// ---------------------------------------------------------------- wire shapes
/// A plugin's UI surface as it registers it. Carries the secret — this shape is only ever a request
@@ -60,6 +66,26 @@ pub(crate) struct PluginRegistration {
pub ui: Option<PluginUi>,
}
/// One log line produced by the runner or a plugin inside it (`POST /plugins/logs`).
#[derive(Deserialize, ToSchema)]
pub(crate) struct PluginLogLine {
/// When the line was produced, unix milliseconds. Kept verbatim — see
/// [`crate::log_capture::LogRing::push_remote`].
pub ts_ms: u64,
/// `ERROR` | `WARN` | `INFO` | `DEBUG` | `TRACE`. Anything else is coerced to `INFO`.
pub level: String,
/// Which unit emitted it — a plugin's `definePlugin` name, a package name, or `runner`.
/// Surfaced in the console's target column as `plugin:<source>`.
pub source: String,
pub msg: String,
}
/// A batch of runner log lines.
#[derive(Deserialize, ToSchema)]
pub(crate) struct PluginLogBatch {
pub entries: Vec<PluginLogLine>,
}
/// The secret-free view of a plugin's UI surface — what [`list_plugins`] returns to the browser.
#[derive(Serialize, ToSchema)]
pub(crate) struct PluginUiPublic {
@@ -264,6 +290,26 @@ fn sanitize(s: &str) -> String {
.to_string()
}
/// The console target for a runner-supplied line: `plugin:<source>`.
///
/// The source is NOT a [`valid_plugin_id`] — the runner names a unit by its `definePlugin` name
/// (`virtualhere`), its package name (`@punktfunk/plugin-virtualhere`), a bare script's file stem,
/// or `runner` for its own supervision lines, and all four are worth telling apart in the log. So
/// this sanitizes rather than validates: control characters go (a log target is rendered in a
/// terminal by `logs download` as readily as in the console), length is capped, and an empty source
/// becomes `runner` so a line is never attributed to nothing.
fn log_target(source: &str) -> String {
let mut s = sanitize(source);
if s.is_empty() {
s = "runner".into();
}
// Cap on CHARS, not bytes — truncating a multi-byte name mid-sequence would panic.
if s.chars().count() > 64 {
s = s.chars().take(64).collect();
}
format!("plugin:{s}")
}
/// Validate a registration body into the internal [`Valid`] form, or a human-readable reason.
fn validate(reg: PluginRegistration) -> Result<Valid, String> {
let title = sanitize(&reg.title);
@@ -367,6 +413,63 @@ pub(crate) async fn register_plugin(
StatusCode::NO_CONTENT.into_response()
}
/// Ingest runner log lines
///
/// The plugin/script runner ships its output here so the console's **Logs** page can show it.
///
/// Plugins are not host child processes — the runner is a separate `bun` process that `import()`s
/// each plugin in-process — so nothing a plugin logs passes through the host's own `tracing`, and
/// before this endpoint the console's log page could not show a single plugin line. On Linux the
/// fallback was `journalctl --user -u punktfunk-scripting`; on Windows the runner task writes no
/// log file at all, so a failing plugin was diagnosable only by stopping the scheduled task and
/// re-running the runner by hand. Both are shell access on the host box, which is exactly what the
/// console exists to avoid.
///
/// Lines land in the same ring as the host's own, sharing one `seq` cursor, targeted
/// `plugin:<source>` — so `GET /logs` needs no second cursor and the console needs no second poll.
#[utoipa::path(
post,
path = "/plugins/logs",
tag = "plugins",
operation_id = "ingestPluginLogs",
request_body = PluginLogBatch,
responses(
(status = NO_CONTENT, description = "Lines ingested"),
(status = BAD_REQUEST, description = "Batch too large", body = ApiError),
(status = UNAUTHORIZED, description = "Missing or invalid bearer token", body = ApiError),
)
)]
pub(crate) async fn ingest_plugin_logs(ApiJson(batch): ApiJson<PluginLogBatch>) -> Response {
if batch.entries.len() > MAX_LOG_BATCH {
return api_error(
StatusCode::BAD_REQUEST,
&format!("at most {MAX_LOG_BATCH} entries per batch"),
);
}
for line in batch.entries {
crate::log_capture::ring().push_remote(
&line.level,
&log_target(&line.source),
&sanitize_msg(&line.msg),
line.ts_ms,
);
}
StatusCode::NO_CONTENT.into_response()
}
/// Strip control characters from an ingested message, keeping tabs.
///
/// Same reasoning as [`sanitize`], one exception wider: a plugin's messages routinely carry a
/// stack trace or a vendor CLI's output, and an embedded newline would let one line forge several
/// in the downloaded log file. Tabs survive because they are load-bearing in that kind of output.
fn sanitize_msg(s: &str) -> String {
s.chars()
.map(|c| if c == '\t' || !c.is_control() { c } else { ' ' })
.collect::<String>()
.trim_end()
.to_string()
}
/// List registered plugins
///
/// The live plugin directory (lease not expired), sorted by title. **Secret-free**: each entry
+70
View File
@@ -620,6 +620,23 @@ async fn plugin_token_lane_is_scoped_and_loopback_only() {
StatusCode::NO_CONTENT
);
// Log ingest. This is the ONLY token the scripting runner holds (on Windows its LocalService
// principal cannot even read the admin one), so if this lane ever stopped reaching this route
// the console's plugin logs would go quiet with nothing else failing — pin it here rather than
// rely on `plugin_may_access`'s denylist continuing to not match `/plugins/logs`.
let body = serde_json::json!({"entries": [{
"ts_ms": 1_700_000_000_000u64,
"level": "INFO",
"source": "virtualhere",
"msg": "hello from the runner",
}]});
let req = axum::http::Request::post("/api/v1/plugins/logs")
.header("content-type", "application/json")
.header("authorization", "Bearer plugin-secret")
.body(Body::from(body.to_string()))
.unwrap();
assert_eq!(send(&app, req).await.0, StatusCode::NO_CONTENT);
// The carve-outs answer 403 (authenticated but not authorized), not 401.
for (method, path) in [
(Method::GET, "/api/v1/hooks"),
@@ -972,6 +989,59 @@ async fn plugin_registry_roundtrip() {
assert_eq!(status, StatusCode::BAD_REQUEST);
}
/// Runner log ingest: lines reach the same ring `GET /logs` serves, tagged so the console can tell
/// them from the host's own, and one chatty plugin can't evict the ring in a single request.
#[tokio::test]
async fn plugin_log_ingest_lands_in_the_ring() {
let app = test_app(test_state(), None);
let marker = "vh-ingest-marker-3f9a";
let (status, _) = send(
&app,
post_json(
"/api/v1/plugins/logs",
serde_json::json!({"entries": [
{"ts_ms": 1_700_000_000_123u64, "level": "warn", "source": "virtualhere", "msg": marker},
// No source: attributed to the runner rather than to nothing.
{"ts_ms": 1_700_000_000_124u64, "level": "NOTICE", "source": "", "msg": "orphan"},
]}),
),
)
.await;
assert_eq!(status, StatusCode::NO_CONTENT);
let (status, body) = send(&app, get_req("/api/v1/logs?limit=1000")).await;
assert_eq!(status, StatusCode::OK);
let entries = body["entries"].as_array().unwrap();
let mine = entries
.iter()
.find(|e| e["msg"] == marker)
.expect("ingested line is served by GET /logs");
// `plugin:` is what the console's Host/Plugins filter keys on.
assert_eq!(mine["target"], "plugin:virtualhere");
// Lowercase in, canonical out — the console ranks these five and nothing else.
assert_eq!(mine["level"], "WARN");
// Stamped when the line happened, not when the batch arrived.
assert_eq!(mine["ts_ms"], 1_700_000_000_123u64);
let orphan = entries.iter().find(|e| e["msg"] == "orphan").unwrap();
assert_eq!(orphan["target"], "plugin:runner");
// An unranked level would sort as 0 in the console's filter and hide under every setting.
assert_eq!(orphan["level"], "INFO");
// An oversized batch is refused whole rather than half-ingested.
let big: Vec<serde_json::Value> = (0..300)
.map(|i| serde_json::json!({"ts_ms": 1u64, "level": "INFO", "source": "x", "msg": format!("f{i}")}))
.collect();
let (status, _) = send(
&app,
post_json("/api/v1/plugins/logs", serde_json::json!({"entries": big})),
)
.await;
assert_eq!(status, StatusCode::BAD_REQUEST);
}
/// The OpenAPI document lists every route with a unique operationId (codegen relies
/// on both), and the checked-in copy is current.
#[test]
+33 -2
View File
@@ -295,8 +295,23 @@ installer's `PATH` change, or call the exe by full path. On Linux the host packa
On SteamOS, re-run `scripts/steamdeck/install.sh` (or
`scripts/steamdeck/update.sh`). On Windows, re-run the installer and keep the scripting component.
**The plugin doesn't show up in the console** — check the runner is actually running with
`punktfunk-host plugins status`, then look at its log:
**Where a plugin's log output goes** — the console's **Logs** page, under the **Plugins** filter.
The runner ships everything your plugins print to the host, so a plugin's own lines sit next to the
host's, on one timeline, with the same search and download. Each is tagged `plugin:<name>` — the
plugin's own name for lines it logged itself, `plugin:runner` for the supervisor's (starting a
plugin, restarting a crashed one, refusing an unsafe file).
An empty Plugins view almost always means the runner isn't running — it is a separate service, and
opt-in on Linux. Check with `punktfunk-host plugins status`.
<Callout>
Nothing is lost if the host is down: the runner keeps buffering and sends the backlog when the host
comes back. It says so in the log if the buffer overflowed, rather than presenting a gap as
continuity.
</Callout>
**Reading the runner's log directly** — rarely needed now, but it is the ground truth if the runner
can't reach the host at all:
<Tabs items={['Linux', 'Windows']}>
<Tab value="Linux">
@@ -318,6 +333,22 @@ plugins (stop it with <kbd>Ctrl</kbd>+<kbd>C</kbd>):
</Tab>
</Tabs>
**A plugin can't reach a service running on the same box (Linux)** — plugins that drive a local
daemon usually talk to it over a socket or FIFO in `/tmp`. The runner's unit shipped with
`PrivateTmp=yes` in earlier releases, which gave it a private `/tmp` and hid all of it: the plugin would
launch the vendor's binary happily and then time out reaching the daemon behind it, while the same
command worked perfectly in your own shell. If you are on an older host, or you have a drop-in that
reinstates it, put the real `/tmp` back:
```sh
systemctl --user edit punktfunk-scripting
```
```ini
[Service]
PrivateTmp=no
ReadWritePaths=/tmp
```
## Writing your own
A plugin is a TypeScript module built on **`@punktfunk/plugin-kit`** (`definePluginKit`), supervised
+4 -1
View File
@@ -360,7 +360,10 @@ Read the host's log around the failed connect or capture.
1. Open the web console's **Logs** page. It always holds the host's recent output at *debug* detail,
whatever the log level is set to — there's nothing to switch on and no restart needed.
2. Filter it down to the level or the text you're after.
2. Filter it down to the level or the text you're after. The **Host / Plugins** switch beside the
level buttons picks the producer: your [plugins](/docs/plugins) log to the same page, tagged
`plugin:<name>`, so a misbehaving plugin is one click away rather than a separate hunt through
the journal.
3. Use **Download logs** to save exactly what you're filtering on as a timestamped `.log` file you
can attach to a bug report. The button beside it hands the same text to your phone or tablet's
share sheet, or copies it to the clipboard on a desktop.
+3 -2
View File
@@ -107,8 +107,9 @@ Nine destinations in the sidebar (a **More** tab on a phone holds the last five)
title with its own art and launch command. See [Your game library](/docs/game-library).
- **Performance** — arm a capture, run a session, stop it, and read the recording back as
per-stage latency, throughput and health graphs.
- **Logs** — the host's recent log stream: follow it live, filter by level, search it, and download
or share it for a bug report.
- **Logs** — the host's recent log stream *and your plugins'*: follow it live, filter by level or
producer, search it, and download or share it for a bug report. Plugin lines are tagged
`plugin:<name>` and the **Host / Plugins** switch isolates either side.
- **Pairing** — arm a PIN, approve or deny devices waiting for approval, and unpair a device. A
second PIN box for [Moonlight/GameStream](/docs/moonlight) clients appears only when this host
runs the GameStream plane.
+15 -7
View File
@@ -33,16 +33,24 @@ KillSignal=SIGTERM
TimeoutStopSec=30
# Sandbox: free hardening for well-behaved plugins. The filesystem is read-only outside the home
# directory (ReadWritePaths keeps plugin state, download dirs, and ~/.config/punktfunk writable);
# /tmp is private; no setuid re-escalation; sockets limited to what automation actually uses
# (loopback mgmt API, LAN/IPv6 webhooks, unix sockets). A plugin that must write OUTSIDE $HOME
# (e.g. a library on another mount) gets a drop-in:
# no setuid re-escalation; sockets limited to what automation actually uses (loopback mgmt API,
# LAN/IPv6 webhooks, unix sockets). A plugin that must write OUTSIDE $HOME (e.g. a library on
# another mount) gets a drop-in:
# systemctl --user edit punktfunk-scripting → [Service]\nReadWritePaths=/mnt/games
# NOTE: the mount-namespace options (ProtectSystem/PrivateTmp) need unprivileged user namespaces
# for a *user* unit; on kernels/distros that restrict those, drop them via the same drop-in.
# NOTE: the mount-namespace options (ProtectSystem) need unprivileged user namespaces for a
# *user* unit; on kernels/distros that restrict those, drop them via the same drop-in.
#
# PrivateTmp is deliberately OFF (field report 2026-08-03, the VirtualHere plugin). A plugin's
# whole job is integrating with things already running on this box, and on Linux those talk over
# /tmp: VirtualHere's client IPC is the FIFO pair /tmp/vhclient + /tmp/vhclient_response, and X11
# is /tmp/.X11-unix. A private /tmp namespace hides all of it — the plugin launches the vendor
# binary fine and then cannot reach the daemon behind it, which presents as an unexplained error
# that no amount of config fixes (the operator's own shell works, because that has the real /tmp).
# ReadWritePaths=/tmp puts the write bit back that ProtectSystem=strict takes away.
NoNewPrivileges=yes
PrivateTmp=yes
PrivateTmp=no
ProtectSystem=strict
ReadWritePaths=%h
ReadWritePaths=%h /tmp
RestrictAddressFamilies=AF_UNIX AF_INET AF_INET6
[Install]
File diff suppressed because one or more lines are too long
+287
View File
@@ -0,0 +1,287 @@
// The runner's log door into the web console (field report 2026-08-03, the VirtualHere plugin).
//
// WHY THIS EXISTS: plugins are not host child processes. The runner is a separate bun process that
// `import()`s each plugin in-process, so a plugin's output is THIS process's stdout and the host's
// `tracing` ring — the thing `GET /api/v1/logs` and the console's Logs page serve — never sees a
// byte of it. On Linux the fallback was `journalctl --user -u punktfunk-scripting`; on Windows the
// runner scheduled task writes no log file AT ALL, so a failing plugin could only be diagnosed by
// stopping the task and re-running the runner by hand. Both need shell access on the host box,
// which is the exact thing the console exists to avoid. A user hitting a plugin misconfiguration
// therefore had no way to see the error explaining it.
//
// So: tee every console line to `POST /api/v1/plugins/logs`, which lands it in the host's ring
// alongside the host's own lines under the target `plugin:<source>`.
//
// Design rules this file will not break:
// - **stdout stays authoritative.** The original console method is called FIRST and always, so
// journald/foreground output is unchanged whatever the host is doing. Shipping is additive.
// - **Never recurse.** Nothing on the shipping path may log through the patched console; a failed
// POST that logged its own failure would enqueue that line, fail again, and spin.
// - **Never throw into a caller.** `console.log` is not allowed to fail because the host is down.
// - **Bounded.** The queue has a hard cap and drops its OLDEST lines, then says how many — an
// unreachable host must not turn the runner into a memory leak.
import { format } from "node:util";
import { type ConnectOptions, resolveConfig } from "./config.js";
/** The level a console method implies when a line carries no level of its own. */
const LEVEL_BY_METHOD = {
log: "INFO",
info: "INFO",
debug: "DEBUG",
warn: "WARN",
error: "ERROR",
} as const;
type Method = keyof typeof LEVEL_BY_METHOD;
const METHODS = Object.keys(LEVEL_BY_METHOD) as Method[];
/**
* `<ISO> [<source>] [LEVEL:] <message>` the line format `plugin-kit`'s `loggingLayer` and this
* package's `runner.ts` both emit. Parsing it back recovers the plugin name and level that the
* formatting flattened, so the console can show `plugin:virtualhere` / `WARN` instead of one
* undifferentiated `runner` stream.
*
* A line that does NOT match is still shipped attributed to `runner` at the console method's own
* level. A plugin calling bare `console.error("boom")` is precisely the case this must not lose.
*/
const STAMPED =
/^(\d{4}-\d{2}-\d{2}T[\d:.]+Z) \[([^\]\n]{1,64})\](?:[ \t]+([A-Z]{3,9}):)?[ \t]?([\s\S]*)$/;
/** Lines per POST. Must stay ≤ the host's `MAX_LOG_BATCH` or a batch is rejected wholesale. */
const BATCH = 256;
/** Queued lines before the oldest start dropping. ~2 MB worst case at the host's 2 KB cap. */
const QUEUE_LIMIT = 1000;
/** A multi-line message (a stack trace) ships as one entry per line, capped here. */
const MAX_LINES_PER_MESSAGE = 40;
export interface LogShipperOptions {
/** Connection overrides. Defaults to the same zero-config resolution `connect()` uses. */
connect?: ConnectOptions;
/** Flush cadence in ms (default 2000). */
intervalMs?: number;
}
export interface LogShipper {
/** Send whatever is queued right now. Never rejects. */
flush: () => Promise<void>;
/** Restore the original console methods and stop the timer. */
stop: () => void;
}
interface Line {
ts_ms: number;
level: string;
source: string;
msg: string;
}
/**
* Split a rendered console call into shippable lines.
*
* Newlines become separate entries rather than one blob: the log viewer is line-oriented, and the
* payload that matters most here an Effect `Cause.pretty` stack from a plugin that failed to
* start is unreadable folded onto a single row. The cap keeps one pathological dump from
* evicting the ring on its own.
*/
const toLines = (method: Method, args: unknown[]): Line[] => {
const text = format(...args);
const m = STAMPED.exec(text);
const source = m?.[2] ?? "runner";
const level = m?.[3] ?? LEVEL_BY_METHOD[method];
const parsedTs = m?.[1] !== undefined ? Date.parse(m[1]) : Number.NaN;
const ts_ms = Number.isNaN(parsedTs) ? Date.now() : parsedTs;
const body = m?.[4] ?? text;
const parts = body.split(/\r?\n/);
const kept = parts.slice(0, MAX_LINES_PER_MESSAGE);
if (parts.length > kept.length) {
kept.push(`${parts.length - kept.length} more line(s) suppressed`);
}
// A trailing newline yields one empty part; an all-empty message still ships one entry so the
// console never silently swallows a call.
const meaningful = kept.filter((l) => l.trim() !== "");
return (meaningful.length > 0 ? meaningful : [""]).map((msg) => ({
ts_ms,
level,
source,
msg,
}));
};
/**
* Patch the console to tee into the host's log ring, and start the flush timer.
*
* Install this ONLY in the managed runner (`runner-cli.ts`). A plugin's own CLI (`punktfunk-plugin-x
* doctor`) must keep its output local — an operator running a diagnostic in their terminal is not
* asking to write to the host's log.
*/
export const installLogShipper = (
options: LogShipperOptions = {},
): LogShipper => {
const queue: Line[] = [];
let droppedByOverflow = 0;
// True from the moment a flush claims a batch until its POST settles. Guards flush RE-ENTRY
// only — the interval can fire while a slow POST is still open, and two concurrent flushes
// would splice disjoint batches out of one queue and deliver them out of order.
//
// It deliberately does NOT gate `enqueue`. It used to, as a recursion guard, and that silently
// dropped every line logged during the few ms of a POST — which under load is a great many of
// them, and exactly the lines a busy plugin is producing. The recursion it was guarding is
// handled by the rule at the top of this file instead: nothing on the shipping path logs.
let shipping = false;
let stopped = false;
// Set once the host's URL/token/CA resolve. Before that (the host writes `plugin-token` as it
// boots, and the runner may well start first) lines keep queueing — those earliest lines are
// exactly the ones that explain a plugin failing to load.
let resolved: Awaited<ReturnType<typeof resolveConfig>> | undefined;
let resolving = false;
// Consecutive failures, for backoff. The host being down is normal (restart, update) and must
// not mean a POST attempt every 2 s forever.
let failures = 0;
let skipTicks = 0;
// The ORIGINAL function objects, unbound. `stop()` must put back exactly what it found: binding
// here and restoring the bound copy would leave a different function in place each cycle, so
// an install/stop/install sequence accumulates a wrapper per round. Calls go through `.call`
// below to keep `this` right without touching identity.
const original = Object.fromEntries(METHODS.map((m) => [m, console[m]])) as Record<
Method,
(...args: unknown[]) => void
>;
const enqueue = (method: Method, args: unknown[]) => {
if (stopped) return;
try {
for (const line of toLines(method, args)) {
if (queue.length >= QUEUE_LIMIT) {
queue.shift();
droppedByOverflow += 1;
}
queue.push(line);
}
} catch {
// Formatting a hostile object must never break the caller's console call.
}
};
for (const method of METHODS) {
console[method] = ((...args: unknown[]) => {
original[method].call(console, ...args);
enqueue(method, args);
}) as typeof console.log;
}
const ensureResolved = async (): Promise<boolean> => {
if (resolved) return true;
if (resolving) return false;
resolving = true;
try {
resolved = await resolveConfig(options.connect);
return true;
} catch {
// No token yet (or no host at all). Keep buffering and try again next tick.
return false;
} finally {
resolving = false;
}
};
/** Put a failed batch back at the FRONT, still honoring the cap (oldest lose). */
const requeue = (batch: Line[]) => {
queue.unshift(...batch);
if (queue.length > QUEUE_LIMIT) {
droppedByOverflow += queue.length - QUEUE_LIMIT;
queue.splice(0, queue.length - QUEUE_LIMIT);
}
};
const flush = async (): Promise<void> => {
if (stopped || shipping || queue.length === 0) return;
if (!(await ensureResolved()) || !resolved) return;
// Re-check after the await: `ensureResolved` yields, so another flush may have claimed the
// queue in the meantime.
if (stopped || shipping || queue.length === 0) return;
shipping = true;
const batch = queue.splice(0, BATCH);
if (droppedByOverflow > 0) {
// Tell the operator the tail is incomplete rather than presenting a gap as continuity —
// the same contract the host's ring keeps with its `dropped` flag.
batch.unshift({
ts_ms: Date.now(),
level: "WARN",
source: "runner",
msg: `log shipper dropped ${droppedByOverflow} line(s): the queue filled while the host was unreachable`,
});
droppedByOverflow = 0;
}
try {
const res = await resolved.fetch(`${resolved.url}/api/v1/plugins/logs`, {
method: "POST",
headers: {
"content-type": "application/json",
authorization: `Bearer ${resolved.token}`,
},
body: JSON.stringify({ entries: batch }),
});
if (!res.ok) {
// 4xx is our bug (a shape the host rejects) and retrying cannot fix it — drop the
// batch. 5xx/transport is the host's problem and worth keeping.
if (res.status >= 500) requeue(batch);
// A token that went stale (host re-keyed) resolves again from disk on the next tick.
if (res.status === 401) resolved = undefined;
failures += 1;
} else {
failures = 0;
}
} catch {
requeue(batch);
failures += 1;
} finally {
shipping = false;
// 2 s, 4 s, 8 s … capped at ~30 s while the host stays away.
skipTicks = failures === 0 ? 0 : Math.min(2 ** (failures - 1), 15);
}
};
// The most recent flush, so an explicit `flush()` can WAIT for a periodic one rather than hit
// the re-entry guard and return having sent nothing. That matters on the shutdown path: the
// runner flushes once more after its units' finalizers have run, and those last lines are the
// ones that say whether the shutdown was clean. The window is widest exactly when the host is
// slow — which is when the logs are worth most.
let inFlight: Promise<void> = Promise.resolve();
const runFlush = (): Promise<void> => {
inFlight = flush();
return inFlight;
};
const timer = setInterval(() => {
if (skipTicks > 0) {
skipTicks -= 1;
return;
}
void runFlush();
}, options.intervalMs ?? 2_000);
// The runner parks on its own keep-alive handle; this timer must not be what holds the process
// open, or a runner with nothing to run would never exit.
timer.unref?.();
return {
flush: async () => {
skipTicks = 0;
// `flush` never rejects (every path is caught); `.catch` only keeps that a guarantee.
await inFlight.catch(() => {});
await runFlush();
},
stop: () => {
stopped = true;
clearInterval(timer);
for (const method of METHODS) {
console[method] = original[method] as typeof console.log;
}
},
};
};
/** Exported for tests. */
export const __test = { toLines, STAMPED };
+17 -2
View File
@@ -22,6 +22,7 @@
// plugin store (crates/punktfunk-host/src/store), which installs one reviewed version of a
// package that may live on somebody else's registry — but they are ordinary CLI flags too.
import { Effect, Fiber } from "effect";
import { installLogShipper } from "./log-ship.js";
import { addPlugins, listInstalled, removePlugins } from "./plugins.js";
import { discoverUnits, runner } from "./runner.js";
@@ -157,16 +158,30 @@ if (process.argv.includes("--list")) {
// nothing at all: field report 2026-07-25 had it pinning a full core indefinitely, `strace`
// showing a bare `clock_gettime` loop and nothing else. One idle handle is the whole fix.
const keepAlive = setInterval(() => {}, 2 ** 31 - 1);
// Tee this process's output to the host so the console's Logs page can show it. Installed HERE and
// not in `runner.ts`, so it covers the supervised run only: a plugin's own CLI builds the same
// layer graph, and an operator running `punktfunk-plugin-x doctor` in their terminal is not asking
// to write into the host's log. Must be installed before the runner starts — the lines that explain
// a plugin failing to load are the first ones out.
const shipper = installLogShipper();
const fiber = Effect.runFork(runner(options));
let stopping = false;
const shutdown = (signal: string) => {
if (stopping) return process.exit(1); // second signal = get out now
stopping = true;
console.log(`${new Date().toISOString()} [runner] ${signal} — interrupting units…`);
void Effect.runPromise(Fiber.interrupt(fiber)).finally(() => process.exit(0));
void Effect.runPromise(Fiber.interrupt(fiber))
// Ship what the finalizers just said before the process goes away — a clean shutdown's
// last lines are the ones that tell you whether it WAS clean.
.finally(() => shipper.flush())
.finally(() => process.exit(0));
};
process.on("SIGINT", () => shutdown("SIGINT"));
process.on("SIGTERM", () => shutdown("SIGTERM"));
await Effect.runPromise(Fiber.await(fiber));
clearInterval(keepAlive); // every unit ended on its own — let the process exit
await shipper.flush(); // every unit ended on its own — don't leave their last lines unsent
shipper.stop();
clearInterval(keepAlive); // …then let the process exit
+39 -13
View File
@@ -41,10 +41,24 @@ export interface RunnerOptions {
connect?: ConnectOptions;
/** Restart backoff base (test seam). Default 1 s, capped at 60 s, jittered. */
restartBase?: Duration.Input;
/** Line sink. Default: stamped stdout. */
log?: (line: string) => void;
/**
* Line sink. Default: stamped stdout, with `warn`/`error` going to the matching console method
* (hence stderr, and hence the right level in the console's log page see `log-ship.ts`).
*
* `level` is optional so an existing `(line: string) => void` sink stays assignable.
*/
log?: (line: string, level?: RunnerLogLevel) => void;
}
/**
* Severity of a runner line. Only three, because that is all the runner distinguishes: it is
* reporting on units, not producing application logs.
*/
export type RunnerLogLevel = "info" | "warn" | "error";
/** The sink shape used internally, with the level always supplied by the caller's default. */
type LogSink = (line: string, level?: RunnerLogLevel) => void;
export interface Unit {
/** Display name: the file stem, or the plugin package name. */
name: string;
@@ -52,8 +66,12 @@ export interface Unit {
file: string;
}
const defaultLog = (line: string) =>
console.log(`${new Date().toISOString()} ${line}`);
const defaultLog: LogSink = (line, level = "info") => {
const stamped = `${new Date().toISOString()} ${line}`;
if (level === "error") console.error(stamped);
else if (level === "warn") console.warn(stamped);
else console.log(stamped);
};
// ---- unit-file trust (the sshd rule, both halves) ---------------------------------------------
@@ -225,7 +243,7 @@ const windowsPowershellEnv = (): Record<string, string | undefined> => {
};
/** Read a file's SDDL and apply [`windowsSddlUnsafeReason`]. Unreadable ACL ⇒ refuse. */
const windowsFileIsSafe = (file: string, log: (l: string) => void): boolean => {
const windowsFileIsSafe = (file: string, log: LogSink): boolean => {
const escaped = file.replace(/'/g, "''");
const res = spawnSync(
windowsPowershell(),
@@ -244,7 +262,7 @@ const windowsFileIsSafe = (file: string, log: (l: string) => void): boolean => {
);
const sddl = res.status === 0 ? (res.stdout ?? "").trim() : "";
if (!sddl) {
log(`[runner] REFUSING ${file} — could not read its ACL`);
log(`[runner] REFUSING ${file} — could not read its ACL`, "error");
return false;
}
const reason = windowsSddlUnsafeReason(sddl, processSid());
@@ -253,6 +271,7 @@ const windowsFileIsSafe = (file: string, log: (l: string) => void): boolean => {
`[runner] REFUSING ${file}${reason}. Reinstall the plugin with ` +
`\`punktfunk-host plugins add\`, or re-own the file to Administrators and strip ` +
`non-admin write ACEs (icacls).`,
"error",
);
return false;
}
@@ -264,13 +283,14 @@ const windowsFileIsSafe = (file: string, log: (l: string) => void): boolean => {
* could have written group/world-writable mode on Unix; on Windows, an owner outside
* SYSTEM/Administrators/TrustedInstaller or a write-capable ACE for a non-admin principal.
*/
const fileIsSafe = (file: string, log: (l: string) => void): boolean => {
const fileIsSafe = (file: string, log: LogSink): boolean => {
if (process.platform === "win32") return windowsFileIsSafe(file, log);
try {
const mode = fs.statSync(file).mode & 0o022;
if (mode !== 0) {
log(
`[runner] REFUSING ${file} — group/world-writable (chmod go-w it first)`,
"error",
);
return false;
}
@@ -285,7 +305,7 @@ const SCRIPT_EXTENSIONS = new Set([".ts", ".js", ".mjs", ".mts", ".cjs"]);
/** Enumerate the operator's units: loose scripts plus installed plugin packages. */
export const discoverUnits = (
options: RunnerOptions = {},
log: (l: string) => void = options.log ?? defaultLog,
log: LogSink = options.log ?? defaultLog,
): Unit[] => {
const units: Unit[] = [];
const scriptsDir = options.scriptsDir ?? path.join(configDir(), "scripts");
@@ -332,7 +352,7 @@ export const discoverUnits = (
if (!fileIsSafe(file, log)) return;
units.push({ name, file });
} catch (e) {
log(`[runner] skipping ${name}: unreadable package.json (${e})`);
log(`[runner] skipping ${name}: unreadable package.json (${e})`, "warn");
}
};
try {
@@ -379,7 +399,7 @@ const attemptUnit = (
unit: Unit,
attempt: number,
options: RunnerOptions,
log: (l: string) => void,
log: LogSink,
): Effect.Effect<"plugin" | "script", unknown> =>
Effect.gen(function* () {
const mod = (yield* Effect.tryPromise(
@@ -431,7 +451,8 @@ export const superviseUnit = (
let attempt = 0;
const once = Effect.suspend(() => {
attempt += 1;
if (attempt > 1) log(`[${unit.name}] restarting (attempt ${attempt})`);
if (attempt > 1)
log(`[${unit.name}] restarting (attempt ${attempt})`, "warn");
return attemptUnit(unit, attempt, options, log);
});
return once.pipe(
@@ -446,13 +467,18 @@ export const superviseUnit = (
),
Effect.tapCause((cause) =>
Effect.sync(() =>
log(`[${unit.name}] failed: ${Cause.pretty(cause).split("\n")[0]}`),
log(
`[${unit.name}] failed: ${Cause.pretty(cause).split("\n")[0]}`,
"error",
),
),
),
Effect.retry(restart),
Effect.catchCause((cause) =>
// A retry schedule that gives up (it doesn't, but stay total) — log and end.
Effect.sync(() => log(`[${unit.name}] gave up: ${Cause.pretty(cause)}`)),
Effect.sync(() =>
log(`[${unit.name}] gave up: ${Cause.pretty(cause)}`, "error"),
),
),
Effect.asVoid,
);
+329
View File
@@ -0,0 +1,329 @@
// The log shipper's contract: what it recovers from a formatted line, that it tees rather than
// swallows, that a POST failure neither loses lines nor spins, and that it stays bounded.
import { afterEach, describe, expect, test } from "bun:test";
import { __test, installLogShipper } from "../src/log-ship.js";
const { toLines } = __test;
const TOKEN = "ship-token";
interface Captured {
entries: { ts_ms: number; level: string; source: string; msg: string }[];
}
/** A host that records every batch, answering with whatever `status()` says. */
const mockHost = (status: () => number = () => 204) => {
const batches: Captured[] = [];
const auth: (string | null)[] = [];
const server = Bun.serve({
port: 0,
fetch: async (req) => {
const url = new URL(req.url);
if (url.pathname !== "/api/v1/plugins/logs") {
return new Response("not found", { status: 404 });
}
auth.push(req.headers.get("authorization"));
batches.push((await req.json()) as Captured);
const s = status();
return new Response(s === 204 ? null : "nope", { status: s });
},
});
return {
batches,
auth,
url: `http://127.0.0.1:${server.port}`,
stop: () => server.stop(true),
};
};
/**
* Run `body` with a shipper installed, always restoring the console.
*
* The console is swapped for a recorder BEFORE the shipper installs, so `seen` is what the shipper
* teed through to "stdout" and the suite stays readable, since a test that logs 2000 lines would
* otherwise print all 2000.
*/
const withShipper = async <T>(
url: string,
body: (
s: ReturnType<typeof installLogShipper>,
seen: string[],
) => Promise<T>,
): Promise<T> => {
const seen: string[] = [];
const real = { log: console.log, warn: console.warn, error: console.error };
const record = (...a: unknown[]) => {
seen.push(String(a[0]));
};
console.log = record;
console.warn = record;
console.error = record;
const shipper = installLogShipper({
connect: { url, token: TOKEN },
// Long enough that only explicit flushes fire — the tests drive the timing.
intervalMs: 60_000,
});
try {
return await body(shipper, seen);
} finally {
shipper.stop();
console.log = real.log;
console.warn = real.warn;
console.error = real.error;
}
};
describe("parsing a formatted line", () => {
test("recovers the plugin name and timestamp plugin-kit's format flattened", () => {
const [line] = toLines(
"log",
["2026-08-03T10:11:12.345Z [virtualhere] holding nothing"],
);
expect(line?.source).toBe("virtualhere");
expect(line?.level).toBe("INFO");
expect(line?.msg).toBe("holding nothing");
expect(line?.ts_ms).toBe(Date.parse("2026-08-03T10:11:12.345Z"));
});
test("an explicit level in the line beats the console method", () => {
// plugin-kit renders Effect's level verbatim — "WARNING", not "WARN". The host coerces it.
const [line] = toLines("log", [
"2026-08-03T10:11:12.345Z [virtualhere] WARNING: vhclient failed (ETIMEDOUT)",
]);
expect(line?.level).toBe("WARNING");
expect(line?.msg).toBe("vhclient failed (ETIMEDOUT)");
});
test("the runner's own error lines keep their severity", () => {
const [line] = toLines("error", [
"2026-08-03T10:11:12.345Z [virtualhere] failed: VhIpcError: no such binary",
]);
expect(line?.source).toBe("virtualhere");
expect(line?.level).toBe("ERROR");
});
test("an unstamped call is kept, not dropped", () => {
// A plugin reaching for bare console.error is exactly the case that must not be lost.
const [line] = toLines("error", ["boom", { code: 7 }]);
expect(line?.source).toBe("runner");
expect(line?.level).toBe("ERROR");
expect(line?.msg).toContain("boom");
expect(line?.msg).toContain("7");
});
test("a multi-line message becomes one entry per line", () => {
const lines = toLines("log", [
"2026-08-03T10:11:12.345Z [x] failed\n at foo\n at bar",
]);
expect(lines.map((l) => l.msg)).toEqual(["failed", " at foo", " at bar"]);
// Every fragment keeps the original stamp, so the trace cannot interleave with other units.
expect(new Set(lines.map((l) => l.ts_ms)).size).toBe(1);
});
test("a pathological dump is capped and says so", () => {
const lines = toLines("log", [
`2026-08-03T10:11:12.345Z [x] ${"line\n".repeat(200)}`,
]);
expect(lines.length).toBeLessThanOrEqual(41);
expect(lines.at(-1)?.msg).toContain("more line(s) suppressed");
});
});
describe("shipping", () => {
let stopHost: (() => void) | undefined;
afterEach(() => {
stopHost?.();
stopHost = undefined;
});
test("tees: stdout still gets the line, and the host gets it too", async () => {
const host = mockHost();
stopHost = host.stop;
const seen = await withShipper(host.url, async (shipper, seen) => {
console.log("2026-08-03T10:11:12.345Z [virtualhere] hello");
await shipper.flush();
return seen;
});
// The original console still ran — journald/foreground output is never traded away.
expect(seen).toEqual(["2026-08-03T10:11:12.345Z [virtualhere] hello"]);
expect(host.batches).toHaveLength(1);
expect(host.batches[0]?.entries[0]).toMatchObject({
source: "virtualhere",
level: "INFO",
msg: "hello",
});
expect(host.auth[0]).toBe(`Bearer ${TOKEN}`);
});
test("a 5xx keeps the lines for the next flush", async () => {
let status = 500;
const host = mockHost(() => status);
stopHost = host.stop;
await withShipper(host.url, async (shipper) => {
console.log("2026-08-03T10:11:12.345Z [x] keep me");
await shipper.flush();
expect(host.batches).toHaveLength(1);
status = 204;
await shipper.flush();
});
// Re-sent rather than dropped: the host being down is not the line's fault.
expect(host.batches).toHaveLength(2);
expect(host.batches[1]?.entries[0]?.msg).toBe("keep me");
});
test("a 4xx drops the batch instead of retrying forever", async () => {
const host = mockHost(() => 400);
stopHost = host.stop;
await withShipper(host.url, async (shipper) => {
console.log("2026-08-03T10:11:12.345Z [x] malformed");
await shipper.flush();
await shipper.flush();
});
// A shape the host rejects cannot be fixed by sending it again.
expect(host.batches).toHaveLength(1);
});
test("a line logged WHILE a POST is in flight is not lost", async () => {
// A plugin logging during the few ms of a POST is the normal case under load, not an edge
// one. An earlier version held a `shipping` flag across the whole `await fetch` and dropped
// everything enqueued in that window — silently, which is the worst way to lose a log line.
let release: (() => void) | undefined;
const held = new Promise<void>((r) => {
release = r;
});
let arrived: (() => void) | undefined;
// Resolves once the server actually has the request — i.e. the shipper is genuinely mid-POST.
// Logging merely "after calling flush()" proves nothing: flush yields at its own awaits long
// before the fetch starts, so the line would land in the pre-send queue and the test would
// pass against the broken code.
const received = new Promise<void>((r) => {
arrived = r;
});
const batches: Captured[] = [];
const server = Bun.serve({
port: 0,
fetch: async (req) => {
batches.push((await req.json()) as Captured);
arrived?.();
await held; // hold this POST open
return new Response(null, { status: 204 });
},
});
stopHost = () => server.stop(true);
await withShipper(`http://127.0.0.1:${server.port}`, async (shipper) => {
console.log("2026-08-03T10:11:12.345Z [x] before");
const inFlight = shipper.flush();
await received;
// The POST is open right now; this is the line that used to vanish.
console.log("2026-08-03T10:11:12.345Z [x] during");
release?.();
await inFlight;
await shipper.flush();
});
const all = batches.flatMap((b) => b.entries.map((e) => e.msg));
expect(all).toContain("before");
expect(all).toContain("during");
});
test("an explicit flush waits for an in-flight one instead of no-opping", async () => {
// This is the shutdown path. The runner flushes once more after its units' finalizers have
// run, and those last lines are the ones that say whether the shutdown WAS clean. If a
// periodic flush happened to be mid-POST, an explicit flush that simply returned would
// leave them unsent — and the window is widest exactly when the host is slow, which is when
// the logs matter most.
let release: (() => void) | undefined;
const held = new Promise<void>((r) => {
release = r;
});
let arrived: (() => void) | undefined;
const received = new Promise<void>((r) => {
arrived = r;
});
let first = true;
const batches: Captured[] = [];
const server = Bun.serve({
port: 0,
fetch: async (req) => {
batches.push((await req.json()) as Captured);
if (first) {
first = false;
arrived?.();
await held;
}
return new Response(null, { status: 204 });
},
});
stopHost = () => server.stop(true);
await withShipper(`http://127.0.0.1:${server.port}`, async (shipper) => {
console.log("2026-08-03T10:11:12.345Z [x] first");
const slow = shipper.flush();
await received;
console.log("2026-08-03T10:11:12.345Z [x] shutdown line");
release?.();
// The shutdown flush: must not return until the tail is actually sent.
await shipper.flush();
await slow;
});
const all = batches.flatMap((b) => b.entries.map((e) => e.msg));
expect(all).toContain("shutdown line");
});
test("overlapping flushes do not double-send", async () => {
// The timer can fire while a slow POST is still open. Two concurrent flushes would splice
// disjoint batches out of one queue and deliver them out of order.
const host = mockHost();
stopHost = host.stop;
await withShipper(host.url, async (shipper) => {
console.log("2026-08-03T10:11:12.345Z [x] one");
await Promise.all([shipper.flush(), shipper.flush()]);
});
expect(host.batches).toHaveLength(1);
expect(host.batches[0]?.entries).toHaveLength(1);
});
test("an unreachable host neither throws into the caller nor grows without bound", async () => {
// Nothing listening on this port.
await withShipper("http://127.0.0.1:1", async (shipper) => {
for (let i = 0; i < 2_000; i++) {
console.log(`2026-08-03T10:11:12.345Z [x] line ${i}`);
}
// The whole point: console.log above must not have thrown, and flush must not reject.
await shipper.flush();
});
});
test("overflow is announced, not silently swallowed", async () => {
const host = mockHost();
stopHost = host.stop;
await withShipper(host.url, async (shipper) => {
// Overrun the 1000-line cap while the shipper has had no chance to drain.
for (let i = 0; i < 1_200; i++) {
console.log(`2026-08-03T10:11:12.345Z [x] line ${i}`);
}
await shipper.flush();
});
const first = host.batches[0]?.entries[0];
expect(first?.level).toBe("WARN");
expect(first?.msg).toContain("dropped");
// The tail is what survived — the oldest lines are the ones that went.
expect(host.batches[0]?.entries[1]?.msg).toBe("line 200");
});
test("stop() puts the real console back", async () => {
const host = mockHost();
stopHost = host.stop;
const before = console.log;
const shipper = installLogShipper({
connect: { url: host.url, token: TOKEN },
intervalMs: 60_000,
});
expect(console.log).not.toBe(before);
shipper.stop();
expect(console.log).toBe(before);
});
});
+5 -1
View File
@@ -319,7 +319,11 @@
"nav_stats": "Leistung",
"nav_logs": "Logs",
"logs_title": "Logs",
"logs_subtitle": "Der aktuelle Log-Stream des Hosts — live verfolgen, nach Level filtern, durchsuchen.",
"logs_subtitle": "Der aktuelle Log-Stream des Hosts und deiner Plugins — live verfolgen, nach Level filtern, durchsuchen.",
"logs_source_all": "Alle",
"logs_source_host": "Host",
"logs_source_plugins": "Plugins",
"logs_empty_plugins": "Noch keine Plugin-Ausgabe. Plugins loggen hier, sobald der Plugin-Runner läuft — prüfe `punktfunk-host plugins status`.",
"logs_follow": "Folgen",
"logs_pause": "Pause",
"logs_clear": "Leeren",
+5 -1
View File
@@ -319,7 +319,11 @@
"nav_stats": "Performance",
"nav_logs": "Logs",
"logs_title": "Logs",
"logs_subtitle": "The host's recent log stream — follow live, filter by level, search.",
"logs_subtitle": "The host's recent log stream, and your plugins' — follow live, filter by level, search.",
"logs_source_all": "All",
"logs_source_host": "Host",
"logs_source_plugins": "Plugins",
"logs_empty_plugins": "No plugin output yet. Plugins log here once the plugin runner is running — check `punktfunk-host plugins status`.",
"logs_follow": "Follow",
"logs_pause": "Pause",
"logs_clear": "Clear",
+47 -2
View File
@@ -38,6 +38,29 @@ const LEVEL_CLASS: Record<string, string> = {
const KEEP = 5_000; // accumulated entries (client memory bound)
const SHOW = 1_000; // rendered rows (DOM bound)
/**
* Producer filter. The ring carries the host's own `tracing` events AND whatever the plugin runner
* ships up (`POST /api/v1/plugins/logs`), the latter targeted `plugin:<name>`. Without this the two
* are interleaved with nothing but the target column to tell them apart, and "show me what my
* plugin said" the question that sends people to `journalctl` means knowing to type `plugin:`
* into the search box.
*/
const SOURCES = ["all", "host", "plugins"] as const;
type Source = (typeof SOURCES)[number];
/** The target prefix the host stamps on every runner-shipped line. */
const PLUGIN_TARGET_PREFIX = "plugin:";
const matchesSource = (target: string, source: Source): boolean =>
source === "all" ||
(source === "plugins") === target.startsWith(PLUGIN_TARGET_PREFIX);
const SOURCE_LABEL: Record<Source, () => string> = {
all: () => m.logs_source_all(),
host: () => m.logs_source_host(),
plugins: () => m.logs_source_plugins(),
};
/**
* Container: cursor-paged log polling. A non-empty page advances the cursor a new query key,
* so the next page fetches immediately and a backlog drains fast; an empty page leaves the key
@@ -177,6 +200,7 @@ export const LogsCard: FC<{
onRetry,
}) => {
const [minLevel, setMinLevel] = useState<MinLevel>("DEBUG");
const [source, setSource] = useState<Source>("all");
const [search, setSearch] = useState("");
const listRef = useRef<HTMLDivElement>(null);
@@ -186,11 +210,12 @@ export const LogsCard: FC<{
return entries.filter(
(e) =>
(RANK[e.level] ?? 0) >= min &&
matchesSource(e.target, source) &&
(q === "" ||
e.msg.toLowerCase().includes(q) ||
e.target.toLowerCase().includes(q)),
);
}, [entries, minLevel, search]);
}, [entries, minLevel, source, search]);
const visible = useMemo(() => matched.slice(-SHOW), [matched]);
const shareLabel = shareMode === "share" ? m.logs_share() : m.logs_copy();
@@ -233,6 +258,18 @@ export const LogsCard: FC<{
</Button>
))}
</div>
<div className="flex items-center gap-1 border-l pl-2">
{SOURCES.map((s) => (
<Button
key={s}
size="sm"
variant={source === s ? "secondary" : "ghost"}
onClick={() => setSource(s)}
>
{SOURCE_LABEL[s]()}
</Button>
))}
</div>
<Input
value={search}
onChange={(e) => setSearch(e.target.value)}
@@ -317,7 +354,15 @@ export const LogsCard: FC<{
</div>
) : (
<p className="text-muted-foreground">
{isLoading ? m.common_loading() : m.logs_empty()}
{isLoading
? m.common_loading()
: // "No plugin output" has a specific, actionable cause that the generic
// "adjust the filter" line actively misdirects from: the runner is a
// separate service and is opt-in on Linux, so the usual reason for an
// empty Plugins view is that it simply isn't running.
source === "plugins"
? m.logs_empty_plugins()
: m.logs_empty()}
</p>
)}
</div>
+16
View File
@@ -64,6 +64,22 @@ const fixtureEntries: LogEntry[] = [
"punktfunk_host::encode",
"NVENC opened 1920x1080 nv12 gop=inf rfi=on",
),
// Lines the plugin runner shipped up (`POST /api/v1/plugins/logs`), targeted `plugin:<name>`.
// They share the ring and the cursor with the host's own, which is what the Host/Plugins
// filter exists to separate — so the fixture has to carry both to be worth screenshotting.
entry(9, "INFO", "plugin:runner", "starting virtualhere"),
entry(
10,
"INFO",
"plugin:virtualhere",
"bound couch-deck.11 (Thrustmaster T300RS) for stream",
),
entry(
11,
"ERROR",
"plugin:virtualhere",
"vhclientx86_64 failed (ETIMEDOUT) — the VirtualHere client is not answering on /tmp/vhclient",
),
];
const meta = {