Incidente 2026-09-19 — Precio de cache incorrecto en Autocobro

Causa raíz, evidencia de logs y fix propuesto — TsArticulos / Dino, sucursal 1

1. Resumen

2. Reclamo de origen (ticket)

Ticket a cargo de sprados / jsalvini. Última modificación: 21/09/2026 10:19:11 por lbevolo.

Reclamo del cliente (19/09, Dino, contacto Eduardo)

Solo para que puedan ver el lunes este problema que surgió este finde. Hubo un cambio de precio de un producto en el cual no impacto en las cajas de autocobros. Luego de consultar con tipre, nos sugirió que reiniciemos el servicio TsArticulos, en el cual luego de unos minutos se probro en las pantallas y ya pasaba sin problemas. [...] Antes de reiniciar el servicio salía a 1.05 , al reiniciar empezó a salir 8490 pesos.

Adjunto del ticket: Autocompra_ReclamoDino20260919.png.

Respuesta del equipo (19 y 21/09)

Se informó que la actualización de cache para Autocompra a partir de novedades y completos ya estaba habilitada; el reinicio se sugirió por falta de acceso remoto en el momento del reclamo.

Nota del ticket: refresh observado OK post novedad

Log del proceso de novedades (sender) del 18/09 11:03:54:

Log del sender
[REFRESH][ARTIC] POST 172.17.11.210:48082/articulos/v1/cache/refresh -> HTTP 202 {"success":true,...,"status":"STARTED","refreshId":"e8de4533-a7bc-4e6a-ac0f-3888e71682f8"}
[REFRESH][PROMO] POST 172.17.11.210:48085/promos/v1/promociones/update -> HTTP 202

(Un primer log pegado en el ticket, fechado 28/08, fue corregido por el autor del ticket por este del 18/09.)

Hipótesis inicial del ticket, refutada
El ticket planteaba que "el cambio de precio no impactó en cache". El análisis muestra lo contrario: la base de datos y la precarga siempre tuvieron el precio correcto (8490.00); el precio incorrecto (1.05) provino del camino on-miss, no de una falta de actualización de cache.

3. Análisis efectuado

Fuentes analizadas

Ticket de reclamo + captura 19–21/09/2026 — síntoma exacto (1.05 vs 8490.00, EAN, efecto del reinicio).
Log del proceso de novedades (sender) 18/09 11:03 — solo prueba que el POST fue aceptado (202), no que el refresh terminó.
logs/tsarticulos.log.2026-09-17.0 (3.5 MB) 17/09 — eventos de refresh, reinicios, y cada respuesta para el EAN.
logs/tsarticulos.log.2026-09-18.0 (4.7 MB) 18/09 — ídem.
logs/tsarticulos.log.2026-09-19.0 (5.9 MB) 19/09 — ídem.
logs/tsarticulos.log.2026-09-20.0 (6.8 MB) 20/09 — ídem.
tsarticulos.log (1.1 MB) 21/09 — ídem.
Código fuente TsArticulos branch main, commit e64bf7f "v20260813- Add iVersion" — ArticuloCacheService, ArticuloCacheAdminController, ArticuloCacheRefreshScheduler, ArticulosCacheLoadRepositoryImpl, ArticulosRepository, ArticuloCacheManager, CacheConfig, application.yml.

Método

  1. Lectura del camino de refresh (POST /cache/refresh → startRefresh → executor asíncrono → buildAndSwapCache). Hallazgo: el HTTP 202 se devuelve también para SKIPPED_ALREADY_RUNNING; el log del sender no prueba finalización.
  2. Hipótesis iniciales, rankeadas:
    • H1 — refresh colgado deja refreshRunning=true y todos los siguientes se omiten.
    • H2 — refresh iniciado pero fallido a mitad de carga.
    • H3 — novedad llegada durante un refresh en curso → solicitud descartada.
    • H4 — filas duplicadas cean|inrosuc en dm_artic.
  3. Contraste con logs del servicio: patrones buscados >>> Inicio refresh, Refresh de cache finalizado|fallido, Cache activa actualizada, ERROR. Resultado: todos los refresh del 19–20/09 finalizaron OK (2–3 s, 84058 artículos), ningún fallido, ningún skip → H1, H2 y H3 descartadas. Único ERROR relevante: 18/09 16:53:51, arranque fallido por SQL Server no disponible (localhost:1433 connection refused), recuperado a las 16:54:39.
  4. Búsqueda del síntoma: precioTotal=1.05 → 19 respuestas el 19/09 y 6 el 20/09, todas para el EAN 2500176000005 sucursal 1.
  5. Línea de tiempo completa del EAN en los 5 archivos: dos id distintos para el mismo EAN (826360887 → 1.05; 826361083 → 8490.00) y correlación exacta de cada respuesta 1.05 con un Producto agregado a cache previo (camino on-miss) → H4 confirmada.
  6. Explicación de los miss: expireAfterWrite(4h) en CacheConfig; el primer 1.05 aparece a las 11:09, 4h09 después del preload de 07:00; tras el reinicio de 15:54 vuelve el 1.05 a las 20:59.
  7. Hallazgo colateral: no se recibió ningún POST /cache/refresh entre el 18/09 17:13:49 y el 20/09 21:40:22.
Limitaciones
No se consultó la base de datos directamente: los dos iid se infieren de las respuestas logueadas por el servicio, no de una lectura directa de dm_artic; ejecutar el SQL de duplicados (sección 6, F4) para confirmarlo. Tampoco se dispone del log del sender (novedades) del 19/09.

4. Causa raíz

La tabla dm_artic tiene dos filas para el mismo cean + inrosuc: el id 826360887 con precio 1.05 (iVersion 28771) y el id 826361083 con precio 8490.00. Dos caminos distintos del código resuelven esta ambigüedad de forma diferente, y solo uno de ellos es determinista.

01 / Origen 02 / Resolución de duplicados 03 / Cache Caffeine 04 / Consumo dm_artic 2 filas: mismo cean + inrosuc duplicado Preload startup / refresh diario ORDER BY inrosuc, iid On-miss getArticuloByEanAndSucursal sin ORDER BY Cache Caffeine expireAfterWrite 4h clave ean|suc WS getArticulo lectura de cache Autocompra self-checkout Dino SELECT ... ORDER BY inrosuc, iid carga completa SELECT ... sin ORDER BY consulta puntual put() por fila, último gana id 826361083 -> 8490.00 put() primera fila devuelta id 826360887 -> 1.05 getIfPresent() hit precio unitario respuesta al lector Legend primary data policy / PII async batch data store

Precarga: consulta ordenada, resultado determinista

On-miss: consulta sin orden, resultado arbitrario

El vencimiento decide qué camino gana

5. Evidencia (logs 19–20/09)

La línea de tiempo reconstruida a partir de logs/tsarticulos.log.2026-09-19.0 y logs/tsarticulos.log.2026-09-20.0 muestra cómo el reinicio manual del 19/09 solo desplazó el problema 4 horas, en lugar de resolverlo.

Preload valido Bug expuesto: responde 1.05 Reinicio 'arregla' temporalmente El efecto vence ~4h despues El ciclo se repite el 20/09 07:00:02 preload OK 84058 articulos, 2.7s 11:09:07 lookup (miss) put 1.05, id 826360887 sin ORDER BY: gana lo que devuelve SQL Server responde 1.05 se repite 15 veces hasta 15:26 15:26:11 entrada expira responde 1.05 (on-miss) 18/09 17:13 ultimo refresh silencio hasta 20/09 21:40 15:53 shutdown manual 15:54:19 STARTUP preload put id 826361083 orden por iid: gana el id mayor 16:05:46 responde 8490.00 20:59:32 expira (4h post-restart) responde 1.05 (on-miss) 21:05:43 segundo reinicio 20/09 07:00 preload 10:01 responde 8490.00 12:37:22 expira responde 1.05 (on-miss) 20/09 21:40 refresh se reanuda Novedades POST /cache/refresh Scheduler preload diario TsArticulos ArticuloCacheService Cache Caffeine 4h Autocompra self-checkout Operación reinicio manual Legend request return security async trace

Días previos: siempre el precio correcto

Factor agravante: silencio de novedades

Nota sobre el log del emisor
El log del lado que envía el refresh registra HTTP 202 STARTED, pero eso no prueba que el refresh haya terminado: el controller también devuelve 202 cuando el estado es SKIPPED_ALREADY_RUNNING (con success:false en el body). Un 202 en el log del emisor no es evidencia de que la cache se haya actualizado.

6. Fix propuesto Propuesto

La regla de desempate "gana el iid mayor" está pendiente de confirmación por el equipo. Es la que ya usa el camino de precarga; este plan solo la hace consistente en on-miss.

F1 — Ordenar la consulta de on-miss Mínimo, obligatorio

Agregar ORDER BY dm.iid DESC a la consulta nativa de ArticulosRepository.findByEanSuc para que on-miss resuelva duplicados con el mismo criterio que la precarga.

Antes
" WHERE dm.inrosuc = :nrosuc AND dm.cean = :ean "
Después
" WHERE dm.inrosuc = :nrosuc AND dm.cean = :ean ORDER BY dm.iid DESC "
Advertencia — no usar iVersion como criterio
No usar "gana el iVersion mayor": en este caso la fila incorrecta (1.05) tiene el iVersion más alto (28771, contra 28480 del resto del catálogo). iid e iVersion apuntan en direcciones opuestas para estas dos filas.

F2 — Test de regresión Test-first / TDD estricto

  • En ArticuloCacheServiceTest, con un repositorio que devuelve dos filas para el mismo ean|suc, verificar que el camino on-miss y el camino de precarga resuelven a la misma fila (el iid más alto).
  • Escribir el test primero, verlo fallar, y recién entonces aplicar F1.
  • El ordenamiento vive en SQL: si existe una costura de test a nivel de repositorio, agregar/ajustar también un test allí; si no existe, documentar la ausencia en vez de simularla.

F3 — Detector de duplicados en precarga Recomendado

Registrar un WARN en loadSucursalInCache cuando una clave de cache es sobreescrita por un iid distinto, para que los duplicados dejen de ser invisibles.

F4 — Duplicados en el origen de datos Fuera de este repo

El proceso de novedades está generando filas duplicadas en dm_artic; requiere revisión del equipo responsable de ese proceso. SQL de diagnóstico:

Diagnóstico
SELECT cean, inrosuc, COUNT(*) c FROM dm_artic WITH(NOLOCK) GROUP BY cean, inrosuc HAVING COUNT(*) > 1

F5 — Confiabilidad del refresh de novedades Operativo

  • Investigar por qué novedades dejó de enviar POST /cache/refresh entre el 18/09 17:13 y el 20/09 21:40.
  • El emisor debería validar el status del body de la respuesta, o consultar GET /cache/refresh/status, en lugar de confiar en el HTTP 202.

Tradeoffs considerados

7. Verificación

  1. Ejecutar el SQL de diagnóstico de duplicados (F4) para confirmar el alcance del problema en dm_artic.
  2. Ejecutar la suite de tests, incluyendo el test de regresión de F2 (debe fallar antes de F1 y pasar después).
  3. Después del deploy, buscar en el log el EAN 2500176000005 más de 4 horas después de la última precarga y confirmar que responde con id=826361083 / 8490.00.

8. Archivos involucrados

ArticulosRepository.java src/main/java/com/tipre/tsarticulos/repository/ArticulosRepository.java — contiene findByEanSuc, la consulta que necesita ORDER BY (F1).
ArticuloCacheService.java src/main/java/com/tipre/tsarticulos/service/cache/ArticuloCacheService.java — resolución on-miss, precarga y armado de la cache.
ArticulosCacheLoadRepositoryImpl.java src/main/java/com/tipre/tsarticulos/repository/ArticulosCacheLoadRepositoryImpl.java — consulta de precarga con ORDER BY dm.inrosuc, dm.iid.
CacheConfig.java src/main/java/com/tipre/tsarticulos/config/CacheConfig.java — configuración de Caffeine, expireAfterWrite(4, TimeUnit.HOURS).
ArticuloCacheAdminController.java src/main/java/com/tipre/tsarticulos/controller/ArticuloCacheAdminController.java — endpoints POST /cache/refresh y GET /cache/refresh/status.

Documento de incidente • Press T for theme and E for export