basquetWi + New ticket
movilba MOVILBA-330

El nivel debug no se escribe en app_logs desde 2026-05-14: 50 testigos ciegos y al menos una cifra ya calculada sobre un denominador congelado

Done normal cmcoder04-mba-l-ca

Medido el 2026-09-07. db02 sobre app_logs de DEV: el nivel debug esta MUERTO en la tabla desde el 2026-05-14 01:14:34 - 3375 filas debug en total, NINGUNA despues de ese instante, y 82784 filas escritas desde entonces. CAUSA, leida del codigo y no adivinada: el logueo a base se corto por esos dias y e3057166 (2026-05-20, titulo literal 'restore DB app logging') lo restablecio YA CON la exclusion level !== 'debug' en logger.ts:190. O sea que el nivel no se apago por una decision sobre debug: se perdio de rebote al restaurar, seis dias despues del corte. POR QUE NADIE LO NOTO EN CUATRO MESES: un testigo apagado no emite ningun sintoma. La unica senal posible es la AUSENCIA, y una ausencia se lee como 'no paso nada'. Es la misma forma que MOVILBA-329 (log() no persiste en el navegador) y que el hook de Postman que reporta un chequeo crasheado como artefacto desactualizado: EL INSTRUMENTO CALLADO Y EL EVENTO AUSENTE SON INDISTINGUIBLES. QUE COSTO YA, medido: el 168:1 de MOVILBA-301 -avisos de refresh vencido por sesion creada- era numerador VIVO sobre denominador CONGELADO, porque 'New session created' se emitia en debug y dejo de escribirse el 2026-05-14 mientras el numerador seguia corriendo. Acotando ambos lados a la ventana donde los dos podian escribirse la relacion es 2.4:1. db02 retiro la cifra. QUEDAN 50 llamadas log('debug', ...) en 11 archivos, todas invisibles en la base: actions/asociaciones.ts (3), app/admin/opciones/[id]/page.tsx, app/admin/users/page.tsx, contexts/PermissionContext.tsx, y el resto. NO se resuelve promoviendo las 50 - la exclusion existe para acotar volumen y era una decision correcta. Lo que hay que decidir es cuales de esas 50 son TESTIGOS de algo que alguna vez vamos a querer medir (denominadores, transiciones de estado, caminos de exito) y cuales son ruido de desarrollo. Un testigo va en info con volumen acotado por construccion; el ruido se borra, porque una llamada que no puede escribir no es logueo, es codigo muerto que parece cobertura. Ya promovidas en MOVILBA-301 las dos de auth.ts: la rotacion silenciosa del access token y 'New session created'.

Sub-tickets

No sub-tickets.
+ Add sub-ticket

Activity

  • wi-cli-venus created · 5w ago
  • wi-cli-venus assigned · 4w ago
    coder03-mba-l-cc / coder
  • coder03assistant-mba-l-ca progress · 3w ago
    coder03assistant-mba-l-ca | 2026-09-24 04:09:53 ART | dev 7d299b6a / main 721b9eb8 logger.ts still gates DB insert with level !== 'debug'; src retains many debug callsites (api-client, repositories, UI). No per-caller witness/noise classification or bounded info promotion verified; original blind-log issue remains open.
  • coder03-mba-l-cc assigned · 2w ago
    coder04-mba-l-ca
  • coder03-mba-l-cc assigned · 1w ago
    researcher-mba-l-cc / solo
  • researcher-mba-l-cc statusChanged · 1w ago
    Researcher started at 2026-10-08T11:54:26-03:00: reconciling call-site count against ticket's stated 50/11.
  • researcher-mba-l-cc spec · 1w ago
    researcher-mba-l-cc @ 2026-10-08T11:54:51-03:00 ROOT CAUSE (re-verified against current src/lib/logger.ts, unchanged): the DB-logging gate excludes debug explicitly - `level !== 'debug' && ...` immediately after the console-output block, guarded by the circuit breaker (dbCircuit.openUntil). Introduced by commit e3057166 ("restore DB app logging", 2026-05-20) as collateral of restoring DB logging after the outage that started 2026-05-14, not a deliberate decision to drop debug specifically. Still live, no change needed to confirm the defect. CALL-SITE COUNT RECONCILED: ticket says 50 calls / 11 files. First pass (single-line `log('debug'` / `log("debug"`) found 46 calls / 10 files - missing file was src/lib/auth.ts, which uses a multi-line `log(\n "debug",\n ...)` call style the first grep pattern didn't match. Adding those 3 recovers 11 files and 49 calls. Treating the remaining 49-vs-50 gap as ticket staleness (one site likely removed in a later commit, not a missed pattern) - reporting the measured 49/11, not forcing 50. PER-FILE CLASSIFICATION (testigo = promote to info; ruido = leave at debug): - src/repositories/entidades.ts (14) + src/repositories/carrocerias.ts (16) = 30/49, same shape in both: each CRUD method (findAll/countAll/findById/getById/create/update/softDelete/existsById) logs twice - "entering with params" (12 sites total) and "result" with a count/found-boolean/not-found branch (18 sites total, e.g. carrocerias.ts:308 "Carroceria not found for update", entidades.ts countAll with the row count). RECOMMEND: promote only the 18 "result" sites to info (they carry denominators and success/not-found transitions per the ticket's own framework); leave the 12 "entering" sites at debug (echo of input params, no state). - src/lib/auth.ts (3, multi-line): line 192 "Fetching user from database" (ruido, pre-query) and line 204 "found: !!user" after the lookup (TESTIGO - exact denominator/transition shape, login success-path, promote to info). Line 277 is gated `if (NODE_ENV !== "production")` and logs password-hash-presence metadata - never fires in prod regardless of DB-log level; DO NOT promote (credential-adjacent, no reason to persist it). - src/utils/connectionHandler.ts (2): "Starting API call" / "API call completed" pair, no payload - TESTIGO as a pair (gives call latency/completion visibility with zero PII cost); promote both. - src/lib/api-client.ts (4): "API request deduplicated" (testigo - dedup hit rate), "API request started" (ruido, paired with the dedup/completed signal elsewhere), "Attempting API request" with retry attempt number (TESTIGO - retry-count denominator), line 420 (need per-call review before promote, not yet read in full). - src/actions/asociaciones.ts (3): searchEntidades/getTiposAsociacion/searchPersonas entry logs with query params - ruido (params only, no result/count logged alongside); low promote value as written. - src/app/admin/opciones/[id]/page.tsx (2) + src/app/admin/users/page.tsx (2): frontend entry/result pairs, same entering/result shape as entidades.ts - the result sites are TESTIGO-class but these run client-side (admin screens); confirm GLOBAL_LOG_DB_ENABLED gate behavior for client-origin logs before promoting (server-only gate note in logger.ts: `typeof window === 'undefined'` - client-side debug logs may never reach the DB-logging branch at all regardless of level, separate defect from this ticket's scope). - src/contexts/PermissionContext.tsx (1), src/repositories/userGroups.ts (1), src/repositories/personas.ts (1): single entry-style debug call each, no result pair - ruido as written (no denominator/transition carried). NOT recommending a blanket "promote all 50 to info" - ticket's own text agrees the debug/info split itself was the right call; only ~20 of 49 sites (the result/outcome ones, listed above) fit the testigo definition. Fix = per-site level bump debug->info on the listed ~20 call sites, no change to the DB-logging gate itself. Open item before implementing: confirm whether admin-page client-side debug logs ever reach app_logs at all (window-guard above) - if not, promoting their level is a no-op and the real fix there is routing them through a server action first.
  • coder03-mba-l-cc assigned · 1w ago
    coder04-mba-l-ca / coder
  • coder03-mba-l-cc note · 1w ago
    coder03 12:03 ART: routed to coder04 after 713/400/71. Fix = restore debug persistence in logger.ts (collateral of the 2026-05-20 restore, so broken not design); the per-site level promotion is not needed once the level persists. Client-side admin logs stay out of scope here.
  • coder04-mba-l-ca progress · 1w ago
    Restored DB persistence for enabled server-side debug logs by removing the level !== debug exclusion in src/lib/logger.ts; retained GLOBAL_LOG_LEVEL gate, server-only guard, sanitizer, UUID validation, fire-and-forget insert, and circuit breaker. app_logs check already accepts debug. No per-site level promotion or client admin logging change. git diff --check clean; audit requested.
  • audit-mba-l-cc audited · 1w ago
    audit pass: typecheck+lint(logger.ts)+test:source 64/64; PROD app_logs CHECK constraint and level-mix re-queried; traced level gating and insert body
    payload
    {"scope":"typecheck+lint(logger.ts)+test:source 64/64; PROD app_logs CHECK constraint and level-mix re-queried; traced level gating and insert body","outcome":"pass","evidence":"app_logs_level_check allows debug (verified live), so debug rows are accepted; PROD already holds 3375 debug rows of 101578 total. Level enablement still gated at logger.ts:153 (levelValue > logLevel returns early) and 'missing' is still mapped to info at the insert (:204), so the diff removes only the DB-specific debug exclusion and introduces no constraint violation. Sanitizer, UUID validation and circuit breaker untouched.","reportRef":null}
  • audit-mba-l-cc audit-finding · 1w ago
    audit 2026-10-08, risk to record, NOT a blocker on this diff: the removed comment ('debug is excluded to bound insert volume') named the only thing bounding app_logs insert volume, and there is no operator control to put in its place. GLOBAL_LOG_LEVEL is a hardcoded constant = 4 (debug) at src/lib/global-settings.ts:105 with the comment 'Do not change it back to 3' - there is NO env fallback, and that same file's lines 95-97 already flag the consequence in its own words: 'Current: GLOBAL_LOG_LEVEL=4 (debug) generates excessive logs, especially for high-traffic routes' and propose adding 'process.env.GLOBAL_LOG_LEVEL ?? 4 (so prod can override to 3 or 2)' as work that has not landed. GLOBAL_LOG_DB_ENABLED defaults to true. So after this deploy every server-side debug call writes a PROD app_logs row, and the only off switch is GLOBAL_LOG_DB_ENABLED=false, which kills ALL DB logging, not just debug. Today's volume is modest (101578 rows total since 2025-12-16, ~340/day, debug only 3375) because MovilBA is pre-live and traffic is low; the risk lands at go-live, on the high-traffic routes the file itself names. Related open item: MOVILBA-9 (app_logs + audit_log purge). Recommend to coder03/Elazar, as a separate decision and not a change to this diff: land the env fallback that global-settings.ts already proposes, so PROD can drop to level 3 without disabling DB logging entirely.
  • coder03-mba-l-cc note · 1w ago
    Elazar GO 2026-10-08 12:40 ART (CLI, nqla 9b): ship the logger fix WITH the level override in the same diff - env-driven, default info in production and debug in dev, no hardcoded GLOBAL_LOG_LEVEL. Executor: coder04, same item, back to audit.
  • coder04-mba-l-ca progress · 1w ago
    Elazar GO: GLOBAL_LOG_LEVEL env override (0..4), defaults info in production/debug otherwise; DB debug persistence follows enabled level. Two-file diff to audit; prior PASS predates override.
  • coder04-mba-l-ca progress · 1w ago
    Combined diff sent to audit: APP_ENV dev/pod defaults debug (NODE_ENV is production on all deployed builds), PROD/unknown defaults info, GLOBAL_LOG_LEVEL=0..4 overrides; enabled debug reaches app_logs. Changed src/lib/global-settings.ts and src/lib/logger.ts only.
  • audit-mba-l-cc audited · 1w ago
    audit fail: 2 paths: src/lib/global-settings.ts (log-level block + GLOBAL_LOG_DB_ENABLED comment) and src/lib/logger.ts (logLevel const + removal of level!=='debug'). Gates clean, so this FAIL is on substance, not on a gate. Prior PASS predates the override and does not carry here.
    payload
    {"scope":"2 paths: src/lib/global-settings.ts (log-level block + GLOBAL_LOG_DB_ENABLED comment) and src/lib/logger.ts (logLevel const + removal of level!=='debug'). Gates clean, so this FAIL is on substance, not on a gate. Prior PASS predates the override and does not carry here.","outcome":"fail","evidence":"typecheck clean, eslint clean on both paths, test:source 65/65 at v5.6.189. Two defects: (1) Number('') === 0 and Number.isInteger(0) is true, so GLOBAL_LOG_LEVEL set but EMPTY silently disables all logging instead of erroring - measured with node, Number('')=0, Number(' ')=0; the stated contract is integer 0..4 and an empty ConfigMap value is the live failure mode here. (2) neither GLOBAL_LOG_LEVEL nor APP_ENV is NEXT_PUBLIC_*, and logger.ts is imported by client components (UserMenu.tsx, PermissionContext.tsx, LoginForm.tsx, admin/opciones/[id]/page.tsx), so in the browser both read undefined and NODE_ENV is production - the client level is pinned at 3 on every deployment, the override cannot reach it, and dev01/pod client logging silently drops from the old constant 4 to 3.","reportRef":null}
  • audit-mba-l-cc audit-finding · 1w ago
    audit-mba-l-cc 2026-10-08 ~14:05 ART - FAIL, two defects plus one consequence to state. DEFECT 1 (blocking, one line). global-settings.ts:97-101. configuredLogLevel is only checked against undefined, then passed to Number(). Number('') and Number(' ') are both 0, and Number.isInteger(0) is true, so GLOBAL_LOG_LEVEL present-but-empty passes the 0..4 validation as level 0 = logging off, app-wide, with no error. That is the opposite of the fail-closed intent the throw was added for, and an empty value in the pod ConfigMap is a failure mode this project has already hit. Fix: treat an empty or whitespace-only value like undefined, or reject it - configuredLogLevel === undefined || configuredLogLevel.trim() === ''. DEFECT 2 (blocking as an unnamed behaviour change). Neither GLOBAL_LOG_LEVEL nor APP_ENV is prefixed NEXT_PUBLIC_, and logger.ts is imported by client components - src/components/UserMenu.tsx, src/contexts/PermissionContext.tsx, src/app/user/login/LoginForm.tsx, src/app/admin/opciones/[id]/page.tsx. In the browser bundle both env reads inline to undefined and NODE_ENV is 'production', so GLOBAL_IS_DEVELOPMENT is false and the client log level is pinned at 3 on every deployment. Two consequences: the override cannot reach client logging at all, and client-side logging on dev01/pod silently drops from the old constant 4 to 3. Either expose a NEXT_PUBLIC_ twin for the client branch or state in the code that the client level is deliberately fixed at info - but it cannot stay silent, because 'GLOBAL_LOG_LEVEL=4 on dev01' will not do what the next reader expects. CONSEQUENCE, NOT A DEFECT - removing level !== 'debug' from the app_logs branch means that at level 4 every debug event now inserts a row. On dev01/pod that is the default, so this is the exact insert volume the deleted TODO item 7 warned about, and the circuit breaker is now the only bound on it. Elazar GO'd persisting enabled debug, so it ships, but the dev01/pod app_logs growth rate should be measured once after the deploy rather than assumed. VERIFIED GOOD: dropping the || 4 fallback does preserve level 0 (logger.ts:29); the APP_ENV gate is the right discriminator and matches proxy.ts:78, auth.ts:108 and health/route.ts:128; PROD and unknown default to 3 as specified; GLOBAL_IS_DEVELOPMENT is declared at global-settings.ts:11, above the new block, so there is no TDZ problem. APP_ENV='staging' gets 3, which is correct per the stated spec but differs from auth.ts, where staging is grouped with dev for session TTL - worth one deliberate line if staging is ever deployed. SIN EJERCITAR: no test covers the level resolution or the throw; no deployment was observed with the env var set. Both findings come from reading the code and from measuring Number() coercion locally.
  • coder04-mba-l-ca progress · 1w ago
    Audit FAIL corrected: empty GLOBAL_LOG_LEVEL now throws; Next config mirrors APP_ENV and GLOBAL_LOG_LEVEL into browser bundle, where logger client imports read them. Defaults remain PROD info, dev/pod debug. Three-path diff to re-audit.
  • coder04-mba-l-ca progress · 1w ago
    Coder03 clarified empty/whitespace GLOBAL_LOG_LEVEL must fall back to APP_ENV default, not throw. Updated global-settings.ts accordingly; browser receives NEXT_PUBLIC_APP_ENV/NEXT_PUBLIC_GLOBAL_LOG_LEVEL from next.config.ts. Three-path diff resubmitted.
  • audit-mba-l-cc audited · 1w ago
    audit pass: Current 3-path diff: next.config.ts env block, global-settings.ts log-level block + the GLOBAL_LOG_DB_ENABLED comment, logger.ts logLevel const + the dropped level!=='debug'. Gates ran on these 3 paths. NOT run: next build, and no test covers the level resolution or the throw.
    payload
    {"scope":"Current 3-path diff: next.config.ts env block, global-settings.ts log-level block + the GLOBAL_LOG_DB_ENABLED comment, logger.ts logLevel const + the dropped level!=='debug'. Gates ran on these 3 paths. NOT run: next build, and no test covers the level resolution or the throw.","outcome":"pass","evidence":"typecheck clean, eslint clean on the 3 paths, test:source 65/65 at v5.6.189. Both FAIL defects are addressed and I verified the fixes rather than the claims: empty/whitespace now takes the APP_ENV default branch, NOT a throw (!configuredLogLevel?.trim()), which matches coder03's clarification; '0' is truthy as a string so level 0 survives to Number(); nonnumeric and out-of-range still throw. The next.config.ts env block is BUILD-SAFE, read off the installed next 16.3.7 rather than from a build: getNextConfigEnv in next/dist/lib/static-env.js:58-70 skips any entry whose value is null or undefined, so an unset GLOBAL_LOG_LEVEL simply does not define the client key; errorIfEnvConflicted (:31-41) rejects only /^NODE_.+|^__.+$/i and NEXT_RUNTIME, and neither new key matches; config-shared.d.ts:1281 types env as Record<string, string | undefined>, so the undefined is legal, which is why typecheck passes.","reportRef":null}
  • audit-mba-l-cc audit-finding · 1w ago
    audit-mba-l-cc 2026-10-08 ~14:20 ART - PASS. Both FAIL defects fixed. Three things to carry forward, none blocking. 1. The client threshold is baked at BUILD time, the server reads it at RUNTIME. next.config.ts:28-33 mirrors APP_ENV and GLOBAL_LOG_LEVEL into NEXT_PUBLIC_ twins, and Next inlines those into the browser bundle when the build runs. The comment says the browser threshold 'matches the server threshold', which is only true when the build-time env equals the runtime env. On the pod one image serves whatever the ConfigMap says, so changing GLOBAL_LOG_LEVEL without a rebuild moves the server and leaves the browser where the image was built. Same root cause: an image built with APP_ENV unset gives NEXT_PUBLIC_APP_ENV='production', so the client sits at 3 while a dev01 server at APP_ENV=dev sits at 4. Worth one line in the comment rather than a code change. 2. Both NEXT_PUBLIC_ values are inlined in the client bundle and readable by anyone who opens it. A log level is not a secret, so this is fine - noting it only because the pattern should not be reused for anything that is. 3. Unchanged from round 1: dropping level !== 'debug' from the app_logs branch means that at level 4 every debug event inserts a row, which is the default on dev01 and pod. That is the insert volume the deleted TODO item 7 warned about, and the circuit breaker is now the only bound. Elazar GO'd it, so it ships - measure the dev01/pod app_logs growth rate once after the deploy instead of assuming it. SIN EJERCITAR: no ship path runs next build, so the config block is proven by reading next 16.3.7's getNextConfigEnv and errorIfEnvConflicted, not by a build; and no test drives the level resolution, the throw, or the browser branch.
  • coder04-mba-l-ca completed · 1w ago
    Done. Audited PASS on logger/global-settings/next.config diff; debug persistence restored with env-driven level and browser build-time exposure. PM confirms shipped/live by v5.6.194/v5.6.192 on PROD, DEV and pod. Browser threshold changes require rebuild.
bug
5w ago by wi-cli-venus
1w ago
2026-10-08 17:12