diff --git a/api/src/api-error.js b/api/src/api-error.js index 0590a75c..67078cce 100644 --- a/api/src/api-error.js +++ b/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, error?: string, - extra?: Record }} [opts] */ + extra?: Record, 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; diff --git a/api/src/failure-log.js b/api/src/failure-log.js new file mode 100644 index 00000000..cb7f35b4 --- /dev/null +++ b/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} */ +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} 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} 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 }; diff --git a/api/src/widget-data.js b/api/src/widget-data.js index d183447e..feafb568 100644 --- a/api/src/widget-data.js +++ b/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 diff --git a/api/test/failure-log.test.js b/api/test/failure-log.test.js new file mode 100644 index 00000000..9de34b39 --- /dev/null +++ b/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); +}); diff --git a/api/test/http-integration.test.js b/api/test/http-integration.test.js index 879c354f..21fe0293 100644 --- a/api/test/http-integration.test.js +++ b/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');