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 <noreply@anthropic.com>

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

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

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

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

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