Fix: log a failing widget once instead of on every request

api/src/api-error.js

@@ -147,14 +147,14 @@ function errorBody(e, overrides = {}) {
     @param {unknown} e
     @param {{ status?: number, kind?: string, code?: string,
               detail?: Record<string, unknown>, error?: string,
-              extra?: Record<string, unknown> }} [opts] */
+              extra?: Record<string, unknown>, quiet?: boolean }} [opts] */
 function fail(res, e, opts = {}) {
-  const { status = 502, kind, code: apiCode, detail, error, extra } = opts;
+  const { status = 502, kind, code: apiCode, detail, error, extra, quiet = false } = opts;
   const thrown = /** @type {{ status?: unknown, message?: unknown }} */ (e && typeof e === 'object' ? e : {});
   const code = (typeof thrown.status === 'number' && thrown.status) || status;
   const body = errorBody(e, { kind, code: apiCode, detail, error });
 
-  if (typeof thrown.message === 'string' && thrown.message && thrown.message !== body.error) {
+  if (!quiet && typeof thrown.message === 'string' && thrown.message && thrown.message !== body.error) {
     /* A SyntaxError message quotes the text it failed on, which can be a
        password or an API key. */
     const logged = e instanceof SyntaxError ? 'not valid JSON' : thrown.message;

api/src/failure-log.js

@@ -0,0 +1,46 @@
+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 }>} */
+const _failing = new Map();
+
+/* Keys can come from a request. An entry nothing has touched for an hour is
+   dropped without a recovery line. */
+function prune(now) {
+  for (const [key, s] of _failing) if (now - s.seenAt >= FORGET_MS) _failing.delete(key);
+}
+
+/** 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()) {
+  prune(now);
+  const s = _failing.get(key);
+  if (!s || s.reason !== reason) {
+    _failing.set(key, { reason, since: now, loggedAt: now, seenAt: now, failures: 1 });
+    log.error(msg, { ...fields, error: reason });
+    return;
+  }
+  s.seenAt = now;
+  s.failures++;
+  if (now - s.loggedAt < REPEAT_MS) return;
+  s.loggedAt = now;
+  log.error(msg, { ...fields, error: reason, failures: s.failures, since: new Date(s.since).toISOString() });
+}
+
+/** @param {string} key @param {string} msg @param {Record<string, unknown>} fields */
+function recovered(key, msg, fields) {
+  const s = _failing.get(key);
+  if (!s) return;
+  _failing.delete(key);
+  log.info(msg, { ...fields, failures: s.failures });
+}
+
+function reset() {
+  _failing.clear();
+}
+
+module.exports = { failed, recovered, reset, REPEAT_MS, FORGET_MS };

api/src/widget-data.js

@@ -13,6 +13,7 @@ const { widgetSettings } = require('./widget-settings');
 const { IS_DEMO } = require('./demo');
 const demoData = require('./demo-data');
 const log = require('./log');
+const failureLog = require('./failure-log');
 const { fail, KIND, WidgetError } = require('./api-error');
 const { rateLimit } = require('./auth');
 const LIMITS = require('./poll-limits');
@@ -148,11 +149,19 @@ on('GET', '/api/widget-data/:id', async (req, res) => {
   const params = widgetParams(new URL(req.url, 'http://x').searchParams, entry.manifest);
   const endpointName = params.get('endpoint') || '';
 
+  const logKey = `${item.id}\n${endpointName}`;
+  const logFields = { widget: item.widgetType, id: item.id };
   const refresh = () =>
-    getWidgetData(item, entry, endpointName, params, fetchUnchecked).catch(e => {
-      log.error('widget-data failed', { widget: item.widgetType, id: item.id, error: log.reason(e) });
-      throw e;
-    });
+    getWidgetData(item, entry, endpointName, params, fetchUnchecked).then(
+      out => {
+        failureLog.recovered(logKey, 'widget-data recovered', logFields);
+        return out;
+      },
+      e => {
+        failureLog.failed(logKey, 'widget-data failed', logFields, log.reason(e));
+        throw e;
+      },
+    );
   const outcome = await latest(`${cfg._rev}:${item.id}?${params}`, refresh, {
     holdMs: WIDGET_HOLD_MS,
     keepMs: WIDGET_KEEP_MS,
@@ -161,7 +170,7 @@ on('GET', '/api/widget-data/:id', async (req, res) => {
   });
   if (!outcome) return json(res, 202, { pending: true });
   if (outcome.ok) return json(res, outcome.value.status, outcome.value.body);
-  fail(res, outcome.error, { status: 502 });
+  fail(res, outcome.error, { status: 502, quiet: true });
 });
 
 /* Config-time "Fetch" for a select field declared with optionsFrom. The id is

api/test/failure-log.test.js

@@ -0,0 +1,60 @@
+const { test, beforeEach } = require('node:test');
+const assert = require('node:assert/strict');
+const log = require('../src/log');
+const failureLog = require('../src/failure-log');
+const { REPEAT_MS, FORGET_MS } = failureLog;
+
+function record(t) {
+  const lines = [];
+  t.mock.method(log, 'error', (msg, data) => lines.push({ level: 'error', msg, data }));
+  t.mock.method(log, 'info', (msg, data) => lines.push({ level: 'info', msg, data }));
+  return lines;
+}
+
+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);
+  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);
+  assert.equal(lines[1].data.since, new Date(1000).toISOString());
+});
+
+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);
+  assert.deepEqual(
+    lines.map(l => l.data.error),
+    ['Timed out', 'AdGuard HTTP 500'],
+  );
+});
+
+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.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 } });
+  assert.equal(lines.filter(l => l.level === 'info').length, 1);
+});
+
+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);
+  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.recovered('junk', 'widget-data recovered', {});
+  assert.equal(lines.filter(l => l.level === 'info').length, 0);
+});

api/test/http-integration.test.js

@@ -284,6 +284,31 @@ test('a query value the widget manifest declares reaches its data function', asy
   }
 });
 
+test('a widget whose service stays down logs one line, not one per request', 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-w', type: 'widget', widgetType: 'fixture', widgetConfig: { url: 'http://127.0.0.1:1/' } },
+    ],
+  });
+  try {
+    for (let i = 0; i < 5; i++) {
+      const r = await req('GET', '/api/widget-data/down-w', { cookie: validCookie });
+      assert.equal(r.status, 502);
+    }
+    assert.deepEqual(errors, ['widget-data failed']);
+  } 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');