From a62396c2dd8dd6ca8333a59dc16c48f321447804 Mon Sep 17 00:00:00 2001 From: ScreenTinker Date: Tue, 28 Jul 2026 19:06:56 -0500 Subject: [PATCH] Attribute a widget play to the widget that played MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A widget playlist item carries its id in widget_id and has no content_id at all. The player sent only content_id, so a widget play arrived with nothing identifiable and was written with both columns null — and play_end bound content_id to BOTH columns, so that row could never match itself and was never closed or given a duration. Nothing looked broken: a row existed for every play. It just named neither what had played nor which widget, and never ended. Reports read empty for any screen showing a widget, which is most of the interesting ones. Seen on a live screen playing a single widget: one open row, both columns null. The player now sends widget_id alongside content_id, and a name falling back through the fields a widget item actually has, so the event records what played even when neither id resolves. The server prefers an explicit widget_id and keeps the old content_id sniff as the fallback for players that predate this, so an older client that puts a widget id in content_id still attributes correctly. Found by reading a real screen's proof-of-play rather than the code. The first attempt at the fix broke the statement outright — the explanatory comment was placed inside the SQL template literal, where a JS comment becomes SQL, and the server logged `near "/": syntax error` on every play_end. Comments now sit above db.prepare(), with a note saying why. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01Uaeo9MvzKoyXuN6ZsbhtkL --- server/player/index.html | 15 +- .../test/play-log-widget-attribution.test.js | 150 ++++++++++++++++++ server/ws/deviceSocket.js | 20 ++- 3 files changed, 176 insertions(+), 9 deletions(-) create mode 100644 server/test/play-log-widget-attribution.test.js diff --git a/server/player/index.html b/server/player/index.html index 203ef69..fae26bf 100644 --- a/server/player/index.html +++ b/server/player/index.html @@ -2062,11 +2062,16 @@ // Only the leader (or single, non-walled players) records a play_start — // followers would just spam duplicate proof-of-play rows for the same item. if (socket?.connected && (!wallConfig || wallConfig.is_leader)) { + // A widget item carries its id in widget_id and has NO content_id, so sending only + // content_id logged widget plays with nothing attached — the row existed but named + // neither what played nor which widget, and Reports read empty for any screen showing + // one. Send both; the server writes whichever column the id belongs in. socket.emit('device:play-event', { device_id: config.deviceId, event: 'play_start', - content_id: item.content_id, - content_name: item.filename, + content_id: item.content_id || null, + widget_id: item.widget_id || null, + content_name: item.filename || item.widget_name || item.title || null, duration_sec: item.duration_sec || null, }); } @@ -2095,8 +2100,10 @@ socket.emit('device:play-event', { device_id: config.deviceId, event: 'play_end', - content_id: playlist[currentIndex].content_id, - content_name: playlist[currentIndex].filename, + content_id: playlist[currentIndex].content_id || null, + widget_id: playlist[currentIndex].widget_id || null, + content_name: playlist[currentIndex].filename || playlist[currentIndex].widget_name + || playlist[currentIndex].title || null, completed: true, }); } diff --git a/server/test/play-log-widget-attribution.test.js b/server/test/play-log-widget-attribution.test.js new file mode 100644 index 0000000..9cad26d --- /dev/null +++ b/server/test/play-log-widget-attribution.test.js @@ -0,0 +1,150 @@ +'use strict'; + +// A widget playlist item carries its id in widget_id and has NO content_id. The player sent only +// content_id, so for a widget play the server received nothing identifiable: it wrote a row with +// content_id NULL and widget_id NULL, and closed nothing on play_end because the match bound +// content_id to both columns. +// +// The row existed, so nothing looked broken — but it named neither what played nor which widget, +// and it never gained a duration. Reports read empty for any screen showing a widget. Observed on +// a live screen playing a single widget: one open play_logs row with both columns null. +// +// Pinned here: a widget play is attributed to the widget and closed like any other. + +const { test, before, after } = require('node:test'); +const assert = require('node:assert/strict'); +const { spawn } = require('node:child_process'); +const path = require('node:path'); +const os = require('node:os'); +const fs = require('node:fs'); +const crypto = require('node:crypto'); +const Database = require('better-sqlite3'); +const ioClient = require('../node_modules/socket.io-client'); + +const { freePort } = require('./helpers/free-port'); +let PORT, BASE, proc, db; +const DATA_DIR = path.join(os.tmpdir(), 'st-plw-' + crypto.randomBytes(4).toString('hex')); +const LOG = path.join(os.tmpdir(), 'st-plw-' + crypto.randomBytes(4).toString('hex') + '.log'); +const S = {}; + +before(async () => { + PORT = await freePort(); + BASE = `http://127.0.0.1:${PORT}`; + const logFd = fs.openSync(LOG, 'w'); + proc = spawn('node', ['server.js'], { + cwd: path.join(__dirname, '..'), + env: { ...process.env, DATA_DIR, SELF_HOSTED: 'true', PORT: String(PORT), NODE_ENV: 'test' }, + stdio: ['ignore', logFd, logFd], + }); + let up = false; + for (let i = 0; i < 80; i++) { + try { const r = await fetch(BASE + '/api/status'); if (r.ok) { up = true; break; } } catch { /* */ } + await new Promise(r => setTimeout(r, 250)); + } + if (!up) throw new Error('server did not boot:\n' + fs.readFileSync(LOG, 'utf8').slice(-2000)); + db = new Database(path.join(DATA_DIR, 'db', 'remote_display.db')); + + S.device = crypto.randomUUID(); + S.token = crypto.randomBytes(32).toString('hex'); + db.prepare(`INSERT INTO devices (id, name, status, device_token, created_at) + VALUES (?, 'W', 'online', ?, strftime('%s','now'))`).run(S.device, S.token); + S.widget = crypto.randomUUID(); + db.prepare(`INSERT INTO widgets (id, name, widget_type, config, created_at, updated_at) + VALUES (?, 'Directory', 'directory', '{}', strftime('%s','now'), strftime('%s','now'))`) + .run(S.widget); +}); +after(() => { try { db && db.close(); } catch { /* */ } try { proc.kill('SIGKILL'); } catch { /* */ } }); + +function connect() { + return new Promise((resolve, reject) => { + const s = ioClient(BASE + '/device', { transports: ['websocket'], reconnection: false }); + s.on('connect', () => s.emit('device:register', { device_id: S.device, device_token: S.token })); + s.on('device:registered', () => resolve(s)); + s.on('device:auth-error', (e) => reject(new Error(e && e.error))); + setTimeout(() => reject(new Error('register timeout')), 10000); + }); +} +const rows = () => db.prepare('SELECT * FROM play_logs WHERE device_id = ? ORDER BY id').all(S.device); +const wait = (ms) => new Promise(r => setTimeout(r, ms)); +// The server throttles proof-of-play INSERTs to one per device per PLAY_LOG_MIN_GAP_MS (2s) so a +// runaway player cannot flood the table. Tests that expect a NEW row must clear that window, or +// the event is correctly dropped and the assertion fails for the wrong reason. +const clearThrottle = () => wait(2200); + +test('THE BUG: a widget play is attributed to the widget', async () => { + const s = await connect(); + s.emit('device:play-event', { + device_id: S.device, event: 'play_start', + content_id: null, widget_id: S.widget, content_name: 'Directory', + }); + await wait(600); + const r = rows(); + assert.equal(r.length, 1, 'a row was written'); + assert.equal(r[0].widget_id, S.widget, 'and it names the widget — previously both columns were null'); + assert.equal(r[0].content_id, null); + assert.equal(r[0].content_name, 'Directory', 'and what played'); + s.close(); +}); + +test('and play_end closes THAT row, giving it a duration', async () => { + const s = await connect(); + s.emit('device:play-event', { + device_id: S.device, event: 'play_end', + content_id: null, widget_id: S.widget, completed: true, + }); + await wait(600); + const r = rows(); + assert.equal(r.length, 1); + assert.ok(r[0].ended_at, 'closed — the match previously bound content_id to BOTH columns, so a widget row could never be found'); + assert.equal(r[0].completed, 1); + s.close(); +}); + +test('an unknown widget id is not written as a dangling reference', async () => { + await clearThrottle(); + const s = await connect(); + s.emit('device:play-event', { + device_id: S.device, event: 'play_start', + content_id: null, widget_id: crypto.randomUUID(), content_name: 'Ghost', + }); + await wait(600); + const r = rows(); + const last = r[r.length - 1]; + assert.equal(last.widget_id, null, 'a vanished widget degrades to NULL rather than failing the insert'); + assert.equal(last.content_name, 'Ghost', 'and the event still records WHAT played'); + s.close(); +}); + +test('an OLDER player, sending a widget id in content_id, still works', async () => { + await clearThrottle(); + // Backwards compatibility: players predating this send only content_id, sometimes carrying a + // widget id. The sniff that used to be the only path remains their fallback. + const before = rows().length; + const s = await connect(); + s.emit('device:play-event', { + device_id: S.device, event: 'play_start', + content_id: S.widget, content_name: 'Legacy', + }); + await wait(600); + const r = rows(); + assert.equal(r.length, before + 1); + assert.equal(r[r.length - 1].widget_id, S.widget, 'still attributed to the widget'); +}); + +test('ordinary content is unaffected', async () => { + await clearThrottle(); + const cid = crypto.randomUUID(); + db.prepare(`INSERT INTO content (id, filename, filepath, mime_type, file_size, created_at) + VALUES (?, 'a.jpg', 'a.jpg', 'image/jpeg', 1, strftime('%s','now'))`).run(cid); + const before = rows().length; + const s = await connect(); + s.emit('device:play-event', { + device_id: S.device, event: 'play_start', content_id: cid, widget_id: null, content_name: 'a.jpg', + }); + await wait(600); + const r = rows(); + assert.equal(r.length, before + 1); + assert.equal(r[r.length - 1].content_id, cid); + assert.equal(r[r.length - 1].widget_id, null); + s.close(); +}); diff --git a/server/ws/deviceSocket.js b/server/ws/deviceSocket.js index c2093a6..a87cb5a 100644 --- a/server/ws/deviceSocket.js +++ b/server/ws/deviceSocket.js @@ -1163,7 +1163,7 @@ module.exports = function setupDeviceSocket(io) { // Play event logging (proof-of-play) socket.on('device:play-event', (data) => { if (!requireDeviceAuth()) return; - const { device_id, event, content_id, content_name, zone_id, completed, duration_sec } = data; + const { device_id, event, content_id, widget_id, content_name, zone_id, completed, duration_sec } = data; if (device_id !== currentDeviceId) return; try { if (event === 'play_start') { @@ -1181,15 +1181,21 @@ module.exports = function setupDeviceSocket(io) { // widget_id was simply never written. Write whichever column the id belongs // in; an id matching neither degrades to NULL references, so content_name // still records WHAT played instead of the event vanishing. - const isContent = content_id ? !!contentExists.get(content_id) : false; - const isWidget = (!isContent && content_id) ? !!widgetExists.get(content_id) : false; + // Prefer an EXPLICIT widget_id. A widget playlist item has no content_id at all, so + // sniffing content_id could never attribute it — those plays were recorded with both + // columns null, and Reports read empty for any screen showing a widget. Older players + // send only content_id (sometimes carrying a widget id), so the sniff stays as their + // fallback. + const explicitWidget = widget_id && widgetExists.get(widget_id) ? widget_id : null; + const isContent = (!explicitWidget && content_id) ? !!contentExists.get(content_id) : false; + const isWidget = (!explicitWidget && !isContent && content_id) ? !!widgetExists.get(content_id) : false; db.prepare(` INSERT INTO play_logs (device_id, content_id, widget_id, zone_id, content_name, started_at, trigger_type) VALUES (?, ?, ?, ?, ?, strftime('%s','now'), 'playlist') `).run( device_id, isContent ? content_id : null, - isWidget ? content_id : null, + explicitWidget || (isWidget ? content_id : null), zone_id || null, content_name || 'Unknown' ); @@ -1204,6 +1210,10 @@ module.exports = function setupDeviceSocket(io) { started_at: Date.now(), }); } else if (event === 'play_end') { + // A widget play is closed by its widget id. Binding content_id to BOTH columns meant a + // widget row could never match itself, so it was never closed and never gained a + // duration — the other half of what made widget reporting useless. + // (Any comment must stay OUT of the template literal below; inside it, it becomes SQL.) db.prepare(` UPDATE play_logs SET ended_at = strftime('%s','now'), duration_sec = strftime('%s','now') - started_at, @@ -1217,7 +1227,7 @@ module.exports = function setupDeviceSocket(io) { -- arbitrary one of the tied set. ORDER BY started_at DESC, id DESC LIMIT 1 ) - `).run(completed ? 1 : 0, device_id, content_id, content_id); + `).run(completed ? 1 : 0, device_id, content_id || null, widget_id || content_id || null); } } catch (err) { // Include the identifiers. Without them this is undiagnosable in production: it