diff --git a/api/src/failure-log.js b/api/src/failure-log.js index cb7f35b4..ceb99ea0 100644 --- a/api/src/failure-log.js +++ b/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} */ +/** @type {Map} */ 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} 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} 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 }; diff --git a/api/src/widget-data.js b/api/src/widget-data.js index feafb568..dac42901 100644 --- a/api/src/widget-data.js +++ b/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; }, ); diff --git a/api/test/failure-log.test.js b/api/test/failure-log.test.js index 9de34b39..1fd14538 100644 --- a/api/test/failure-log.test.js +++ b/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'], + ); +}); diff --git a/api/test/http-integration.test.js b/api/test/http-integration.test.js index 21fe0293..0e53059d 100644 --- a/api/test/http-integration.test.js +++ b/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');