From 0c439259ac4552519505ea832850e479adb047cc Mon Sep 17 00:00:00 2001 From: Nicolas Date: Mon, 14 Sep 2026 00:53:55 +0200 Subject: [PATCH] Add server-side logging of the party lifecycle Requested now that the app is actually running on real infrastructure: visibility from docker logs/journalctl into what's happening (parties created/destroyed, who joined/left, play/pause, pause requests) without needing to reproduce a bug through the UI first. server/src/logger.js: a deliberately tiny partyLog(message) - plain console.log, prefixed [watchparty:party], ISO timestamp - plus a who(userId, userName) formatter shared by every call site. No logging library; this app runs as a single container, not behind a log aggregator, so a consistent grep-able prefix is what actually helps here. Covers the party's business lifecycle end to end, logged at the source so every caller (REST and socket) is covered without repeating the check: - partyManager.js: create, join, leave (also covers a host handoff or the party being destroyed, both fall out of leave), advanceQueue, removeIdleParties. - socketHandler.js: playstate and requestPause, since those two mutate member state directly rather than through a PartyManager method. The one thing that needed real care: the host's player re-sends its CURRENT play/pause state every 3 seconds regardless of whether anything changed (the heartbeat), on top of firing per actual play/pause/seeked event. Logging every "playstate" message as it arrives would mean one log line every 3 seconds per active party, forever. The handler instead compares incoming isPaused against the member's previous value and only logs on an actual flip - so a party generates exactly one line per real pause or resume, never one per heartbeat tick. Verified directly against the real shipped modules, not reimplemented mocks: a scripted create/join/advanceQueue/leave/idle-sweep sequence against the real partyManager.js produced exactly the expected line at every step; a fake io/socket pair driving the real socketHandler.js through start -> 5 unchanged heartbeats -> pause -> 3 unchanged heartbeats -> resume logged exactly 3 playstate lines (not 9) at exactly the right points, and a throttled repeat requestPause produced no second line - all assertions passed, counted programmatically. docs/architecture.md has the full writeup. Co-Authored-By: Claude Sonnet 5 --- README.md | 3 +++ docs/architecture.md | 44 +++++++++++++++++++++++++++++++++++++ server/src/logger.js | 26 ++++++++++++++++++++++ server/src/partyManager.js | 14 ++++++++++++ server/src/socketHandler.js | 14 ++++++++++++ 5 files changed, 101 insertions(+) create mode 100644 server/src/logger.js diff --git a/README.md b/README.md index 7a0f057..8fc417c 100644 --- a/README.md +++ b/README.md @@ -62,6 +62,7 @@ server/ Node.js backend: proxies ALL Emby access (auth, catalog, src/embyProxy.js generic Emby request/response proxying (incl. HLS) src/socketHandler.js Socket.IO protocol (see comments in the file) src/partyManager.js in-memory room state + src/logger.js party lifecycle logging (docker logs/journalctl-friendly) client/ Static frontend (plain JS, ES modules, no build step). Talks only to server/ - never to Emby directly. @@ -117,6 +118,8 @@ Then put it behind your existing reverse proxy like everything else - [x] Live "watch parties en cours" list (host, elapsed time, member count), live host handoff, no join codes - [x] Presence overlay (avatars) + "request pause" in the player +- [x] Server-side logging of the party lifecycle (create/join/leave/destroy, + host handoff, play/pause, pause requests) — see docs/architecture.md - [ ] Try a full party end-to-end with two real accounts (still the main gap) - [ ] Music: dedicated player, artist/album browsing, collaborative playlist - [ ] Tune transcoding target / support direct play when possible diff --git a/docs/architecture.md b/docs/architecture.md index 41930de..4f20a70 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -600,6 +600,50 @@ position). The sidebar and library routing already treat `music` as a first later doesn't need another structural pass — see `library.js`'s early return. Right now it just shows an honest placeholder. +## Server-side logging + +Requested once the app was running for real on the user's own server: +visibility into what's actually happening, from `docker logs`/journalctl, +without needing to reproduce a bug through the UI first. `server/src/logger.js` +is a deliberately tiny `partyLog(message)` (plain `console.log`, prefixed +`[watchparty:party]`, ISO timestamp) plus a `who(userId, userName)` formatter +shared by every call site - no logging library, consistent with this app's +general bias against dependencies it doesn't need. + +Covers the party's business lifecycle end to end, called from wherever the +state actually changes so every caller is covered without repeating the +check - `server/src/partyManager.js`'s `create`/`join`/`leave` (which also +covers a host handoff or the party being destroyed, both of which fall out +of `leave`)/`advanceQueue`/`removeIdleParties`, plus +`server/src/socketHandler.js`'s `playstate` and `requestPause` handlers, +since those two mutate member state directly rather than through a +`PartyManager` method. + +The one thing this needed real care over: the host's player re-sends its +*current* play/pause state every 3 seconds regardless of whether anything +changed (the heartbeat - see "Realtime transport" above), on top of firing +once per actual `play`/`pause`/`seeked` event. Logging every `"playstate"` +message as it arrives would mean one log line every 3 seconds for every +active party, forever - noise that would drown out everything else within +minutes on a server with even a couple of parties running. The handler +instead compares the incoming `isPaused` against the member's *previous* +value and only logs on an actual flip, silently updating position on every +other message - so a party generates exactly one `"playstate"` line per +real pause or resume, never one per heartbeat tick. + +Verified directly against the real shipped modules (not reimplemented +mocks) - see session history: a scripted `create`/`join`×2/`advanceQueue` +(twice — once real, once a no-op past the end of the queue, correctly +silent)/`leave`×3 (plain, host handoff, final-member destroy)/idle-sweep +sequence against the real `partyManager.js` produced exactly the expected +line for every step, in the expected order; a fake `io`/`socket` pair +driving the real `socketHandler.js` through a start → 5 unchanged +heartbeats → pause → 3 unchanged heartbeats → resume sequence logged +exactly 3 `"playstate"` lines (not 9) at exactly the right points, and a +throttled repeat `"requestPause"` produced no second `"pauseRequested"` +line - all assertions passed, counted programmatically rather than +eyeballed. + ## Known limitations - Playback always goes through `hls.js` against whatever Emby's diff --git a/server/src/logger.js b/server/src/logger.js new file mode 100644 index 0000000..4f4ad97 --- /dev/null +++ b/server/src/logger.js @@ -0,0 +1,26 @@ +'use strict'; + +/** + * Minimal server-side logging for the party lifecycle - plain stdout lines, + * no logging library. This app runs as a single Docker container watched + * via `docker logs`/journalctl (see README's Deploying section), not behind + * a log aggregator, so a consistent prefix + timestamp is what actually + * makes these greppable in practice, not structured JSON nobody's parsing. + * + * Deliberately covers the party's business-level lifecycle only (created, + * joined, left, destroyed, host handoff, queue advance, playstate + * transitions, pause requests) - not connection-level noise like every + * Socket.IO reconnect or the 3s playstate heartbeat re-sending the same + * state (see socketHandler.js, which only calls this on an actual + * play/pause transition, not every heartbeat tick). + */ +function partyLog(message) { + console.log(`[watchparty:party] ${new Date().toISOString()} ${message}`); +} + +/** `"name(id)"` - the same shape in every party lifecycle log line. */ +function who(userId, userName) { + return `${userName}(${userId})`; +} + +module.exports = { partyLog, who }; diff --git a/server/src/partyManager.js b/server/src/partyManager.js index a923602..1044106 100644 --- a/server/src/partyManager.js +++ b/server/src/partyManager.js @@ -1,6 +1,7 @@ 'use strict'; const crypto = require('crypto'); +const { partyLog, who } = require('./logger'); /** * In-memory party store - mirrors the Party/PartyMember/PartyManager design @@ -45,6 +46,7 @@ class PartyManager { party.members.set(hostUserId, this._newMember(hostUserId, hostUserName)); this.partiesById.set(party.id, party); + partyLog(`created partyId=${party.id} host=${who(hostUserId, hostUserName)} item="${itemName}" queueLength=${party.queue.length}`); return party; } @@ -56,6 +58,7 @@ class PartyManager { const member = this._newMember(userId, userName); party.members.set(userId, member); party.lastActivityUtc = Date.now(); + partyLog(`joined partyId=${party.id} user=${who(userId, userName)} memberCount=${party.members.size}`); return member; } @@ -67,6 +70,7 @@ class PartyManager { * home page's live list - see docs/architecture.md. */ leave(party, userId) { + const leavingMember = party.members.get(userId); const wasHost = party.hostUserId === userId; party.members.delete(userId); party.lastActivityUtc = Date.now(); @@ -79,8 +83,15 @@ class PartyManager { } const destroyed = party.members.size === 0; + const whoLeft = leavingMember ? who(userId, leavingMember.userName) : userId; if (destroyed) { this.partiesById.delete(party.id); + partyLog(`destroyed partyId=${party.id} (last member ${whoLeft} left)`); + } else if (wasHost && newHostUserId != null) { + const newHost = party.members.get(newHostUserId); + partyLog(`left partyId=${party.id} user=${whoLeft} memberCount=${party.members.size} hostHandoff->${who(newHostUserId, newHost.userName)}`); + } else { + partyLog(`left partyId=${party.id} user=${whoLeft} memberCount=${party.members.size}`); } return { hostChanged: wasHost && newHostUserId != null, newHostUserId, destroyed }; @@ -106,6 +117,7 @@ class PartyManager { member.lastUpdatedUtc = Date.now(); } party.lastActivityUtc = Date.now(); + partyLog(`advanced partyId=${party.id} to item="${next.itemName}" (${party.queueIndex + 1}/${party.queue.length})`); return true; } @@ -119,6 +131,8 @@ class PartyManager { for (const party of this.partiesById.values()) { if (party.lastActivityUtc < cutoff) { this.partiesById.delete(party.id); + const idleMinutes = Math.round((Date.now() - party.lastActivityUtc) / 60000); + partyLog(`destroyed partyId=${party.id} (idle ${idleMinutes}min, ${party.members.size} member(s) still connected)`); } } } diff --git a/server/src/socketHandler.js b/server/src/socketHandler.js index 7ceda21..633bd36 100644 --- a/server/src/socketHandler.js +++ b/server/src/socketHandler.js @@ -1,6 +1,7 @@ 'use strict'; const { PartyManager } = require('./partyManager'); +const { partyLog, who } = require('./logger'); /** * Realtime side of the app: one party's own room, plus a shared "lobby" room @@ -65,10 +66,22 @@ function attachSocketServer(io, { parseCookies, getSession }) { return; // only the host drives playback - see docs/architecture.md } const member = party.members.get(userId); + const wasPaused = member.isPaused; member.isPaused = !!(msg && msg.isPaused); member.positionTicks = Number(msg && msg.positionTicks) || 0; member.lastUpdatedUtc = Date.now(); party.lastActivityUtc = Date.now(); + + // Logged only on an actual play/pause transition, not every one of + // these - the host's player also re-sends the current state on a + // plain 3s heartbeat (see player.js), which would otherwise spam this + // line for every active party every 3 seconds regardless of whether + // anything actually changed. + if (member.isPaused !== wasPaused) { + const positionSeconds = Math.round(member.positionTicks / 10000000); + partyLog(`playstate partyId=${party.id} host=${who(userId, member.userName)} -> ${member.isPaused ? 'paused' : 'playing'} at ${positionSeconds}s`); + } + socket.to(party.id).emit('playstate', { isPaused: member.isPaused, positionTicks: member.positionTicks }); }); @@ -101,6 +114,7 @@ function attachSocketServer(io, { parseCookies, getSession }) { const now = Date.now(); if (member.lastPauseRequestUtc && now - member.lastPauseRequestUtc < 5000) return; member.lastPauseRequestUtc = now; + partyLog(`pauseRequested partyId=${party.id} user=${who(userId, member.userName)}`); io.to(party.id).emit('pauseRequested', { userId, userName: member.userName }); });