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 }); });