diff --git a/README.md b/README.md index 718d2b2..3d949a4 100644 --- a/README.md +++ b/README.md @@ -101,8 +101,9 @@ iob-sync logs garage # only lines mentioning "garage" iob-sync logs --level error # only failures ``` -If `logs` shows nothing, that is usually the adapter's own log level rather than a fault -— see [TROUBLESHOOTING.md](docs/TROUBLESHOOTING.md). +If `logs` shows nothing at `info` and above while scripts are demonstrably running, that +is a bug and not your instance — see [TROUBLESHOOTING.md](docs/TROUBLESHOOTING.md). +Missing `debug` lines specifically are usually the adapter's own log level. ## Commands diff --git a/docs/TROUBLESHOOTING.md b/docs/TROUBLESHOOTING.md index 4288e85..b595783 100644 --- a/docs/TROUBLESHOOTING.md +++ b/docs/TROUBLESHOOTING.md @@ -41,7 +41,14 @@ other tools happy, regenerate the certificate on the instance and then run ## `logs` prints the banner and nothing else -It is streaming; there is simply nothing to show. Two things surprise people: +**First: if you are on a version before the `requireLog` fix, this is a bug and no amount +of adapter configuration will help.** `subscribeLog` used to send `subscribe(['log'])`. +Admin's generic `subscribe` takes a _state id pattern_, so that asked to watch states +named `log`, of which there are none — accepted, acknowledged, and silent forever. The +wire command is `requireLog`. Upgrade; nothing about your instance is wrong. + +That bug was originally misdiagnosed as the two entries below, which are both real but +were not the cause. If you are current and still see silence, they are what to check: - **`--level` only narrows what the server already sends.** An ioBroker adapter emits nothing below _its own_ configured log level, so asking for `--level debug` while @@ -52,7 +59,9 @@ It is streaming; there is simply nothing to show. Two things surprise people: worked. Your own `log()` calls are info-level and do appear. To prove the stream is alive, run `iob-sync logs` and then any `iob-sync` command in a -second terminal: Admin logs every connection at info, so a line appears immediately. +second terminal: Admin logs every connection at info, so a line appears immediately. Note +that this check is what _should_ have caught the `requireLog` bug and did not — treat a +silent result from it as the client being broken, not as the house being quiet. ## Every script shows `Cannot find name 'log'` diff --git a/src/client/socket.ts b/src/client/socket.ts index 113b1fc..dae0eb0 100644 --- a/src/client/socket.ts +++ b/src/client/socket.ts @@ -347,19 +347,29 @@ export class AdminSocketClient implements SocketClient { /** * Subscribes to the server log stream. * - * The wire command is the generic `subscribe` with the literal type `log` — not a - * `subscribeLog` of its own. Server-side that flips `requireLog(true)` on the - * adapter, after which log lines arrive as ordinary `[0, null, "log", [entry]]` - * message frames. + * The wire command is `requireLog`, which is its own command and not a variant of + * `subscribe`. Admin's generic `subscribe` takes a *state* id pattern, so + * `subscribe(['log'])` is a well-formed request to watch states named `log` — of + * which there are none. It is accepted, it acknowledges, and it delivers nothing + * for the rest of time. + * + * That is exactly what it did. This was misdiagnosed once already as "the house was + * simply quiet" (see the docs note about adapter log levels, which is true and was + * not the cause), and the cost of the wrong conclusion was a whole debugging session + * spent on the instance rather than the client. Verified against the live instance + * on 2026-08-30: `requireLog([true])` delivers `javascript.*` lines within a second + * of a script restart, `subscribe(['log'])` delivers nothing across 25 s. + * + * Once enabled, lines arrive as ordinary `[0, , "log", [entry]]` message frames. */ async subscribeLog(handler: LogHandler): Promise { this.logHandlers.push(handler); - await this.emit('subscribe', ['log']); + await this.emit('requireLog', [true]); } async unsubscribeLog(): Promise { this.logHandlers.length = 0; - await this.emit('unsubscribe', ['log']); + await this.emit('requireLog', [false]); } private handleCallback(id: number, args: unknown[] | undefined): void { diff --git a/test/commands-logs.test.ts b/test/commands-logs.test.ts index 211bd4b..95428a3 100644 --- a/test/commands-logs.test.ts +++ b/test/commands-logs.test.ts @@ -49,13 +49,27 @@ describe('logs', () => { project = await makeTempProject(); }); - it('asks the server for the log stream', async () => { + /** + * The wire command, pinned deliberately. + * + * This used to assert `subscribe:log` and passed, because the fake broadcast log + * frames to every connection regardless. Against the real Admin, `subscribe` takes a + * state id pattern — so the client was asking to watch states named `log`, getting an + * acknowledgement, and receiving nothing ever. Verified on the live instance + * 2026-08-30. Assert the command, not just that lines arrive, or a fake that is too + * generous hides the bug again. + */ + it('asks the server for the log stream with requireLog', async () => { const t = await makeContext(port, project); const handle = await logs(t.ctx); try { assert.ok( - server.subscriptionRequests.includes('subscribe:log'), - `expected a log subscription, got ${JSON.stringify(server.subscriptionRequests)}`, + server.logRequests.includes('requireLog:true'), + `expected requireLog(true), got ${JSON.stringify(server.logRequests)}`, + ); + assert.ok( + !server.subscriptionRequests.includes('subscribe:log'), + 'subscribe(["log"]) is a state pattern and never delivers logs — do not send it', ); } finally { await handle.stop(); @@ -63,6 +77,20 @@ describe('logs', () => { } }); + it('turns the log stream off again when stopped', async () => { + const t = await makeContext(port, project); + const handle = await logs(t.ctx); + await handle.stop(); + try { + assert.ok( + server.logRequests.includes('requireLog:false'), + `expected requireLog(false) on stop, got ${JSON.stringify(server.logRequests)}`, + ); + } finally { + await t.close(); + } + }); + it('prints a log line as it arrives', async () => { const t = await makeContext(port, project); const handle = await logs(t.ctx); diff --git a/test/fake-server.ts b/test/fake-server.ts index bc1e50f..6b4e978 100644 --- a/test/fake-server.ts +++ b/test/fake-server.ts @@ -164,6 +164,17 @@ export class FakeAdminServer { private wss: WebSocket.Server | null = null; private httpServer: http.Server | null = null; private readonly sockets = new Set(); + /** + * Sockets that have asked for logs with `requireLog(true)`. + * + * The fake used to broadcast log frames to every connection, which is why it happily + * agreed with a client that sent `subscribe(['log'])` — a command the real Admin + * accepts as a *state* pattern and then never acts on. The suite passed for months + * against a fake that shared the client's misunderstanding. Gating delivery here is + * the whole point: it is what makes the wire command a tested contract instead of a + * comment. + */ + private readonly logSubscribers = new Set(); private readonly objects = new Map(); /** * State *values*, stored independently of `objects` — which is the entire point. @@ -187,6 +198,9 @@ export class FakeAdminServer { /** Generic `subscribe`/`unsubscribe` calls, e.g. `subscribe:log`. */ readonly subscriptionRequests: string[] = []; + /** Every `requireLog` call, as `requireLog:true` / `requireLog:false`. */ + readonly logRequests: string[] = []; + /** Delay before sending `___ready___` after connect, in ms. */ readyDelayMs = 0; @@ -256,6 +270,7 @@ export class FakeAdminServer { ws.on('close', () => { this.sockets.delete(ws); + this.logSubscribers.delete(ws); }); const sendReady = () => { @@ -442,6 +457,11 @@ export class FakeAdminServer { this.requireCookieOnSocket = false; this.httpRequests.length = 0; this.subscriptionRequests.length = 0; + this.logRequests.length = 0; + // Not the socket set itself: `reset` runs between tests while connections from the + // previous one may still be closing, and dropping them here would be a different + // kind of lie. Only the recorded intent is cleared. + this.logSubscribers.clear(); } getObject(id: string): IoBrokerObject | null { @@ -454,8 +474,10 @@ export class FakeAdminServer { /** Broadcast an objectChange message to all connected clients (bypassing storage). */ /** - * Pushes a log line to every connected client, as the real server does after a - * `subscribe(['log'])`. Shape mirrors ioBroker's log objects. + * Pushes a log line to every client that asked for logs with `requireLog(true)`, + * as the real server does. Shape mirrors ioBroker's log objects. + * + * A client that never sent `requireLog` receives nothing — see `logSubscribers`. */ emitLog(entry: { message: string; severity?: string; from?: string; ts?: number }): void { const payload = { @@ -464,7 +486,7 @@ export class FakeAdminServer { from: entry.from ?? 'javascript.0', ts: entry.ts ?? Date.now(), }; - for (const ws of this.sockets) { + for (const ws of this.logSubscribers) { if (ws.readyState === WebSocket.OPEN) { ws.send(JSON.stringify([0, null, 'log', [payload]])); } @@ -657,14 +679,29 @@ export class FakeAdminServer { case 'subscribe': case 'unsubscribe': { - // The generic subscribe, used with the literal type 'log'. Recorded so a - // test can assert the client asked for logs before expecting any. + // The generic subscribe. In the real Admin this takes a *state id pattern*, + // so `subscribe(['log'])` is a request to watch states named `log` — accepted, + // acknowledged, and silent forever. Recorded, but deliberately does not enable + // log delivery: that is the bug this fake now refuses to reproduce. const [what] = (args as string[]) ?? []; this.subscriptionRequests.push(`${name}:${what}`); this.reply(ws, id, null, null); return; } + case 'requireLog': { + // The actual log command. Only this turns the stream on. + const [enabled] = (args as [boolean]) ?? [false]; + this.logRequests.push(`requireLog:${enabled}`); + if (enabled) { + this.logSubscribers.add(ws); + } else { + this.logSubscribers.delete(ws); + } + this.reply(ws, id, null, null); + return; + } + default: { this.reply(ws, id, `Unknown command: ${name}`, null); return;