fix: harden Sonos playback and E2E diagnostics

Author: htilly

docker/Dockerfile

@@ -5,7 +5,7 @@ FROM --platform=$TARGETPLATFORM node:24-slim AS base
 
 # System deps needed for native builds (e.g., bcrypt) and git optional deps
 RUN apt-get update && \
-    apt-get install -y --no-install-recommends python3 build-essential && \
+    apt-get install -y --no-install-recommends python3 build-essential git && \
     rm -rf /var/lib/apt/lists/* && \
     npm cache clean --force
 

docker/Dockerfile-local

@@ -2,9 +2,10 @@
 # The --platform flag is used here to make sure we use a multi-platform base image
 FROM --platform=$BUILDPLATFORM node:26-slim AS base
 
-# Update and install git (if needed for your application)
-#RUN apk update && \
-#    apk upgrade
+# System deps needed by startup diagnostics and optional dependencies.
+RUN apt-get update && \
+    apt-get install -y --no-install-recommends git && \
+    rm -rf /var/lib/apt/lists/*
 
 # Clear npm cache to reduce image size and avoid potential issues
 RUN npm cache clean --force
@@ -25,4 +26,4 @@ COPY . .
 RUN chmod -R 755 /app
 
 # Command to run the application
-CMD ["node", "index.js"]
+CMD ["node", "index.js"]

index.js

@@ -72,10 +72,11 @@ const getReleaseVersion = () => {
 
   // 2. Git commit SHA (for native/local development)
   try {
-    const sha = execSync('git rev-parse --short HEAD', { encoding: 'utf8' }).trim();
+    const gitExecOptions = { encoding: 'utf8', stdio: ['ignore', 'pipe', 'ignore'] };
+    const sha = execSync('git rev-parse --short HEAD', gitExecOptions).trim();
     // Try to get tag from git if available
     try {
-      const tag = execSync('git describe --tags --exact-match HEAD 2>/dev/null', { encoding: 'utf8' }).trim();
+      const tag = execSync('git describe --tags --exact-match HEAD', gitExecOptions).trim();
       if (tag) {
         return tag; // Return exact tag if on tagged commit
       }

lib/add-handlers.js

@@ -7,6 +7,10 @@
  */
 
 const queueUtils = require('./queue-utils');
+const {
+  getFirstQueuedTrackNumber,
+  playFromQueue
+} = require('./sonos-playback');
 
 // ==========================================
 // DEPENDENCIES (injected via initialize)
@@ -163,9 +167,12 @@ async function add(input, channel, userName) {
     let result = null;
     try {
       logger.info(`Attempting to queue: ${firstCandidate.name} by ${firstCandidate.artist} (URI: ${firstCandidate.uri})`);
-      await sonos.queue(firstCandidate.uri);
+      const queueResult = await sonos.queue(firstCandidate.uri);
       logger.info('Successfully queued track: ' + firstCandidate.name);
-      result = firstCandidate;
+      result = {
+        ...firstCandidate,
+        queuePosition: getFirstQueuedTrackNumber(queueResult, 1)
+      };
     } catch (e) {
       const errorDetails = e.message || String(e);
       const upnpErrorMatch = errorDetails.match(/errorCode[>](\d+)[<]/);
@@ -212,61 +219,7 @@ async function add(input, channel, userName) {
     if (state === 'stopped') {
       (async () => {
         try {
-          try {
-            await sonos.stop();
-            await new Promise(resolve => setTimeout(resolve, 500));
-          } catch (stopErr) {
-            logger.debug('Stop before play (may already be stopped): ' + stopErr.message);
-          }
-          
-          // Verify queue has items before trying to play
-          let queueReady = false;
-          let retries = 0;
-          while (!queueReady && retries < 5) {
-            try {
-              const q = await sonos.getQueue();
-              if (q && q.items && q.items.length > 0) {
-                queueReady = true;
-                logger.debug(`Queue verified: ${q.items.length} items ready`);
-              } else {
-                logger.debug(`Queue not ready yet (attempt ${retries + 1}/5), waiting...`);
-                await new Promise(resolve => setTimeout(resolve, 300));
-                retries++;
-              }
-            } catch (queueErr) {
-              logger.debug(`Queue check failed (attempt ${retries + 1}/5): ${queueErr.message}`);
-              await new Promise(resolve => setTimeout(resolve, 300));
-              retries++;
-            }
-          }
-          
-          if (!queueReady) {
-            logger.warn('Queue not ready after 5 attempts, attempting playback anyway');
-          }
-          
-          // Try to activate queue by seeking to position 1
-          try {
-            logger.debug('Attempting to seek to queue position 1 to activate queue');
-            await sonos.avTransportService().Seek({
-              InstanceID: 0,
-              Unit: 'TRACK_NR',
-              Target: '1'
-            });
-            logger.debug('Successfully sought to track 1, queue should be active');
-            await new Promise(resolve => setTimeout(resolve, 500));
-          } catch (seekErr) {
-            logger.debug('Seek failed, trying next() to activate queue: ' + seekErr.message);
-            try {
-              await sonos.next();
-              logger.debug('Used next() to activate queue');
-              await new Promise(resolve => setTimeout(resolve, 300));
-            } catch (nextErr) {
-              logger.debug('next() also failed: ' + nextErr.message);
-            }
-          }
-          
-          await new Promise(resolve => setTimeout(resolve, 500));
-          await sonos.play();
+          await playFromQueue(sonos, logger, { trackNumber: result.queuePosition || 1 });
           logger.info('Started playback from queue');
         } catch (playErr) {
           logger.warn('Failed to start playback: ' + playErr.message);
@@ -426,19 +379,23 @@ async function queueAlbum(result, albumSearchTerm, channel, userName) {
             })
           );
 
-          await Promise.allSettled(queuePromises);
+          const queueResults = await Promise.allSettled(queuePromises);
+          result.queuePosition = getFirstQueuedTrackNumber(
+            queueResults.find(queueResult => queueResult.status === 'fulfilled' && queueResult.value)?.value,
+            1
+          );
           logger.info(`Added ${allowedTracks.length} tracks from album (filtered ${blacklistedTracks.length})`);
         } else {
-          await sonos.queue(result.uri);
+          const queueResult = await sonos.queue(result.uri);
+          result.queuePosition = getFirstQueuedTrackNumber(queueResult, 1);
           logger.info('Added album: ' + result.name);
         }
 
         if (isStopped) {
-          await new Promise(resolve => setTimeout(resolve, 300));
-          await sonos.play();
+          await playFromQueue(sonos, logger, { trackNumber: result.queuePosition || 1 });
           logger.info('Started playback after album add');
         } else if (state !== 'playing' && state !== 'transitioning') {
-          await sonos.play();
+          await playFromQueue(sonos, logger);
           logger.info('Player was not playing, started playback.');
         }
       } catch (err) {
@@ -529,40 +486,36 @@ async function addplaylist(input, channel, userName) {
       }
     }
 
+    let queuedTrackNumber = null;
+
     // If we have blacklisted tracks, add individually; otherwise use playlist URI
     if (blacklistedTracks.length > 0) {
       const allowedTracks = playlistTracks.filter(track => 
         !isTrackBlacklisted(track.name, track.artist)
       );
 
       for (const track of allowedTracks) {
-        await sonos.queue(track.uri);
+        const queueResult = await sonos.queue(track.uri);
+        queuedTrackNumber = queuedTrackNumber || getFirstQueuedTrackNumber(queueResult, 1);
       }
       logger.info(`Added ${allowedTracks.length} tracks from playlist (filtered ${blacklistedTracks.length})`);
     } else {
-      await sonos.queue(result.uri);
+      const queueResult = await sonos.queue(result.uri);
+      queuedTrackNumber = getFirstQueuedTrackNumber(queueResult, 1);
       logger.info('Added playlist: ' + result.name);
     }
 
     // Start playback if needed
     if (isStopped) {
       try {
-        try {
-          await sonos.stop();
-          await new Promise(resolve => setTimeout(resolve, 500));
-        } catch (stopErr) {
-          logger.debug('Stop before play (may already be stopped): ' + stopErr.message);
-        }
-        
-        await new Promise(resolve => setTimeout(resolve, 1000));
-        await sonos.play();
+        await playFromQueue(sonos, logger, { trackNumber: queuedTrackNumber || 1 });
         logger.info('Started playback from queue');
       } catch (playErr) {
         logger.warn('Failed to start playback: ' + playErr.message);
       }
     } else if (state !== 'playing' && state !== 'transitioning') {
       try {
-        await sonos.play();
+        await playFromQueue(sonos, logger);
         logger.info('Player was not playing, started playback.');
       } catch (playErr) {
         logger.warn('Failed to auto-play: ' + playErr.message);
@@ -578,23 +531,6 @@ async function addplaylist(input, channel, userName) {
 
     logger.info(`Sending playlist confirmation message: ${text}`);
     sendMessage(text, channel, { trackName: result.name });
-
-    // Note: Queueing is already done synchronously above (lines 532-545)
-    // This background task only handles playback if needed
-    (async () => {
-      try {
-        if (isStopped) {
-          await new Promise(resolve => setTimeout(resolve, 300));
-          await sonos.play();
-          logger.info('Started playback after playlist add');
-        } else if (state !== 'playing' && state !== 'transitioning') {
-          await sonos.play();
-          logger.info('Player was not playing, started playback.');
-        }
-      } catch (err) {
-        logger.error('Error in background playlist queueing: ' + err.message);
-      }
-    })();
   } catch (err) {
     logger.error('Error adding playlist: ' + err.message);
     sendMessage('🔎 Couldn\'t find that playlist. Try a Spotify link, or use `searchplaylist <name>` to pick one. 🎵', channel);
@@ -645,7 +581,7 @@ async function append(input, channel, userName) {
     }
 
     // Always add to queue (preserving existing tracks)
-    await sonos.queue(result.uri);
+    const queueResult = await sonos.queue(result.uri);
     logger.info('Appended track: ' + result.name);
 
     let msg = '✅ Added *' + result.name + '* by _' + result.artist + '_ to the queue!';
@@ -656,8 +592,9 @@ async function append(input, channel, userName) {
       logger.info('Current state after append: ' + state);
 
       if (state !== 'playing' && state !== 'transitioning') {
-        await new Promise(resolve => setTimeout(resolve, 1000));
-        await sonos.play();
+        await playFromQueue(sonos, logger, {
+          trackNumber: state === 'stopped' ? getFirstQueuedTrackNumber(queueResult, null) : null
+        });
         logger.info('Started playback after append.');
         msg += ' Playback started! :notes:';
       }

lib/command-handlers.js

@@ -7,6 +7,7 @@
  */
 
 const queueUtils = require('./queue-utils');
+const { playFromQueue } = require('./sonos-playback');
 
 // ==========================================
 // DEPENDENCIES (injected via initialize)
@@ -78,16 +79,14 @@ function stop(input, channel, userName) {
 /**
  * Start playback
  */
-function play(input, channel, userName) {
+async function play(input, channel, userName) {
   logUserAction(userName, 'play');
-  sonos
-    .play()
-    .then(() => {
-      sendMessage('▶️ Let\'s gooo! Music is flowing! 🎶', channel);
-    })
-    .catch((err) => {
-      logger.error('Error starting playback: ' + err);
-    });
+  try {
+    await playFromQueue(sonos, logger);
+    sendMessage('▶️ Let\'s gooo! Music is flowing! 🎶', channel);
+  } catch (err) {
+    logger.error('Error starting playback: ' + err);
+  }
 }
 
 /**