feat(autoplay): instrument outcome eval to disambiguate #1275

packages/bot/src/handlers/player/trackHandlers.spec.ts

@@ -585,6 +585,118 @@ describe('trackHandlers autoplay replenishment', () => {
         })
     })
 
+    describe('autoplay outcome diagnostic log (#1275)', () => {
+        const findEvalLog = ():
+            | { data?: Record<string, unknown> }
+            | undefined =>
+            infoLogMock.mock.calls.find(
+                (call) =>
+                    (call[0] as { message?: string } | undefined)?.message ===
+                    'Autoplay outcome eval',
+            )?.[0] as { data?: Record<string, unknown> } | undefined
+
+        it('logs path=skip, recordedOutcome=rejected for an autoplay skip before 30%', async () => {
+            jest.useFakeTimers()
+            const handlers = setupHandlers()
+            const queue = createQueue(QueueRepeatMode.AUTOPLAY)
+            const track = {
+                ...createAutoplayTrack('listener-1'),
+                id: 'diag-skip-reject',
+                durationMS: 100000,
+            } as unknown as Track
+
+            await handlers.playerStart(queue, track)
+            jest.advanceTimersByTime(15000) // 15%
+            await handlers.playerSkip(queue, track)
+
+            expect(findEvalLog()).toMatchObject({
+                data: {
+                    path: 'skip',
+                    trackId: 'diag-skip-reject',
+                    hasStartTime: true,
+                    playedRatio: 0.15,
+                    recordedOutcome: 'rejected',
+                },
+            })
+        })
+
+        it('logs recordedOutcome=ambiguous(dropped) for an autoplay skip after 30%', async () => {
+            jest.useFakeTimers()
+            const handlers = setupHandlers()
+            const queue = createQueue(QueueRepeatMode.AUTOPLAY)
+            const track = {
+                ...createAutoplayTrack('listener-1'),
+                id: 'diag-skip-ambig',
+                durationMS: 100000,
+            } as unknown as Track
+
+            await handlers.playerStart(queue, track)
+            jest.advanceTimersByTime(55000) // 55%
+            await handlers.playerSkip(queue, track)
+
+            expect(findEvalLog()).toMatchObject({
+                data: { path: 'skip', recordedOutcome: 'ambiguous(dropped)' },
+            })
+        })
+
+        it('logs path=finish, recordedOutcome=accepted for an autoplay finish past 30%', async () => {
+            jest.useFakeTimers()
+            const handlers = setupHandlers()
+            const queue = createQueue(QueueRepeatMode.AUTOPLAY)
+            const track = {
+                ...createAutoplayTrack('listener-1'),
+                id: 'diag-finish-accept',
+                durationMS: 100000,
+            } as unknown as Track
+
+            await handlers.playerStart(queue, track)
+            jest.advanceTimersByTime(40000)
+            await handlers.playerFinish(queue, track)
+
+            expect(findEvalLog()).toMatchObject({
+                data: { path: 'finish', recordedOutcome: 'accepted' },
+            })
+        })
+
+        it('flags hasStartTime=false / no-timing when a skip has no recorded start (the H1 race)', async () => {
+            const handlers = setupHandlers()
+            const queue = createQueue(QueueRepeatMode.AUTOPLAY)
+            const track = {
+                ...createAutoplayTrack('listener-1'),
+                id: 'diag-no-timing',
+                durationMS: 100000,
+            } as unknown as Track
+
+            // No playerStart → no start time recorded for this track.
+            await handlers.playerSkip(queue, track)
+
+            expect(findEvalLog()).toMatchObject({
+                data: {
+                    hasStartTime: false,
+                    playedRatio: null,
+                    recordedOutcome: 'none(no-timing)',
+                },
+            })
+        })
+
+        it('does not emit the diagnostic for non-autoplay tracks', async () => {
+            jest.useFakeTimers()
+            const handlers = setupHandlers()
+            const queue = createQueue(QueueRepeatMode.AUTOPLAY)
+            const track = {
+                ...createTrack('listener-1'),
+                id: 'diag-manual',
+                durationMS: 100000,
+            } as unknown as Track
+
+            await handlers.playerStart(queue, track)
+            jest.advanceTimersByTime(10000)
+            await handlers.playerSkip(queue, track)
+
+            expect(findEvalLog()).toBeUndefined()
+        })
+    })
+
     // #1275 probe: prod shows 0 rejected all-time despite a working accepted
     // path. The isolated tests above pass, so the per-event logic is correct.
     // These exercise the REALISTIC continuous-autoplay sequencing where the

packages/bot/src/handlers/player/trackHandlers.ts

@@ -296,10 +296,52 @@
     await addTrackToHistory(trackToRecord, queue.guild.id)
 }
 
+// #1275 diagnostic: the per-event accept/reject logic is correct and
+// unit-tested (incl. the interleaving probe), yet prod records 0 rejected.
+// The existing "Track skipped" log lacks the fields to tell a code issue
+// (missing start time, skips routing through playerFinish, the real skipRatio
+// distribution) from a genuinely-rare signal (most picks are over-queued and
+// never played → 'pending'). Emit the decision inputs for every autoplay
+// terminal event, on both paths, so Loki can disambiguate H1 vs H2.
+const logAutoplayOutcomeEval = (
+    path: 'finish' | 'skip',
+    queue: GuildQueue,
+    track: Track,
+    startTime: number | undefined,
+): void => {
+    const playedRatio =
+        startTime !== undefined && track.durationMS
+            ? (Date.now() - startTime) / track.durationMS
+            : null
+    const recordedOutcome =
+        playedRatio === null
+            ? 'none(no-timing)'
+            : playedRatio < OUTCOME_ACCEPT_PLAY_RATIO
+              ? 'rejected'
+              : path === 'finish'
+                ? 'accepted'
+                : 'ambiguous(dropped)'
+    infoLog({
+        message: 'Autoplay outcome eval',
+        data: {
+            path,
+            guildId: queue.guild.id,
+            trackId: track.id,
+            hasStartTime: startTime !== undefined,
+            durationMS: track.durationMS ?? null,
+            playedRatio:
+                playedRatio === null
+                    ? null
+                    : Math.round(playedRatio * 1000) / 1000,
+            recordedOutcome,
+        },
+    })
+}
+
 const handlePlayerFinish = async (
     queue: GuildQueue,
     track?: Track,
 ): Promise<void> => {
     try {
         await scrobbleAndRecord(queue, track)
 
@@ -307,6 +349,9 @@
             const startTime = trackStartTimes.get(
                 trackStartKey(queue.guild.id, track.id),
             )
+            if (isRecommendationAutoplay(track)) {
+                logAutoplayOutcomeEval('finish', queue, track, startTime)
+            }
             if (startTime && track.durationMS) {
                 const completionRatio =
                     (Date.now() - startTime) / track.durationMS
@@ -348,7 +393,7 @@
 const handlePlayerSkip = async (
     queue: GuildQueue,
     track?: Track,
 ): Promise<void> => {
     try {
         infoLog({
             message: 'Track skipped',
@@ -369,6 +414,9 @@
             const startTime = trackStartTimes.get(
                 trackStartKey(queue.guild.id, track.id),
             )
+            if (isRecommendationAutoplay(track)) {
+                logAutoplayOutcomeEval('skip', queue, track, startTime)
+            }
             if (startTime && track.durationMS) {
                 const skipRatio = (Date.now() - startTime) / track.durationMS
                 // Implicit-dislike noise filter: only for tracks long enough that