feat(row 333): count dropped proxy usage batches and show them in the Console (Vikunja #778)

The usage queue read drains the proxy. A batch that is then not written (the
client or the bus refuses its shape, an ambiguous key owner, a failed write) is
lost, and the Console showed proxy totals with no sign of it. The reader now
counts these per enabled business since the bus started, the proxy view returns
the count as droppedBatches, and the Console proxy section says so above 0.
A read that failed before the proxy answered or that it refused drained nothing
and is not counted. Telemetry only; no quota reads it. The log line stays
proxy-usage-read-failed.
This commit is contained in:
jason.woltje committed 2026-11-02 20:08:50 -06:00
1 parent 3dc824ea12
commit 38cfa72335
5 files changed
+92 -8

No files matched your search

+19 -3
View File
@@ -12,6 +12,9 @@ export function createProxyUsage({ store, read, client, records, log, now = Date
const loader = makeLoader({ log }); const loader = makeLoader({ log });
let due = 0, previous = '', pending = null, closed = false; let due = 0, previous = '', pending = null, closed = false;
const states = new Map(); const states = new Map();
// #778: per enabled business, the batches taken off the proxy queue and then not written, since
// this bus started. Telemetry only: the events in a dropped batch are gone and no quota reads this.
const dropped = new Map();
function configured() { function configured() {
return Object.entries(read()).filter(([, b]) => b.plugins?.usage === 'cliproxy-queue').map(([business, b]) => { return Object.entries(read()).filter(([, b]) => b.plugins?.usage === 'cliproxy-queue').map(([business, b]) => {
checkUsageSettings(b.usage ?? {}); checkUsageSettings(b.usage ?? {});
@@ -27,13 +30,22 @@ export function createProxyUsage({ store, read, client, records, log, now = Date
if (signature !== previous) { previous = signature; due = 0; } if (signature !== previous) { previous = signature; due = 0; }
if (now() < due) return; if (now() < due) return;
due = now() + Math.min(...enabled.map(b => b.pollSeconds)) * 1000; due = now() + Math.min(...enabled.map(b => b.pollSeconds)) * 1000;
// drained: the proxy has given this batch up, because module.read returned or because the client
// refused a 2xx answer it had already taken (proxy-client-response). Down, redirected or non-2xx
// answers drained nothing. written: the rows are in.
let drained = false, written = false;
try { try {
await loader.load({ usage: 'cliproxy-queue' }); await loader.load({ usage: 'cliproxy-queue' });
const module = loader.modules('usage')[0], management = await client(); const module = loader.modules('usage')[0], management = await client();
if (!module || !management) throw Error('unavailable'); if (!module || !management) throw Error('unavailable');
// Row 333 R3 (#1831): the module gets the one read it needs and nothing else. No path from // Row 333 R3 (#1831): the module gets the one read it needs and nothing else. No path from
// its argument reaches getKeys, putKeys, the OAuth calls or any other management call. // its argument reaches getKeys, putKeys, the OAuth calls or any other management call.
const events = await module.read(Object.freeze({ readUsageQueue: () => management.readUsageQueue() })); const readUsageQueue = async () => {
try { return await management.readUsageQueue(); }
catch (error) { if (error?.code === 'proxy-client-response') drained = true; throw error; }
};
const events = await module.read(Object.freeze({ readUsageQueue }));
drained = true;
const owners = new Map(); const owners = new Map();
for (const record of records()) { for (const record of records()) {
if (record.service !== 'model') continue; if (record.service !== 'model') continue;
@@ -64,10 +76,14 @@ export function createProxyUsage({ store, read, client, records, log, now = Date
JSON.stringify({ modelKeyId: e.keyId, failed: e.failed, statusCode: e.statusCode }), e.input, e.output, e.cacheWrite, e.cacheRead); JSON.stringify({ modelKeyId: e.keyId, failed: e.failed, statusCode: e.statusCode }), e.input, e.output, e.cacheWrite, e.cacheRead);
} }
}); });
written = true;
for (const keyId of unknown) log({ action: 'proxy.usage.reconcile', keyId, code: 'proxy-usage-unknown-key' }); for (const keyId of unknown) log({ action: 'proxy.usage.reconcile', keyId, code: 'proxy-usage-unknown-key' });
for (const { business } of enabled) states.set(business, 'available'); for (const { business } of enabled) states.set(business, 'available');
} catch { } catch {
for (const { business } of enabled) states.set(business, 'unavailable'); for (const { business } of enabled) {
states.set(business, 'unavailable');
if (drained && !written) dropped.set(business, (dropped.get(business) ?? 0) + 1);
}
log({ action: 'proxy.usage', code: 'proxy-usage-read-failed' }); log({ action: 'proxy.usage', code: 'proxy-usage-read-failed' });
} }
} }
@@ -92,7 +108,7 @@ export function createProxyUsage({ store, read, client, records, log, now = Date
} }
} }
const finish = map => [...map.values()].map(e => ({ ...e, ...Object.fromEntries(KINDS.map(k => [k, plain(e[k])])) })); const finish = map => [...map.values()].map(e => ({ ...e, ...Object.fromEntries(KINDS.map(k => [k, plain(e[k])])) }));
return { source: 'proxy', state: states.get(business) ?? 'unread', byKey: finish(byKey), byAccount: finish(byAccount) }; return { source: 'proxy', state: states.get(business) ?? 'unread', droppedBatches: dropped.get(business) ?? 0, byKey: finish(byKey), byAccount: finish(byAccount) };
} }
return { tick, view, async close() { closed = true; await pending; } }; return { tick, view, async close() { closed = true; await pending; } };
} }
+49 -3
View File
@@ -15,15 +15,15 @@ const id = s => createHash('sha256').update(s).digest('hex').slice(0,12);
const key='msk-fake-client-value',source='fake-upstream-value',keyId=id(key); const key='msk-fake-client-value',source='fake-upstream-value',keyId=id(key);
async function fixture(t,{makeLoader}={}) { async function fixture(t,{makeLoader}={}) {
const root=mkdtempSync(join(tmpdir(),'proxy-usage-')),store=new Store(root),logs=[],calls=[]; const root=mkdtempSync(join(tmpdir(),'proxy-usage-')),store=new Store(root),logs=[],calls=[];
let events=[],now=0,fail=false; let events=[],now=0,fail=false,noClient=false,recs=[{instance:'demo/coder',service:'model',keyId,retiring:[]}];
const server=http.createServer((req,res)=>{calls.push(req.url);res.writeHead(fail?500:200);res.end(JSON.stringify(events));events=[];}); const server=http.createServer((req,res)=>{calls.push(req.url);res.writeHead(fail?500:200);res.end(JSON.stringify(events));events=[];});
await new Promise(r=>server.listen(0,'127.0.0.1',r)); await new Promise(r=>server.listen(0,'127.0.0.1',r));
const client=new ManagementClient({baseUrl:`http://127.0.0.1:${server.address().port}`,key:'fake-management',receipt:e=>logs.push(e)}); const client=new ManagementClient({baseUrl:`http://127.0.0.1:${server.address().port}`,key:'fake-management',receipt:e=>logs.push(e)});
let doc={plugins:{},launch:{limits:{tokens:{keys:{[keyId]:{limit:1,since:'2026-01-01T00:00:00.000Z'}}}}}}; let doc={plugins:{},launch:{limits:{tokens:{keys:{[keyId]:{limit:1,since:'2026-01-01T00:00:00.000Z'}}}}}};
const reader=createProxyUsage({store,read:()=>({demo:doc}),client:()=>client,...(makeLoader?{makeLoader}:{}),records:()=>[{instance:'demo/coder',service:'model',keyId,retiring:[]}],log:e=>logs.push(e),now:()=>now}); const reader=createProxyUsage({store,read:()=>({demo:doc}),client:()=>noClient?null:client,...(makeLoader?{makeLoader}:{}),records:()=>recs,log:e=>logs.push(e),now:()=>now});
t.after(async()=>{await reader.close();await new Promise(r=>server.close(r));store.close();rmSync(root,{recursive:true,force:true});}); t.after(async()=>{await reader.close();await new Promise(r=>server.close(r));store.close();rmSync(root,{recursive:true,force:true});});
const event=(over={})=>({api_key:key,source,failed:true,fail:{status_code:503,body:source},tokens:{input_tokens:9,output_tokens:2},...over}); const event=(over={})=>({api_key:key,source,failed:true,fail:{status_code:503,body:source},tokens:{input_tokens:9,output_tokens:2},...over});
return {store,logs,calls,reader,client,event,setEvents:v=>{events=v;},clock:v=>{now=v;},enable:(pollSeconds)=>{doc={...doc,plugins:{usage:'cliproxy-queue','limit-check':['token-limit']},...(pollSeconds===undefined?{}:{usage:{cliproxyQueue:{pollSeconds}}})};},doc:()=>doc,fail:()=>{fail=true;}}; return {store,logs,calls,reader,client,event,setEvents:v=>{events=v;},clock:v=>{now=v;},enable:(pollSeconds)=>{doc={...doc,plugins:{usage:'cliproxy-queue','limit-check':['token-limit']},...(pollSeconds===undefined?{}:{usage:{cliproxyQueue:{pollSeconds}}})};},doc:()=>doc,fail:()=>{fail=true;},noClient:v=>{noClient=v;},setRecords:v=>{recs=v;}};
} }
test('P5 usage plugin off by default, default poll is 15 seconds and configured polls skip early ticks',async t=>{ test('P5 usage plugin off by default, default poll is 15 seconds and configured polls skip early ticks',async t=>{
const f=await fixture(t);await f.reader.tick();assert.equal(f.calls.length,0);assert.equal(f.reader.view('demo'),null); const f=await fixture(t);await f.reader.tick();assert.equal(f.calls.length,0);assert.equal(f.reader.view('demo'),null);
@@ -109,3 +109,49 @@ test('R3 the usage module is handed one function, readUsageQueue, and no path to
assert.deepEqual(called,['readUsageQueue']); assert.deepEqual(called,['readUsageQueue']);
assert.equal(f.reader.view('demo').byKey[0].failures,1); assert.equal(f.reader.view('demo').byKey[0].failures,1);
}); });
// #778 (Vikunja): the queue read drains the proxy, so a batch that is then not written is lost. The count
// is per enabled business, in memory since the bus started, and telemetry only.
test('#778 a drained batch that is not written counts as dropped; a poll that drained nothing does not; a good poll keeps the count',async t=>{
const f=await fixture(t);f.enable();
const usage=await createUsage({store:f.store,businesses:{demo:f.doc()},log:()=>{},proxyView:b=>f.reader.view(b)});
assert.equal(f.reader.view('demo').droppedBatches,0);
// An invalid batch: the client refuses the 2xx answer whole, and the proxy has already given the batch up.
f.setEvents([f.event(),f.event({source:'malformed-upstream-canary',tokens:{input_tokens:-1}})]);await f.reader.tick();
assert.equal(f.reader.view('demo').droppedBatches,1);assert.equal(f.reader.view('demo').state,'unavailable');
// An ambiguous owner: one key id held by two agents.
f.setRecords([{instance:'demo/coder',service:'model',keyId,retiring:[]},{instance:'demo/other',service:'model',keyId,retiring:[]}]);
f.setEvents([f.event()]);f.clock(15000);await f.reader.tick();
assert.equal(f.reader.view('demo').droppedBatches,2);
// No client before the read: nothing was drained, so nothing was dropped.
f.noClient(true);f.setEvents([f.event()]);f.clock(30000);await f.reader.tick();
assert.equal(f.reader.view('demo').droppedBatches,2);assert.equal(f.reader.view('demo').state,'unavailable');
// A good poll sets the state back and leaves the count alone. The event set while the client was missing is still queued.
f.noClient(false);f.setRecords([{instance:'demo/coder',service:'model',keyId,retiring:[]}]);f.clock(45000);await f.reader.tick();
assert.equal(f.reader.view('demo').state,'available');assert.equal(f.reader.view('demo').droppedBatches,2);
assert.equal(f.reader.view('demo').byKey[0].requests,1);
// The usage view carries it, and a log line names no event content.
assert.equal(usage.view('demo').proxy.droppedBatches,2);
for(const secret of [key,source,'malformed-upstream-canary'])assert.equal(JSON.stringify([f.logs,usage.view('demo')]).includes(secret),false);
assert.deepEqual(f.logs.filter(e=>e.action==='proxy.usage').map(e=>e.code),['proxy-usage-read-failed','proxy-usage-read-failed','proxy-usage-read-failed']);
});
test('#778 a batch the module returns in a shape the bus refuses is a drop',async t=>{
const makeLoader=opts=>{const loader=createLoader(opts);return {...loader,modules:kind=>loader.modules(kind).map(m=>kind==='usage'&&m?{interfaceVersion:m.interfaceVersion,read:async arg=>{await arg.readUsageQueue();return [{keyId:'not-a-key-id',accountId:id(source)}];}}:m)};};
const f=await fixture(t,{makeLoader});f.enable();f.setEvents([f.event()]);await f.reader.tick();
assert.equal(f.reader.view('demo').state,'unavailable');assert.equal(f.reader.view('demo').droppedBatches,1);
assert.equal(f.store.all('SELECT * FROM usage_records').length,0);
});
test('#778 a read the proxy refused or never answered drained nothing and is not a drop',async t=>{
const f=await fixture(t);f.enable();f.fail();await f.reader.tick();
assert.equal(f.reader.view('demo').state,'unavailable');assert.equal(f.reader.view('demo').droppedBatches,0);
});
test('#778 a failed transaction drops the batch for every enabled business',async t=>{
const f=await fixture(t);f.enable();
const broken={all:(...a)=>f.store.all(...a),run:(...a)=>f.store.run(...a),transaction:()=>{throw new Error('disk full');}};
const both={demo:f.doc(),other:f.doc()};
const reader=createProxyUsage({store:broken,read:()=>both,client:()=>f.client,records:()=>[{instance:'demo/coder',service:'model',keyId,retiring:[]}],log:e=>f.logs.push(e),now:()=>0});
t.after(()=>reader.close());
f.setEvents([f.event()]);await reader.tick();
for(const business of ['demo','other']){assert.equal(reader.view(business).droppedBatches,1);assert.equal(reader.view(business).state,'unavailable');}
assert.equal(f.store.all('SELECT * FROM usage_records').length,0);
});
@@ -30,7 +30,14 @@ Telemetry uses the existing append-only usage table with source
excludes it before every limit check and native usage total. Proxy totals may be excludes it before every limit check and native usage total. Proxy totals may be
incomplete (60-second upstream retention and a 100-event drain); the Console incomplete (60-second upstream retention and a 100-event drain); the Console
labels them proxy-reported and reports the reader's availability. They never labels them proxy-reported and reports the reader's availability. They never
independently enforce quotas. independently enforce quotas. A batch the proxy has already given up and the
bus then does not save (the client refuses its answer, the bus refuses its
shape or an ambiguous key owner, or the write fails) is lost. The reader counts
these per business since the bus started and the usage view returns the count
as `droppedBatches` (0 when none); the Console shows it above 0. A read that
failed before the proxy answered, or that the proxy refused, drained nothing
and is not counted. The count is in memory, restarts at 0 and is not a quota
input.
Native transcript counts carry the immutable run's safe `modelKeyId` in the Native transcript counts carry the immutable run's safe `modelKeyId` in the
usage cursor, preserved at turn begin and end. The Console exposes `byKey`. usage cursor, preserved at turn begin and end. The Console exposes `byKey`.
+4 -1
View File
@@ -759,7 +759,10 @@
} }
// Row 333 R3 (#1831): a daily key quota whose key id no hired agent holds, now or before. // Row 333 R3 (#1831): a daily key quota whose key id no hired agent holds, now or before.
const orphans = Array.isArray(value.orphanedKeyQuotas) && value.orphanedKeyQuotas.length ? `<ul id="token-usage-orphans" aria-label="Key quotas that match no agent">${value.orphanedKeyQuotas.map(id => `<li>Key quota ${txt(id)} matches no agent, so it limits nothing. A fire and re-hire gives the agent a new key; set the quota on the new key id.</li>`).join('')}</ul>` : ''; const orphans = Array.isArray(value.orphanedKeyQuotas) && value.orphanedKeyQuotas.length ? `<ul id="token-usage-orphans" aria-label="Key quotas that match no agent">${value.orphanedKeyQuotas.map(id => `<li>Key quota ${txt(id)} matches no agent, so it limits nothing. A fire and re-hire gives the agent a new key; set the quota on the new key id.</li>`).join('')}</ul>` : '';
const proxy = value.proxy ? `<section aria-label="Proxy-reported usage"><h3>Proxy-reported usage</h3><p>Optional proxy telemetry never enforces a quota. Status: ${txt(value.proxy.state)}. These counts cover drained events and may be incomplete.</p><div class="table-wrap"><table><thead><tr><th>Proxy account ID</th><th>Input</th><th>Output</th><th>Cache write</th><th>Cache read</th><th>Requests</th><th>Failures</th></tr></thead><tbody>${(value.proxy.byAccount || []).map(row => `<tr><th scope="row">${txt(row.accountId)}</th>${['input','output','cacheWrite','cacheRead','requests','failures'].map(k => `<td>${txt(row[k])}</td>`).join('')}</tr>`).join('')}</tbody></table></div></section>` : ''; // #778: batches the proxy gave up and the bus did not save, since the bus started. Shown only above 0.
const lost = Number.isSafeInteger(value.proxy?.droppedBatches) ? value.proxy.droppedBatches : 0;
const dropped = lost > 0 ? `<p id="token-usage-proxy-dropped" role="status">${txt(lost)} ${lost === 1 ? 'batch' : 'batches'} of proxy usage events could not be saved since the bus started. The events in a dropped batch are lost and are not in these totals.</p>` : '';
const proxy = value.proxy ? `<section aria-label="Proxy-reported usage"><h3>Proxy-reported usage</h3><p>Optional proxy telemetry never enforces a quota. Status: ${txt(value.proxy.state)}. These counts cover drained events and may be incomplete.</p>${dropped}<div class="table-wrap"><table><thead><tr><th>Proxy account ID</th><th>Input</th><th>Output</th><th>Cache write</th><th>Cache read</th><th>Requests</th><th>Failures</th></tr></thead><tbody>${(value.proxy.byAccount || []).map(row => `<tr><th scope="row">${txt(row.accountId)}</th>${['input','output','cacheWrite','cacheRead','requests','failures'].map(k => `<td>${txt(row[k])}</td>`).join('')}</tr>`).join('')}</tbody></table></div></section>` : '';
return `<section class="panel" aria-labelledby="token-usage-title"><h2 id="token-usage-title">Token usage</h2><p>Best reading of session-editable transcripts, not proof. Unknown turns may have used more tokens. Account is unassigned until account tracking is configured.</p><div class="table-wrap"><table id="token-usage-table"><thead><tr><th scope="col">Subject</th><th scope="col">Input</th><th scope="col">Output</th><th scope="col">Cache write</th><th scope="col">Cache read</th><th scope="col">Unknown turns</th></tr></thead><tbody>${rows.join('')}</tbody></table></div>${orphans}${proxy}</section>`; return `<section class="panel" aria-labelledby="token-usage-title"><h2 id="token-usage-title">Token usage</h2><p>Best reading of session-editable transcripts, not proof. Unknown turns may have used more tokens. Account is unassigned until account tracking is configured.</p><div class="table-wrap"><table id="token-usage-table"><thead><tr><th scope="col">Subject</th><th scope="col">Input</th><th scope="col">Output</th><th scope="col">Cache write</th><th scope="col">Cache read</th><th scope="col">Unknown turns</th></tr></thead><tbody>${rows.join('')}</tbody></table></div>${orphans}${proxy}</section>`;
} }
// Row 155 (#1649, Q169): each assistant instance's settings, its seat name and a stop. A save // Row 155 (#1649, Q169): each assistant instance's settings, its seat name and a stop. A save
@@ -28,3 +28,15 @@ test('R3 Console marks an orphaned key quota by id and says it limits nothing',(
const hostile=render({total:counts,byKey:[],orphanedKeyQuotas:['<img src=x>']}); const hostile=render({total:counts,byKey:[],orphanedKeyQuotas:['<img src=x>']});
assert.doesNotMatch(hostile,/<img/);assert.match(hostile,/&lt;img src=x&gt;/); assert.doesNotMatch(hostile,/<img/);assert.match(hostile,/&lt;img src=x&gt;/);
}); });
// #778: batches the proxy gave up and the bus did not save. Shown in the proxy section only when above 0.
test('#778 Console says how many proxy batches were dropped, only when there are any, and that their events are not in the totals',()=>{
const native={total:counts,byKey:[]},proxy=(over={})=>({source:'proxy',state:'available',byAccount:[],...over});
const one=render({...native,proxy:proxy({droppedBatches:1})});
assert.match(one,/<p id="token-usage-proxy-dropped" role="status">1 batch of proxy usage events could not be saved since the bus started\. The events in a dropped batch are lost and are not in these totals\.<\/p>/);
assert.ok(one.indexOf('token-usage-proxy-dropped')>one.indexOf('Proxy-reported usage'));
assert.match(render({...native,proxy:proxy({droppedBatches:3})}),/>3 batches of proxy usage events could not be saved/);
for(const over of [{droppedBatches:0},{},{droppedBatches:-1},{droppedBatches:'2'},{droppedBatches:1.5},{droppedBatches:null}]){
const page=render({...native,proxy:proxy(over)});assert.match(page,/Proxy-reported/);assert.doesNotMatch(page,/token-usage-proxy-dropped|dropped batch/);
}
assert.doesNotMatch(render({...native,proxy:null}),/token-usage-proxy-dropped/);
});