[ISS-1] api_tokens.last_used_at wordt bij elk request geschreven: lock-contention geeft api_token_usage_write_failed (dispatch) #69

New issue

Open

opened 2026-10-04 23:44:33 +02:00 by janpeter · 0 comments

janpeter commented

2026-10-04 23:44:33 +02:00

Owner

Beheerd door Scrum4Me — wijzigingen hier worden overschreven. Bron: https://thuis.jp-visser.nl/issues/cmuuccpdt0009j217gj66ojqi

Status: new · Severity: s4_minor · Gemeld door: mac:claude · Occurrences: 1 (laatst: 2026-10-04T21:36:53.633Z) · Aangemaakt: 2026-10-04T21:36:53.633Z

Registratie

Symptoom (scrum4me-server, scrum4me-dispatch.service). De log toont herhaaldelijk api_token_usage_write_failed interface=dispatch code=WRITE_FAILED: 331× sinds de start op 2026-10-03, en 7× in één venster van ca. 60 s op 2026-10-04. api_tokens.last_used_at van het supervisor-token blijft wel actueel. Er is geen functionele schade.

Code.

scrum4me-mcp src/dispatch/token-usage.ts: na elk geslaagd bearer-request draait recordDispatchTokenUse een eigen transactie met lock_timeout = 100ms, statement_timeout = 500ms en 1 s acquire-timeout. Elke fout wordt ingeslikt en alleen als de generieke regel hierboven gelogd; de echte oorzaak verdwijnt dus.
scrum4me-shared lib/api-token-usage.ts (apiTokenUsageUpdate): UPDATE api_tokens SET last_used_at = $3 WHERE id=$1 AND user_id=$2 AND revoked_at IS NULL AND (last_used_at IS NULL OR last_used_at < $3). Er is geen throttle: elk request schrijft dezelfde rij.

Waarschijnlijke oorzaak (hypothese, nog niet met foutcode bevestigd).

Beide dispatch-supervisors delen één token. Samen doen ze ca. 100 geslaagde requests per minuut (heartbeat en claim).
Overlappende UPDATEs op dezelfde rij wachten op de row-lock, en de tweede faalt na 100 ms (55P03 lock_not_available).
Permissies vallen af: dan zou elke write falen en last_used_at stilstaan.

Gevolg.

Lognoise.
Ca. 100 writes per minuut op één hot row (onnodige DB-last en dead tuples).
last_used_at loopt hooguit enkele seconden achter.

Voorgestelde aanpak (klein).

Bevestigen: log in de catch van recordDispatchTokenUse (en het MCP-equivalent src/token-usage.ts) de Postgres-foutcode of het acquire-timeout-type, zonder secrets.
Throttlen in de shared query: schrijf alleen als last_used_at IS NULL OR last_used_at < $3 - interval '60 seconds'. Dat brengt het terug van ca. 100 naar 1 write per minuut per token en neemt de contention weg. Minuutprecisie volstaat voor "Laatst gebruikt" (IDEA-227).
Na een shared-merge: submodule-bump in scrum4me-mcp (dispatch en MCP-HTTP) en in de andere consumers. Daarna deployen.

Testcontract: de query moet idempotent blijven en de tijdvolgorde bewaken; tests op "binnen 60 s geen update" en "na 60 s wel".

Los hiervan, niet onderzocht: tick_listener: dropped_on_error elke 15 min, met direct daarna listening, in dezelfde service.

Onderzoek

Nog geen onderzoek.

Oplossing

Nog geen oplossing.

> Beheerd door Scrum4Me — wijzigingen hier worden overschreven. Bron: https://thuis.jp-visser.nl/issues/cmuuccpdt0009j217gj66ojqi Status: new · Severity: s4_minor · Gemeld door: mac:claude · Occurrences: 1 (laatst: 2026-10-04T21:36:53.633Z) · Aangemaakt: 2026-10-04T21:36:53.633Z ## Registratie **Symptoom (scrum4me-server, `scrum4me-dispatch.service`).** De log toont herhaaldelijk `api_token_usage_write_failed interface=dispatch code=WRITE_FAILED`: 331× sinds de start op 2026-10-03, en 7× in één venster van ca. 60 s op 2026-10-04. `api_tokens.last_used_at` van het supervisor-token blijft wel actueel. Er is geen functionele schade. **Code.** - scrum4me-mcp `src/dispatch/token-usage.ts`: na elk geslaagd bearer-request draait `recordDispatchTokenUse` een eigen transactie met `lock_timeout = 100ms`, `statement_timeout = 500ms` en 1 s acquire-timeout. Elke fout wordt ingeslikt en alleen als de generieke regel hierboven gelogd; de echte oorzaak verdwijnt dus. - scrum4me-shared `lib/api-token-usage.ts` (`apiTokenUsageUpdate`): `UPDATE api_tokens SET last_used_at = $3 WHERE id=$1 AND user_id=$2 AND revoked_at IS NULL AND (last_used_at IS NULL OR last_used_at < $3)`. Er is **geen throttle**: elk request schrijft dezelfde rij. **Waarschijnlijke oorzaak (hypothese, nog niet met foutcode bevestigd).** - Beide dispatch-supervisors delen één token. Samen doen ze ca. 100 geslaagde requests per minuut (heartbeat en claim). - Overlappende UPDATEs op dezelfde rij wachten op de row-lock, en de tweede faalt na 100 ms (`55P03 lock_not_available`). - Permissies vallen af: dan zou elke write falen en `last_used_at` stilstaan. **Gevolg.** - Lognoise. - Ca. 100 writes per minuut op één hot row (onnodige DB-last en dead tuples). - `last_used_at` loopt hooguit enkele seconden achter. **Voorgestelde aanpak (klein).** 1. **Bevestigen:** log in de `catch` van `recordDispatchTokenUse` (en het MCP-equivalent `src/token-usage.ts`) de Postgres-foutcode of het acquire-timeout-type, zonder secrets. 2. **Throttlen in de shared query:** schrijf alleen als `last_used_at IS NULL OR last_used_at < $3 - interval '60 seconds'`. Dat brengt het terug van ca. 100 naar 1 write per minuut per token en neemt de contention weg. Minuutprecisie volstaat voor "Laatst gebruikt" (IDEA-227). 3. Na een shared-merge: submodule-bump in scrum4me-mcp (dispatch en MCP-HTTP) en in de andere consumers. Daarna deployen. Testcontract: de query moet idempotent blijven en de tijdvolgorde bewaken; tests op "binnen 60 s geen update" en "na 60 s wel". **Los hiervan, niet onderzocht:** `tick_listener: dropped_on_error` elke 15 min, met direct daarna `listening`, in dezelfde service. ## Onderzoek _Nog geen onderzoek._ ## Oplossing _Nog geen oplossing._

janpeter added the

severity/s4

label

2026-10-04 23:44:33 +02:00

No labels

severity/s4

No milestone

No project

No assignees

1 participant

Notifications

Due date

The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference

janpeter/scrum4me-shared#69

No description provided.

Rows
Columns