Merge pull request 'Resi Cues 1.0.3: the next cue's name keeps moving, and Resi logins stop hammering the account' (#43) from claude/resi-cues-startup-pause into main

modules/resi-cues/module.json

@@ -1,7 +1,7 @@
 {
   "id": "resi-cues",
   "name": "Resi Cues",
-  "version": "1.0.0",
+  "version": "1.0.3",
   "proddash": ">=1.4.0",
   "description": "Time until the next Resi cue point, on the board and as a timer",
   "provides": ["timers"],

modules/resi-cues/resi.js

@@ -39,6 +39,9 @@ function msToPosition(total) {
 
 const WINDOW_MS = 120000;   // how long a reading stays useful
 const JUMP_FLOOR_MS = 5000; // the smallest move ever treated as a seek
+const LOGIN_BACKOFF_MS = 15000;      // first wait after a failed Resi login
+const LOGIN_BACKOFF_MAX_MS = 300000; // longest wait between login attempts
+const SESSION_FRESH_MS = 60000;      // a refusal younger than this is a permission, not an expired session
 
 /**
  * Resi republishes a decoder's `position` only every few seconds, on an irregular
@@ -61,6 +64,8 @@ function createPlayhead(options) {
   let offsets = [];      // { at, off } — off is mediaMs - wall time it was read
   let spreads = [];      // how far apart honest readings sit: this link's noise
   let gaps = [];         // how long between the playhead actually moving
+  let changes = 0;       // readings that differed from the one before
+  let rejected = false;  // the last gap looked like a pause and was skipped
   let base;              // the trusted offset
   let lastMedia;
   let lastNewAt;
@@ -90,15 +95,25 @@ function createPlayhead(options) {
           spreads = spreads.concat(-delta).slice(-20);
         }
       }
-      if (lastNewAt !== undefined) {
+      // The first reading lands at an arbitrary point in Resi's cycle, so the gap
+      // from it to the next one is only a fraction of the real cadence. Learning
+      // from it locked in a 2s cadence that rejected every honest 30s gap.
+      if (lastNewAt !== undefined && changes > 0) {
         const gap = t - lastNewAt;
         // The gap either side of a pause is not Resi's cadence — recording it
         // would inflate the estimate and make the next pause slow to notice.
+        // But a pause is one gap; twice in a row is the cadence having changed.
         const worst = gaps.length ? Math.max.apply(null, gaps) : 0;
-        if (gap > 0 && gap < 60000 && (!worst || gap <= worst * 3)) {
-          gaps = gaps.concat(gap).slice(-8);
+        if (gap > 0 && gap < 60000) {
+          if (!worst || gap <= worst * 3 || rejected) {
+            gaps = gaps.concat(gap).slice(-8);
+            rejected = false;
+          } else {
+            rejected = true;
+          }
         }
       }
+      if (lastNewAt !== undefined) changes++;
       offsets = offsets.concat({ at: t, off });
       lastMedia = mediaMs;
       lastNewAt = t;
@@ -118,7 +133,9 @@ function createPlayhead(options) {
     // Only call it paused once the playhead has been still for clearly longer than
     // Resi's own cadence. A fixed timeout mistakes a slow update for a stop, and a
     // countdown that freezes mid-service is the worse failure of the two.
-    const pauseAfter = Math.max(15000, Math.min(45000, cadenceMs * 2.5 + 6000));
+    // Until a full gap has been measured the cadence is unknown; assume the slowest
+    // Resi plausibly is, or a 30s publisher reads as paused 15s after every start.
+    const pauseAfter = cadenceMs ? Math.max(15000, Math.min(45000, cadenceMs * 2.5 + 6000)) : 45000;
     const playing = base !== undefined && t - lastNewAt < pauseAfter;
     if (!playing) {
       return { estMs: lastEst !== undefined ? lastEst : lastMedia, playing: false, cadenceMs };
@@ -161,13 +178,43 @@ function createResiClient(options) {
     return h;
   }
 
+  /* A failed login used to be retried on the very next poll -- once a second, for
+     ever. Resi answers that with 429s, and since the retries never let up, the
+     account never got out of them. So a failure now holds off further attempts,
+     doubling from 15s to 5min (or as long as Resi's Retry-After asks), and every
+     call in between fails at once with the same reason instead of signing in. */
+  const now = typeof opts.now === 'function' ? opts.now : () => Date.now();
+  let loginFailures = 0;
+  let loginBlockedUntil = 0;
+  let loginError = '';
+
   async function login() {
-    const res = await doFetch(`${RESI}/api/v3/login?newToken=true`, {
-      method: 'POST',
-      headers: { 'Content-Type': 'application/json', Accept: 'application/json' },
-      body: JSON.stringify({ userName: opts.username, password: opts.password }),
-    });
-    if (!res.ok) throw new Error(`Resi login failed (${res.status})`);
+    if (now() < loginBlockedUntil) {
+      const wait = Math.ceil((loginBlockedUntil - now()) / 1000);
+      throw new Error(`${loginError} — retrying in ${wait}s`);
+    }
+    let res;
+    try {
+      res = await doFetch(`${RESI}/api/v3/login?newToken=true`, {
+        method: 'POST',
+        headers: { 'Content-Type': 'application/json', Accept: 'application/json' },
+        body: JSON.stringify({ userName: opts.username, password: opts.password }),
+      });
+    } catch (err) {
+      holdOff(`Resi unreachable (${(err && err.message) || err})`, 0);
+      throw new Error(loginError);
+    }
+    if (!res.ok) {
+      const reason = res.status === 429 ? 'Resi is rate-limiting this login (429)'
+        : res.status === 400 || res.status === 401 ? `Resi rejected the login (${res.status}) — check the password`
+          : `Resi login failed (${res.status})`;
+      const retryAfter = Number(res.headers && res.headers.get && res.headers.get('retry-after')) || 0;
+      holdOff(reason, retryAfter * 1000);
+      throw new Error(reason);
+    }
+    loginFailures = 0;
+    loginBlockedUntil = 0;
+    loginError = '';
     const setCookies = (res.headers.getSetCookie && res.headers.getSetCookie())
       || (res.headers.get('set-cookie') ? [res.headers.get('set-cookie')] : []);
     const jar = {};
@@ -179,24 +226,49 @@ function createResiClient(options) {
     token = jar.livingas1 || '';
     if (!token) throw new Error('Resi login returned no session cookie');
     cookieHeader = Object.keys(jar).map((k) => `${k}=${jar[k]}`).join('; ');
-    loggedInAt = Date.now();
+    loggedInAt = now();
     const me = await get('/api_v2.svc/users/me');
     customerId = (me && me.customerId) || '';
     if (!customerId) throw new Error('This Resi account has no customerId');
     return me;
   }
 
-  async function ensureSession() {
-    if (!token || Date.now() - loggedInAt > 50 * 60 * 1000) await login();
+  function holdOff(reason, askedMs) {
+    loginFailures++;
+    const backoff = Math.min(LOGIN_BACKOFF_MAX_MS, LOGIN_BACKOFF_MS * 2 ** (loginFailures - 1));
+    loginBlockedUntil = now() + Math.max(backoff, askedMs || 0);
+    loginError = reason;
   }
 
+  async function ensureSession() {
+    if (!token || now() - loggedInAt > 50 * 60 * 1000) await login();
+  }
+
+  /* The same hold-off covers every request, not just the login. A 401/403 used to
+     sign in again on the spot, every time: for a login that simply isn't allowed to
+     see a venue, that was a fresh sign-in on every poll. Now a refusal straight
+     after signing in is taken as what it is -- a permission -- and held off like a
+     failed login; only an older session is renewed. A 429 holds off too. */
   async function get(path) {
-    const res = await doFetch(RESI + path, { method: 'GET', headers: headers() });
-    if (res.status === 401 || res.status === 403) {
+    if (now() < loginBlockedUntil) {
+      const wait = Math.ceil((loginBlockedUntil - now()) / 1000);
+      throw new Error(`${loginError} — retrying in ${wait}s`);
+    }
+    let res = await doFetch(RESI + path, { method: 'GET', headers: headers() });
+    if ((res.status === 401 || res.status === 403) && now() - loggedInAt > SESSION_FRESH_MS) {
       await login();
-      const retry = await doFetch(RESI + path, { method: 'GET', headers: headers() });
-      if (!retry.ok) throw new Error(`Resi ${path} failed (${retry.status})`);
-      return retry.json();
+      res = await doFetch(RESI + path, { method: 'GET', headers: headers() });
+    }
+    if (res.status === 401 || res.status === 403) {
+      const where = path.includes('/venues') ? 'its venues'
+        : path.includes('/players') ? "this venue's decoders" : 'part of the account';
+      holdOff(`This Resi login isn't allowed to see ${where} (${res.status}) — ask a Resi admin for access`, 0);
+      throw new Error(loginError);
+    }
+    if (res.status === 429) {
+      const retryAfter = Number(res.headers && res.headers.get && res.headers.get('retry-after')) || 0;
+      holdOff('Resi is rate-limiting requests (429)', retryAfter * 1000);
+      throw new Error(loginError);
     }
     if (!res.ok) throw new Error(`Resi ${path} failed (${res.status})`);
     return res.json();
@@ -216,7 +288,10 @@ function createResiClient(options) {
       try {
         return (await get(`${path}?_=${Date.now()}`)) || [];
       } catch (err) {
-        if (!/\((4\d\d)\)/.test(String(err.message))) throw err;
+        // Only an objection to the parameter itself; a refusal or a "slow down"
+        // (401/403/429) is about the login, and dropping it then lost fresh readings.
+        const code = (String(err.message).match(/\((4\d\d)\)/) || [])[1];
+        if (!code || ['401', '403', '429'].includes(code)) throw err;
         cacheBust = false;
       }
     }

modules/resi-cues/resi.test.js

@@ -197,6 +197,32 @@ test('surroundingCues puts a cue you are exactly on behind you', () => {
   assert.strictEqual(surroundingCues([], 1000).next, null);
 });
 
+/* ── starting partway through Resi's cycle ─────────────────────────────── */
+
+// Seen live at North Attleboro: Resi publishing every ~30s, and the board starting a
+// few seconds before a publish. The first "gap" it measured was 2s (9s after a
+// reboot), and once that was the cadence every honest 30s gap was thrown out as a
+// pause gap -- so playback read as paused 15s into every update, the countdown froze,
+// and the next cue (and its name) stopped moving on.
+for (const [into, burst] of [[28000, false], [21000, false], [0, true]]) {
+  test(`30s Resi, started ${into / 1000}s into its cycle${burst ? ', 2s burst after a seek' : ''}: never falsely paused`, () => {
+    const w = makeWorld({ cadence: 30000, lag: 1000, jitter: 2000, net: 500 });
+    w.lastPublish = w.t - into;
+    const head = createPlayhead({ now: () => w.t });
+    const second = () => { w.advance(1000); head.note(w.poll()); return head.read(); };
+    let paused = 0;
+    for (let i = 0; i < 100; i++) if (!second().playing) paused++;
+    if (burst) {
+      w.media += 15 * 60000;                       // a seek, published at once...
+      w.lastPublish = w.t - w.nextCadence;
+      second(); second();
+      w.lastPublish = w.t - w.nextCadence;          // ...and again 2s later
+    }
+    for (let i = 0; i < 300; i++) if (!second().playing) paused++;
+    assert.strictEqual(paused, 0, `read as paused for ${paused}s while playing`);
+  });
+}
+
 /* ── the matrix ────────────────────────────────────────────────────────── */
 
 const argv = process.argv.slice(2).map(Number);

modules/resi-cues/server.js

@@ -70,6 +70,7 @@ function emptyTimers(now) {
 }
 
 let current = null; // the live handle, shared with routes()
+let pickerClient = null; // { key, client } for the decoder picker when the module isn't running those credentials
 
 module.exports = {
   init({ config, log }) {
@@ -146,7 +147,9 @@ module.exports = {
             elapsedMs: null,
             remainingMs,
             targetMs: Math.max(1000, state.next.ms - from),
-            status: { text: state.next.name || 'Next cue', tone: state.playing ? 'ok' : 'warn' },
+            // The label already is the cue's name, and it is what the card is titled
+            // with; repeating it on the status line only crowded the card.
+            status: { text: state.playing ? 'Next cue' : 'Held', tone: state.playing ? 'ok' : 'warn' },
             detail: state.event || '',
           });
         }
@@ -271,6 +274,7 @@ module.exports = {
       stateStreams,
       timerStreams,
       resi,
+      credentialsKey: `${username}\n${password}`,
       configured: Boolean(username && password),
       stop() {
         stopped = true;
@@ -332,9 +336,21 @@ module.exports = {
           return json(res, 200, { options: [], note: 'Enter the Resi login first' });
         }
         try {
-          const client = createResiClient({
-            username: String(config.username), password: String(config.password),
-          });
+          // The running module's client when it has these credentials, else one kept
+          // per login: a fresh client per request signed in on every admin page load,
+          // and its own hold-off never applied -- which kept Resi rate-limiting.
+          const username = String(config.username).trim();
+          const key = `${username}\n${config.password}`;
+          let client;
+          if (current && current.resi && current.credentialsKey === key) client = current.resi;
+          else {
+            if (!pickerClient || pickerClient.key !== key) {
+              pickerClient = { key, client: createResiClient({
+                username, password: String(config.password),
+              }) };
+            }
+            client = pickerClient.client;
+          }
           const options = [];
           for (const v of await client.venues()) {
             for (const p of await client.players(v.uuid)) {

modules/resi-cues/server.test.js

@@ -18,8 +18,9 @@
 const assert = require('assert');
 
 let passed = 0;
-function test(name, fn) {
-  fn();
+// Awaited, so an async test finishes before the next one changes the world under it.
+async function test(name, fn) {
+  await fn();
   passed++;
   console.log(`  ok  ${name}`);
 }
@@ -101,7 +102,7 @@ function collect(route, req) {
 
   const routes = server.routes({ config: {}, log: (m) => logged.push(m) });
 
-  test('signs in once and finds the configured decoder', () => {
+  await test('signs in once and finds the configured decoder', () => {
     assert.strictEqual(world.logins, 1, 'should sign in exactly once');
     const state = handle.state;
     assert.strictEqual(state.status, 'ok', state.message);
@@ -110,20 +111,20 @@ function collect(route, req) {
     assert.strictEqual(state.cues.length, 3);
   });
 
-  test('works out the cue either side of the playhead', () => {
+  await test('works out the cue either side of the playhead', () => {
     const state = handle.state;
     assert.strictEqual(state.next.name, 'Campus Host');
     assert.strictEqual(state.prev.name, 'Welcome');
     assert.ok(Math.abs(state.estMs - 528000) < 2000, `playhead was ${state.estMs}`);
   });
 
-  test('/state answers the same snapshot as the stream', () => {
+  await test('/state answers the same snapshot as the stream', () => {
     const res = collect(routes['GET /state']);
     assert.strictEqual(res.code, 200);
     assert.deepStrictEqual(JSON.parse(res.body), handle.state);
   });
 
-  test('/stream opens with an event so a new tile paints at once', () => {
+  await test('/stream opens with an event so a new tile paints at once', () => {
     const res = collect(routes['GET /stream']);
     assert.strictEqual(res.code, 200);
     assert.strictEqual(res.headers['Content-Type'], 'text/event-stream; charset=utf-8');
@@ -131,7 +132,7 @@ function collect(route, req) {
     assert.ok(res.body.includes('event: state'), 'should send an initial state event');
   });
 
-  test('/timers offers the countdown and the playhead, shaped as the guide says', () => {
+  await test('/timers offers the countdown and the playhead, shaped as the guide says', () => {
     const snap = JSON.parse(collect(routes['GET /timers']).body);
     assert.strictEqual(snap.source, 'resi-cues');
     assert.strictEqual(snap.label, 'Resi');
@@ -145,7 +146,7 @@ function collect(route, req) {
     assert.ok(Math.abs(next.remainingMs - 222000) < 2000, `remaining was ${next.remainingMs}`);
     // the countdown runs from the cue before it, so a consumer can colour progress
     assert.strictEqual(next.targetMs, 450000);
-    assert.strictEqual(next.status.text, 'Campus Host');
+    assert.strictEqual(next.status.text, 'Next cue');   // the name is the label; not repeated
     assert.ok(next.startedAt <= snap.updatedAt, 'startedAt must be in the past');
 
     assert.strictEqual(playhead.id, 'playhead');
@@ -154,7 +155,7 @@ function collect(route, req) {
     assert.ok(Math.abs(playhead.elapsedMs - 528000) < 2000);
   });
 
-  test('a cue fired at the host moves the countdown on the next poll', async () => {
+  await test('a cue fired at the host moves the countdown on the next poll', async () => {
     world.position = '00:12:40.000';         // jumped past Campus Host
     tickFn();
     await settle();
@@ -162,10 +163,10 @@ function collect(route, req) {
     assert.strictEqual(state.next.name, 'Message');
     assert.strictEqual(state.prev.name, 'Campus Host');
     const snap = JSON.parse(collect(routes['GET /timers']).body);
-    assert.strictEqual(snap.timers[0].label, 'Message');
+    assert.strictEqual(snap.timers[0].label, 'Message');   // the card's name follows the cue
   });
 
-  test('a decoder with no event reports nothing playing rather than stale cues', async () => {
+  await test('a decoder with no event reports nothing playing rather than stale cues', async () => {
     world.eventId = '';
     tickFn();
     await settle();
@@ -174,13 +175,13 @@ function collect(route, req) {
     assert.strictEqual(handle.state.event, '');
   });
 
-  test('health speaks about the upstream, not about itself', () => {
+  await test('health speaks about the upstream, not about itself', () => {
     const h = handle.health();
     assert.ok(['ok', 'connecting', 'error'].includes(h.status), h.status);
     assert.ok(h.message.length > 0, 'health should say something useful');
   });
 
-  test('an unconfigured module idles instead of hammering Resi', () => {
+  await test('an unconfigured module idles instead of hammering Resi', () => {
     const before = world.logins;
     const idle = server.init({ config: {}, log: () => {} });
     assert.strictEqual(world.logins, before, 'must not sign in with no credentials');
@@ -189,12 +190,90 @@ function collect(route, req) {
     idle.stop();
   });
 
-  test('stop() leaves nothing running', () => {
+  await test('stop() leaves nothing running', () => {
     handle.stop();
     const res = collect(routes['GET /state']);
     assert.strictEqual(JSON.parse(res.body).status, 'error');
   });
 
+  // Seen live at North Attleboro: a failed login was retried on every 1s poll, so
+  // Resi answered 429 and kept answering it, and the decoder picker stayed empty.
+  await test('a failed login holds off instead of retrying every poll', async () => {
+    const { createResiClient } = require('./resi');
+    let t = 1700000000000;
+    let logins = 0;
+    let limited = true;
+    const client = createResiClient({
+      username: 'a@b.c',
+      password: 'secret',
+      now: () => t,
+      fetch: async (url) => {
+        const path = String(url).replace('https://central.resi.io', '').split('?')[0];
+        if (path === '/api/v3/login') {
+          logins++;
+          if (limited) return reply({}, { ok: false, status: 429 });
+          return reply({}, { headers: { get: () => null, getSetCookie: () => ['livingas1=T; Path=/'] } });
+        }
+        if (path === '/api_v2.svc/users/me') return reply({ customerId: 'CUST' });
+        if (path === '/api/v3/customers/CUST/venues') return reply([{ uuid: 'V1' }]);
+        return reply({}, { ok: false, status: 404 });
+      },
+    });
+    const poll = async () => { try { await client.venues(); return 'ok'; } catch (e) { return e.message; } };
+
+    assert.match(await poll(), /rate-limiting/);
+    for (let i = 0; i < 60; i++) { t += 1000; await poll(); }   // a minute of 1s polls
+    assert.ok(logins <= 3, `signed in ${logins} times in a minute while rate-limited`);
+    assert.match(await poll(), /retrying in \d+s/, 'the wait is shown, not hidden');
+
+    limited = false;
+    t += 5 * 60000;                                             // past the longest hold-off
+    assert.strictEqual(await poll(), 'ok', 'recovers once Resi lets it in');
+    const after = logins;
+    for (let i = 0; i < 30; i++) { t += 1000; await poll(); }
+    assert.strictEqual(logins, after, 'a good session is not signed in again');
+  });
+
+  await test('a rejected password says so', async () => {
+    const { createResiClient } = require('./resi');
+    const client = createResiClient({
+      username: 'a@b.c', password: 'wrong', now: () => 0,
+      fetch: async () => reply({}, { ok: false, status: 400 }),
+    });
+    await assert.rejects(client.venues(), /check the password/);
+  });
+
+  // Seen live: media@waters.church signs in fine but may not list venues (403). The
+  // client answered every 403 by signing in again -- a fresh login on every poll.
+  await test('a login that may not see venues is held off, not signed in every poll', async () => {
+    const { createResiClient } = require('./resi');
+    let t = 1700000000000;
+    let logins = 0;
+    let venueCalls = 0;
+    const client = createResiClient({
+      username: 'a@b.c', password: 'secret', now: () => t,
+      fetch: async (url) => {
+        const path = String(url).replace('https://central.resi.io', '').split('?')[0];
+        if (path === '/api/v3/login') {
+          logins++;
+          return reply({}, { headers: { get: () => null, getSetCookie: () => ['livingas1=T; Path=/'] } });
+        }
+        if (path === '/api_v2.svc/users/me') return reply({ customerId: 'CUST' });
+        if (path === '/api/v3/customers/CUST/venues') { venueCalls++; return reply({}, { ok: false, status: 403 }); }
+        return reply({}, { ok: false, status: 404 });
+      },
+    });
+    const poll = async () => { try { await client.venues(); return 'ok'; } catch (e) { return e.message; } };
+
+    assert.match(await poll(), /isn't allowed to see its venues \(403\)/);
+    for (let i = 0; i < 120; i++) { t += 1000; await poll(); }   // two minutes of 1s polls
+    // At most one renewal once the session is over a minute old (in case it really
+    // had expired), then the hold-off keeps growing -- not one sign-in per poll.
+    assert.ok(logins <= 2, `signed in ${logins} times in two minutes for a permission problem`);
+    assert.ok(venueCalls <= 8, `asked for venues ${venueCalls} times in two minutes (a poll each would be 121)`);
+    assert.match(await poll(), /ask a Resi admin/);
+  });
+
   globalThis.setInterval = realSetInterval;
   globalThis.clearInterval = realClearInterval;
   console.log(`\n${passed} tests passed`);