openvibers/openvibe.events Commits

A limit refusal logs once a minute per actor, with how many it held back (svc:search's re-index bursts printed 935 lines) (#108)

OP OpenVibers committed 21 days ago · 11577c5bd2 · 2 files, +22 −3

Changes

ddiff --git a/server/actor-limits.js b/server/actor-limits.js
iindex 16e859c..b3109af 100644
---- a/server/actor-limits.js
++++ b/server/actor-limits.js
@@@ -30,15 +30,26 @@ function createLimits({ config, clock = { now: () => Date.now() }, metrics = nul
const refused = metrics && metrics.registry
? metrics.registry.counter({ name: 'events_rate_limited_total', help: 'Requests refused 429 by a per-actor limit, by limit name and window', labelNames: ['limit', 'window'] })
: null;
++ const logged = new Map(); // name|actor|window → { at, skipped }: the last refusal line and how many it held back
const limiter = createActorLimiter({
limits: { minute: config.limits.minute, hour: config.limits.hour },
now: () => clock.now(),
// Shared across processes on Valkey (ADR-035) when VALKEY_URL is set; in-process otherwise.
...(valkey ? { store: createValkeyLimitStore(valkey) } : {}),
onLimited(e) {
-- // The actor is a principal id (svc:…, app:app_…), never a token.
-- log.warn(`[limits] ${e.name}: ${e.actor} refused, over ${e.limit} per ${e.window}`);
++ // The actor is a principal id (svc:…, app:app_…), never a token. One line a minute per actor, limit and window,
++ // with how many were refused since the last line: a service's outbox draining a re-index after a burst was
++ // refused (and retried) hundreds of times a minute, one line each (svc:search, 935 lines on 2026-10-23).
++ // The counter below still counts every refusal.
if (refused) refused.inc({ limit: e.name, window: e.window });
++ const k = `${e.name}|${e.actor}|${e.window}`;
++ const t = clock.now();
++ const seen = logged.get(k);
++ if (seen && t - seen.at < 60000) { seen.skipped++; return; }
++ if (logged.size > 1000) logged.clear();
++ logged.set(k, { at: t, skipped: 0 });
++ const more = seen && seen.skipped ? ` (and ${seen.skipped} more since the last line)` : '';
++ log.warn(`[limits] ${e.name}: ${e.actor} refused, over ${e.limit} per ${e.window}${more}`);
},
});
const limits = (name, own) => { record(name, own); return limiter(name, own); };
ddiff --git a/test/actor-limits.test.js b/test/actor-limits.test.js
iindex 86fdf95..021fc0c 100644
---- a/test/actor-limits.test.js
++++ b/test/actor-limits.test.js
@@@ -93,7 +93,8 @@ t('refusals are counted in events_rate_limited_total', async () => {
t('refusals are logged once each: the limit, the principal and the window, never a token', async () => {
const warned = [];
-- const limits = createLimits({ config: load({ EVENTS_LIMITS_MINUTE: '1' }), clock: manualClock(Date.UTC(2026, 8, 27, 12, 0, 0)), log: { warn: (...a) => warned.push(a.join(' ')) } });
++ const clock = manualClock(Date.UTC(2026, 8, 27, 12, 0, 0));
++ const limits = createLimits({ config: load({ EVENTS_LIMITS_MINUTE: '1' }), clock, log: { warn: (...a) => warned.push(a.join(' ')) } });
const mw = limits('events.event.read');
const req = { principal: { kind: 'service', sub: 'svc:search' }, headers: { authorization: 'Bearer secret-token' } };
const res = { headers: {}, statusCode: 200, setHeader(k, v) { this.headers[k.toLowerCase()] = v; }, end(b) { this.body = b; } };
@@@ -102,6 +103,13 @@ t('refusals are logged once each: the limit, the principal and the window, never
mw(req, res, () => { passed++; });
assert.deepStrictEqual([passed, res.statusCode, res.headers['retry-after']], [1, 429, '60']);
assert.deepStrictEqual(warned, ['[limits] events.event.read: svc:search refused, over 1 per minute']);
++ // A burst logs one line a minute: the refusals in between are counted on the next line (and in the metric).
++ for (let i = 0; i < 3; i++) mw(req, res, () => { passed++; });
++ assert.strictEqual(warned.length, 1, 'no line per refusal');
++ clock.advance(61000);
++ mw(req, res, () => { passed++; });
++ mw(req, res, () => { passed++; });
++ assert.deepStrictEqual(warned.slice(1), ['[limits] events.event.read: svc:search refused, over 1 per minute (and 3 more since the last line)']);
});
t('EVENTS_LIMITS=off: no limit answers', async () => {