Skip to content

litellm-community: the SpendLogs pruner is not running — retention window grows monotonically #44

Closed
Closed
litellm-community: the SpendLogs pruner is not running — retention window grows monotonically#44
Assignees
barckcode
Labels
bugSomething isn't working

Description

@sre-helmcode
sre-helmcode
opened on Sep 9, 2026

What

litellm-community is configured to keep 2 days of LiteLLM_SpendLogs and prune daily. It is not pruning. The oldest row has not moved in over 24 hours of observation and the table's span keeps growing.

Config, confirmed live inside the pod (/etc/litellm/, not just in git):

maximum_spend_logs_retention_period: 2d
maximum_spend_logs_retention_interval: 1d

Observed:

when min(startTime) span rows
2026-09-08 ~22:00Z 2026-09-05 19:33:22.833 3d 02:45 1,404,423
2026-09-09 07:46Z 2026-09-05 19:33:22.833 3d 12:13 1,581,290
2026-09-09 08:47Z 2026-09-05 19:33:22.833 3d 13:14 1,600,008

Same oldest row throughout. With a 2-day period and a 1-day interval it should have been purged on 2026-09-07. No cleanup activity in the proxy logs.

Enterprise, for contrast, is pruning: 7d configured, span measured at exactly 7d (2026-09-02 → 2026-09-09), and its row count fell from 82,021 to 59,483 during a few hours of observation. So the mechanism works somewhere; community specifically is not doing it.

Why it matters

  1. It extends a credential exposure window. Per LiteLLM community: member API keys are stored in cleartext in SpendLogs (secret_fields.raw_headers) #43, community stores members' Authorization: Bearer sk-... in cleartext in proxy_server_request in 99.87% of rows. The 2-day retention was the one thing bounding how many live keys sit in the table. It is not bounding anything.
  2. Unbounded growth. The table is at 1.6M rows and ~1,500 rows/minute of ingest with store_prompts_in_spend_logs: true, so rows are large. There is prior art on this exact database filling up (project_litellm_dailytagspend_bloat: DBs reached 179/97 GB).
  3. Every measurement taken against this table inherits a wrong window. nan-devops#289 had to correct "1 row in 30 days" to "the retained window"; the retained window is itself not what the config says. Anything derived from "we keep 2 days" is wrong.

Where to look

  • Whether the pruner task actually starts: it is a background job in the proxy, and community runs 10 replicas — check whether it is leader-elected, and whether whichever replica owns it is the one that keeps getting restarted.
  • Whether it errors silently. The DailyTagSpend bloat incident showed jobs on this database timing out without surfacing.
  • Whether the delete is too large to complete inside its window: 1.6M rows of full request bodies is a lot to remove in one pass, and per feedback_purga_masiva_postgres_cnpg the real ceiling here is WAL archiving to R2 and autovacuum, not the DELETE.

Do not fix by

Turning off store_prompts_in_spend_logs to shrink the rows. That is a separate decision (see #43 option 2) and it would mask this bug rather than fix it — the pruner would still not be running.

Evidence trail

Activity

  1. sre-helmcode
    assigned
    barckcode
    on Sep 9, 2026
  2. sre-helmcode
    added
    bugSomething isn't working
    on Sep 9, 2026

  3. sre-helmcode commented on Sep 9, 2026

    @sre-helmcode
    sre-helmcode
    on Sep 9, 2026
    ContributorAuthor

    Causa raíz encontrada, y está en el runbook que ya teníamos

    docs/runbooks/litellm-spend-table-bloat.md:55-58 calculó el techo del barrido hace meses. Verificado en la imagen viva (constants.py:1428-1429, ruta resuelta con import litellm):

    SPEND_LOG_RUN_LOOPS          = 500     (env-overridable)
SPEND_LOG_CLEANUP_BATCH_SIZE = 1000    (env-overridable)
                             = 500.000 filas por ejecución

    Con maximum_spend_logs_retention_interval: "1d" eso es 500k filas/día de capacidad de purga. Y el PodLockManager garantiza que solo un pod barre, así que las 10 réplicas no suman.

    La ingesta ha crecido hasta cruzar ese techo. Buckets horarios cerrados del primario, 2026-09-09:

    03:00  13.238   220,6/min
04:00  14.016   233,6/min
05:00  17.048   284,1/min
06:00  17.933   298,9/min
07:00  18.729   312,2/min
08:00  19.666   327,8/min

    Media 24h: 352,5 filas/min → ~508k/día. La hora de las 08:00 sola proyecta ~472k/día.

    El runbook, en :64, tenía a community en ~250-285k/día con el veredicto "drains, in equilibrium". Eso ya no es cierto: la ingesta se ha duplicado y ahora iguala o supera el techo. El barrido tendría que borrar el día entrante más el día y medio de atraso acumulado, con una capacidad que apenas cubre lo primero. Por eso min(startTime) no se mueve: no es que el barrido no corra, es que no puede ganar.

    El arreglo ya está probado en el otro tenant

    Enterprise pasó por esto mismo y la solución está documentada en :67:

    maximum_spend_logs_retention_interval: "6h"   # 4 x 500k = 2M/dia

    Community sigue en 1d. Cambiarlo a 6h da 4x de capacidad, muy por encima de los ~508k/día actuales, y deja margen para que drene el atraso.

    Alternativa o complemento: subir SPEND_LOG_RUN_LOOPS por env. Pero 6h es el camino ya validado aquí y no toca constantes del upstream.

    Advertencia del propio runbook (:67-68): "Do not copy community's interval without redoing that sum" — funciona en la otra dirección también. Antes de aplicar 6h, comprobar que el barrido más frecuente no compite con el archivado de WAL a R2, que es el techo real según feedback_purga_masiva_postgres_cnpg.

    Dos correcciones a este issue

    La tasa que escribí en "Why it matters" era errónea. Puse "~1.500 filas/minuto". Son ~350/min (media 24h; máximo 607; cero minutos por encima de 1.000 en 24h). Lo desmienten los propios snapshots de arriba: 1.581.290 @07:46Z → 1.600.008 @08:47Z son 18.718 filas en 61 min = 307/min. Afirmé una tasa sin medirla, teniendo la medición en la misma tabla.

    Y el runbook de bloat necesita corregirse, no solo este issue. :64 (la fila de ingesta de community) y :399 ("Community SpendLogs is 50 GB for ~617k live rows. Its 2d retention works" — hoy son 1,6M filas y no funciona) son la referencia a la que irá quien vea llenarse esta base. Va en nan-devops#289.

  4. sre-helmcode commented on Sep 9, 2026

    @sre-helmcode
    sre-helmcode
    on Sep 9, 2026
    ContributorAuthor

    Mi causa raíz era incorrecta. La real es el scheduler, no la aritmética

    Un reviewer la tumbó y lo he verificado. Retiro lo del comentario anterior.

    El job de limpieza nunca se dispara. proxy_server.py:4645-4657 lo registra así:

    scheduler.add_job(..., "interval", seconds=interval_seconds + random.randint(0, 60))

    Sin start_date. APScheduler con un trigger interval y sin fecha de inicio dispara por primera vez un intervalo completo después del registro, o sea después del arranque del pod. Con _interval: "1d" eso son 24h de vida del pod.

    Edad de los pods de community, medida ahora:

    6 pods   2026-09-09T06:19  (~6h45m)
1 pod    2026-09-09T04:43  (~8h20m)
3 pods   2026-09-08T21:56-21:59  (~15h)

    Ninguno ha alcanzado nunca las 24h. Community ha rotado varios ReplicaSets en las últimas 39h (parte de ello son mis propios reinicios de hoy para el rollout del hook, parte rollouts normales). El barrido a 1d no llega a ejecutarse jamás: cada rollout reinicia el contador.

    Y enterprise funciona por lo mismo, no por la aritmética que escribí. Sus dos pods son de 2026-09-08T21:56-21:58, ~15h, y su _interval es 6h. 6h < 15h, así que dispara. No es que 4×500k > 880k.

    Dos correcciones más a lo que escribí

    La ingesta no está en el techo. Puse "~508k/día" extrapolando desde los buckets horarios de la mañana. Días completos reales:

    2026-09-06   424.446
2026-09-07   427.012
2026-09-08   514.001

    Dos de los tres están por debajo del techo. La capacidad por ejecución tampoco es 500k exactos: el corte es run_count > SPEND_LOG_RUN_LOOPS (spend_log_cleanup.py:77-82), así que son 501 lotes = 501.000. El techo nunca fue el problema.

    Y el tamaño que importa faltaba. La tabla está en 136 GB: heap 2.472 MB, índices 741 MB, TOAST 133 GB. Ese TOAST es la columna proxy_server_request, o sea que los 133 GB son mayoritariamente los cuerpos de peticiones con las credenciales en claro de #43. Un solo número que dimensiona los dos issues.

    El arreglo correcto

    _interval: "6h" es a lo sumo una mitigación coincidente: seis de los diez pods ya son más jóvenes que 6h45m, así que un rollout en mal momento vuelve a dejarlo sin disparar. No es el arreglo.

    Lo que dispara por reloj de pared existe en 1.83.14 y no lo estábamos usando:

    general_settings:
  maximum_spend_logs_cleanup_cron: "7 */6 * * *"

    proxy_server.py:4617-4633 lo comprueba antes de la rama del intervalo y usa CronTrigger.from_crontab, que es independiente de la edad del pod. El PodLockManager sigue garantizando que solo un pod barre. Cada 6h da 4 ejecuciones/día × 501k = ~2M/día, suficiente para drenar el atraso acumulado y luego mantener el ritmo con margen.

    Lo que no cambia

    Que la ventana de la tabla viva no está acotada mientras esto no se arregle, y que eso es también cuánto tiempo llevan ahí las credenciales de #43.

  5. sre-helmcode commented on Sep 10, 2026

    @sre-helmcode
    sre-helmcode
    on Sep 10, 2026
    ContributorAuthor

    Desplegado, y pendiente de la única verificación que importa

    nan-devops#290 mergeado como a548384 y desplegado. El cron está en el config vivo de los pods:

    maximum_spend_logs_cleanup_cron: 7 */6 * * *

    Y el sync de los values cambió checksum/config de 38381388 a 6e6db0dd, que rotó los diez pods por sí solo — exactamente lo que las notas de despliegue predijeron con helm template, así que no hizo falta rollout restart.

    Lo que NO está verificado todavía: que el barrido se ejecute. El cron dispara a 00:07/06:07/12:07/18:07 UTC y ninguno ha caído aún desde el despliegue. La comprobación es una sola consulta:

    SET statement_timeout='60s';
SELECT min("startTime"), max("startTime")-min("startTime") AS span, count(*)
FROM "LiteLLM_SpendLogs";

    min("startTime") lleva clavado en 2026-09-05 19:33:22.833. Cuando se mueva, esto está cerrado. Si a las 12:07 UTC no se ha movido, el diagnóstico de edad-de-pod es incompleto y hay que mirar el PodLockManager y los logs del pod que gane el lock.

    Nota de la revisión, que confirma el diagnóstico en vez de contradecirlo: el job por interval SÍ disparó una vez, ~24h después del reinicio del 2026-09-08 22:56, así que el atraso más allá de la ventana de 2d es de solo ~30k filas. Es decir el mecanismo funciona cuando un pod vive lo suficiente; el problema era exactamente que no viven tanto.

    Pendiente aparte, en #46: enterprise sigue con _interval: "6h" y sin cron, o sea con el mismo fallo latente de edad de pod.

  6. sre-helmcode commented on Sep 10, 2026

    @sre-helmcode
    sre-helmcode
    on Sep 10, 2026
    ContributorAuthor

    Resolved — and my earlier report on this issue was wrong

    The pruner is running. I said it was not, and that was a measurement error on my side, not a change in the system.

    The evidence

    min("startTime")   = 2026-09-08 12:07:00.063
the 12:07 cutoff   = 2026-09-10 12:07 UTC − 2d = 2026-09-08 12:07
last_autovacuum    = 2026-09-10 12:09:36+00

    min sits 63 ms past the cutoff that only the 12:07 UTC run can produce, and autovacuum fired two minutes behind it. That run reclaimed ~5h46 of rows (06:21 → 12:07, roughly 150k). The maximum_spend_logs_cleanup_cron: "7 */6 * * *" shipped in nan-devops#290 fixed this issue.

    Why I reported the opposite

    I watched min("startTime") from 09:58 and cut the watcher off at 12:15 UTC — a deadline I picked because it felt reasonable, with nothing behind it. The run was still working, and I read a slow success as a failure. Everything I then concluded about "the cron never fires" was built on that.

    Two other instruments failed silently on the way here, both worth recording:

    • LITELLM_LOG=ERROR on community suppresses every diagnostic line in this code path — they are all verbose_proxy_logger.info. Control: 0 INFO lines in 5h against 4980 ERROR lines. So "no cleanup lines in the logs" proved nothing, in either direction.
    • Inspecting the live scheduler with kubectl exec … python3 -c does not work: it starts a new process that builds its own objects. It told me redis_cache is None, which was false — Valkey shows cronjob_lock:db_spend_update_job and cronjob_lock:db_daily_tag_spend_update_job present, so the lock manager works in the live process.

    A suspicion that the 1351 timedelta is not JSON serializable Redis errors were the pod lock failing is also wrong, checked against the stacktrace: they come from redis_cache.py:624 writing router latency data for qwen3-embedding-eu005. Recorded so nobody re-derives it.

    What the investigation did surface, which is a real problem

    LiteLLM_SpendLogs   heap 2721 MB   total 154 GB
pg_toast_10712991        148 GB    30,240,880 chunks
n_live_tup          1,013,094

    ~146 KB of TOAST per row. store_prompts_in_spend_logs: true puts the whole caller body in the row, so heap_delete() also calls heap_toast_delete() — deleting one row is ~30 further deletes in the TOAST table plus its index. Sizing a sweep in rows is wrong by two orders of magnitude, which is exactly why the 12:07 run took long enough to look like it had done nothing.

    Two consequences, both addressed in nan-devops#302:

    1. SPEND_LOG_RUN_LOOPS defaults to 500 (litellm/constants.py:1428), i.e. 501k rows in a single run. Against an archiver sustaining ~21 GB/h to R2 and a single synchronous replica that must fsync every COMMIT, a run that size risks blocking primary writes with no timeout. That replica, pg-4, restarted 5 times on 2026-09-09. Capped at 50.
    2. acquire_lock is called without a ttl and never renewed inside the batch loop (spend_log_cleanup.py:146 against the loop at 77-120), so any run longer than the 60s TTL silently loses exclusivity and a second of the ~20 schedulers (5 pods × 4 workers — --num_workers gives each uvicorn worker its own APScheduler) starts sweeping the same rows. Almost certainly what happened at 12:07. Capping the run keeps every run under the TTL.

    The cadence also moves 7 */6 → */30 there, so each run is ~13k rows instead of ~157k.

    Closing

    This issue is fixed. The remaining work is nan-devops#302, and the TOAST bloat itself (154 GB for a 2-day window) deserves its own issue rather than riding along here.

  7. sre-helmcode commented on Sep 10, 2026

    @sre-helmcode
    sre-helmcode
    on Sep 10, 2026
    ContributorAuthor

    Fixed by the maximum_spend_logs_cleanup_cron: "7 */6 * * *" shipped in nan-devops#290, verified by min("startTime") = 2026-09-08 12:07:00.063 sitting exactly on the 12:07 UTC cutoff with last_autovacuum two minutes behind it. My earlier report that the pruner was not running was a measurement error, detailed in the comment above.

    Two things this surfaced are tracked separately: nan-devops#302 caps a single sweep at 50k rows (the SPEND_LOG_RUN_LOOPS=500 default allows 501k, and the 60s pod lock is never renewed inside the batch loop), and #47 covers the 148 GB TOAST table that makes every sweep far more expensive than its row count suggests.

  8. sre-helmcode
    closed this as completedon Sep 10, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

bugSomething isn't working

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions