Fix: cap the widget failure log per widget

api/src/failure-log.js

@@ -3,7 +3,7 @@ const log = require('./log');
 const REPEAT_MS = 10 * 60 * 1000;
 const FORGET_MS = 60 * 60 * 1000;
 
-/** @type {Map<string, { reason: string, since: number, loggedAt: number, seenAt: number, failures: number }>} */
+/** @type {Map<string, { reason: string, since: number, loggedAt: number, seenAt: number, failures: number, group: string | null }>} */
 const _failing = new Map();
 
 /* Keys can come from a request. An entry nothing has touched for an hour is
@@ -12,15 +12,23 @@ function prune(now) {
   for (const [key, s] of _failing) if (now - s.seenAt >= FORGET_MS) _failing.delete(key);
 }
 
+function groupSize(group) {
+  let n = 0;
+  for (const s of _failing.values()) if (s.group === group) n++;
+  return n;
+}
+
 /** Logs the first failure, a changed reason, and a reminder at most every
-    REPEAT_MS while the same failure lasts.
-    @param {string} key @param {string} msg @param {Record<string, unknown>} fields
-    @param {string} reason @param {number} [now] */
-function failed(key, msg, fields, reason, now = Date.now()) {
+    REPEAT_MS while the same failure lasts. A new key in a group that already
+    holds maxPerGroup keys is neither kept nor logged.
+    @param {string} key @param {string} msg @param {Record<string, unknown>} fields @param {string} reason
+    @param {{ now?: number, group?: string, maxPerGroup?: number }} [opts] */
+function failed(key, msg, fields, reason, { now = Date.now(), group, maxPerGroup } = {}) {
   prune(now);
   const s = _failing.get(key);
   if (!s || s.reason !== reason) {
-    _failing.set(key, { reason, since: now, loggedAt: now, seenAt: now, failures: 1 });
+    if (!s && group != null && maxPerGroup && groupSize(group) >= maxPerGroup) return;
+    _failing.set(key, { reason, since: now, loggedAt: now, seenAt: now, failures: 1, group: group ?? null });
     log.error(msg, { ...fields, error: reason });
     return;
   }
@@ -43,4 +51,4 @@ function reset() {
   _failing.clear();
 }
 
-module.exports = { failed, recovered, reset, REPEAT_MS, FORGET_MS };
+module.exports = { failed, recovered, reset, REPEAT_MS, FORGET_MS, _size: () => _failing.size };

api/src/widget-data.js

@@ -158,7 +158,10 @@ on('GET', '/api/widget-data/:id', async (req, res) => {
         return out;
       },
       e => {
-        failureLog.failed(logKey, 'widget-data failed', logFields, log.reason(e));
+        failureLog.failed(logKey, 'widget-data failed', logFields, log.reason(e), {
+          group: item.id,
+          maxPerGroup: KEPT_PER_WIDGET,
+        });
         throw e;
       },
     );

api/test/failure-log.test.js

@@ -16,7 +16,7 @@ beforeEach(() => failureLog.reset());
 test('a failure that repeats is logged once until the reminder is due', t => {
   const lines = record(t);
   for (let i = 0; i < 200; i++)
-    failureLog.failed('w1', 'widget-data failed', { id: 'w1' }, 'Timed out', 1000 + i * 5000);
+    failureLog.failed('w1', 'widget-data failed', { id: 'w1' }, 'Timed out', { now: 1000 + i * 5000 });
   assert.equal(lines.length, 2);
   assert.deepEqual(lines[0], { level: 'error', msg: 'widget-data failed', data: { id: 'w1', error: 'Timed out' } });
   assert.equal(lines[1].data.failures, 1 + REPEAT_MS / 5000);
@@ -25,8 +25,8 @@ test('a failure that repeats is logged once until the reminder is due', t => {
 
 test('a changed reason is logged at once', t => {
   const lines = record(t);
-  failureLog.failed('w1', 'widget-data failed', {}, 'Timed out', 0);
-  failureLog.failed('w1', 'widget-data failed', {}, 'AdGuard HTTP 500', 1000);
+  failureLog.failed('w1', 'widget-data failed', {}, 'Timed out', { now: 0 });
+  failureLog.failed('w1', 'widget-data failed', {}, 'AdGuard HTTP 500', { now: 1000 });
   assert.deepEqual(
     lines.map(l => l.data.error),
     ['Timed out', 'AdGuard HTTP 500'],
@@ -36,8 +36,8 @@ test('a changed reason is logged at once', t => {
 test('recovery is logged once with the failure count, and only after a failure', t => {
   const lines = record(t);
   failureLog.recovered('w1', 'widget-data recovered', { id: 'w1' });
-  failureLog.failed('w1', 'widget-data failed', {}, 'Timed out', 0);
-  failureLog.failed('w1', 'widget-data failed', {}, 'Timed out', 1000);
+  failureLog.failed('w1', 'widget-data failed', {}, 'Timed out', { now: 0 });
+  failureLog.failed('w1', 'widget-data failed', {}, 'Timed out', { now: 1000 });
   failureLog.recovered('w1', 'widget-data recovered', { id: 'w1' });
   failureLog.recovered('w1', 'widget-data recovered', { id: 'w1' });
   assert.deepEqual(lines.at(-1), { level: 'info', msg: 'widget-data recovered', data: { id: 'w1', failures: 2 } });
@@ -46,15 +46,36 @@ test('recovery is logged once with the failure count, and only after a failure',
 
 test('separate keys are tracked separately', t => {
   const lines = record(t);
-  failureLog.failed('w1', 'widget-data failed', {}, 'Timed out', 0);
-  failureLog.failed('w2', 'widget-data failed', {}, 'Timed out', 0);
+  failureLog.failed('w1', 'widget-data failed', {}, 'Timed out', { now: 0 });
+  failureLog.failed('w2', 'widget-data failed', {}, 'Timed out', { now: 0 });
   assert.equal(lines.length, 2);
 });
 
 test('an entry untouched for an hour is forgotten', t => {
   const lines = record(t);
-  failureLog.failed('junk', 'widget-data failed', {}, 'Timed out', 0);
-  failureLog.failed('w1', 'widget-data failed', {}, 'Timed out', FORGET_MS);
+  failureLog.failed('junk', 'widget-data failed', {}, 'Timed out', { now: 0 });
+  failureLog.failed('w1', 'widget-data failed', {}, 'Timed out', { now: FORGET_MS });
   failureLog.recovered('junk', 'widget-data recovered', {});
   assert.equal(lines.filter(l => l.level === 'info').length, 0);
 });
+
+test('a widget keeps at most maxPerGroup failing keys, and the rest are not logged', t => {
+  const lines = record(t);
+  const opts = { now: 0, group: 'w1', maxPerGroup: 16 };
+  for (let i = 0; i < 2000; i++) failureLog.failed(`w1\nendpoint-${i}`, 'widget-data failed', {}, 'Timed out', opts);
+  failureLog.failed('w2\n', 'widget-data failed', {}, 'Timed out', { ...opts, group: 'w2' });
+  assert.equal(lines.length, 17);
+  assert.equal(failureLog._size(), 17);
+});
+
+test('a kept key still logs a changed reason when its group is full', t => {
+  const lines = record(t);
+  const opts = { now: 0, group: 'w1', maxPerGroup: 2 };
+  failureLog.failed('w1\na', 'widget-data failed', {}, 'Timed out', opts);
+  failureLog.failed('w1\nb', 'widget-data failed', {}, 'Timed out', opts);
+  failureLog.failed('w1\na', 'widget-data failed', {}, 'HTTP 500', opts);
+  assert.deepEqual(
+    lines.map(l => l.data.error),
+    ['Timed out', 'Timed out', 'HTTP 500'],
+  );
+});

api/test/http-integration.test.js

@@ -309,6 +309,32 @@ test('a widget whose service stays down logs one line, not one per request', asy
   }
 });
 
+test('a client cannot grow the failure log with endpoint values', async t => {
+  const failureLog = require('../src/failure-log');
+  const log = require('../src/log');
+  failureLog.reset();
+  const errors = [];
+  t.mock.method(log, 'error', msg => errors.push(msg));
+  const cfg = loadConfig();
+  saveConfig({
+    ...cfg,
+    items: [
+      ...(cfg.items || []),
+      { id: 'down-e', type: 'widget', widgetType: 'fixture', widgetConfig: { url: 'http://127.0.0.1:1/' } },
+    ],
+  });
+  try {
+    for (let i = 0; i < 40; i++) {
+      const r = await req('GET', `/api/widget-data/down-e?endpoint=e${i}`, { cookie: validCookie });
+      assert.equal(r.status, 502);
+    }
+    assert.equal(errors.length, 16);
+    assert.equal(failureLog._size(), 16);
+  } finally {
+    saveConfig(cfg);
+  }
+});
+
 test('OPTIONS is no longer specially routed', async () => {
   const r = await req('OPTIONS', '/api/config', { cookie: validCookie });
   assert.equal(r.status, 404, 'it must fall through like any other unmatched method');