Saltar a contenido

Incidente: Colas de sincronización atascadas (Junio 2026)

Post-mortem técnico. Jobs de salida (WooCommerce, TiendaNaranja, Contimarket, Medusa, Algolia, UMarket) acumulándose por miles sin avanzar, con CPU y RAM ociosas. Documenta qué se encontró, cómo se diagnosticó, cómo se resolvió y qué queda por optimizar.

  • Fecha: Junio 2026
  • Severidad: Alta (sincronización de productos hacia canales detenida ~horas)
  • Commits de la solución: 9a6959a (scoped lookup), 3da7da2 (política de reintentos)

1. Resumen ejecutivo

Las colas de salida acumulaban 1500+ jobs cada una sin procesarse. Horizon estaba corriendo y con workers activos, pero los jobs tardaban 50–70s y morían por timeout (MaxAttemptsExceededException), reintentándose en bucle.

Hubo dos causas raíz independientes que se potenciaban:

  1. Lookup lentísimo de product_item_view — el filtro por id se aplicaba por fuera de una vista con GROUP BY, obligando a MariaDB a materializar y ordenar la vista entera en cada consulta (decenas de segundos por producto).
  2. Llamadas síncronas a Medusa dentro de cada job — la consulta de precio hacía hasta 2 requests HTTP secuenciales con timeout de 25s c/u, de modo que un solo job podía gastar ~50s y superar el timeout de 60s del worker.

Se resolvió encapsulando el lookup en ProductItemView::forProduct() (query scopeada, ~1ms) y endureciendo la política de reintentos de los jobs.

2. Síntomas observados

  • Colas woocommerce_products, tn_products, contimarket, medusa_products, algolia, umarket con 800–1500+ jobs en espera, sin drenar.
  • CPU del servidor ociosa, RAM sin saturar — los workers no estaban calculando, estaban bloqueados en I/O (red a Medusa + queries lentas).
  • Jobs visibles como delayed en Horizon (auto-reintentándose).
  • Productos recientemente actualizados sin reflejarse en los canales.

3. Cómo se diagnosticó

Metodología: descartar de afuera hacia adentro (infra → workers → código → DB).

3.1 ¿Horizon vivo? — sí

php artisan horizon:status        # "Horizon is running"
php artisan horizon:supervisors   # todos los supervisores running, con workers
systemctl status horizon          # active (running)

Esto descartó "Horizon caído / supervisor sin levantar".

3.2 ¿Por qué fallan los jobs? — timeout

php artisan tinker --execute="echo \DB::table('failed_jobs')->latest('failed_at')->value('exception');"
# => Illuminate\Queue\MaxAttemptsExceededException ... markJobAsFailedIfAlreadyExceedsMaxAttempts

MaxAttemptsExceededException por markJobAsFailedIfAlreadyExceedsMaxAttempts es la firma de un job que excede el timeout del worker (60s): el proceso se mata a mitad de ejecución y al reintentar ya pasó el máximo de intentos.

El log de Horizon confirmó duraciones de 50s, 1m8s, 1m10s → FAIL.

3.3 ¿Dónde se va el tiempo? — Medusa + vista

Rastreando SyntToTiendaNaranjaJob / SyncToMedusaJob se llegó a ProductPriceService::getProductPriceInfo(), usado por todos los canales de salida vía sus transformers/services. Esa función:

  • Hace hasta 2 requests HTTP secuenciales a Medusa (store + admin price list), con timeout=25s y connect_timeout=10s cada uno → peor caso ~50s.
  • Internamente consulta product_item_view, que resultó ser el otro cuello.

3.4 La query de la vista — EXPLAIN y cronometraje

Scripts de auditoría en audit/ confirmaron el problema de la vista:

php audit/audit_scoped.php 30   # cronometra la query scopeada + EXPLAIN

El patrón viejo (WHERE id=? por fuera de la vista con GROUP BY) producía Creating sort index sobre la vista entera. La query con vp.id=? inyectado adentro del cuerpo bajaba de decenas de segundos a ~1ms, con EXPLAIN arrancando por vp con key=PRIMARY rows=1.

4. Causas raíz

4.1 Lookup de product_item_view no scopeado (principal)

product_item_view tiene GROUP BY. Al hacer:

$productItem->productItemView()->where('channel', 'Compulandia')->first();

el WHERE id = ? se aplica después de que la vista se materializó completa. MariaDB no puede empujar ese filtro adentro del GROUP BY, así que construye y ordena la vista entera en cada lookup. Como cada job de salida hace ese lookup (precio, stock, payload), el costo se multiplicaba por miles de jobs.

4.2 Consulta síncrona a Medusa por producto (principal)

Cada job de salida llamaba a getProductPriceInfo(), que con id_medusa_product presente hace 2 requests HTTP a Medusa (timeout 25s c/u). Con Medusa lento/saturado, cada job gastaba 25–50s sólo en red → superaba el timeout=60s del worker → MaxAttemptsExceededException → reintento → cascada.

4.3 Causas secundarias (amplificadores)

  • Sin $timeout explícito en los jobs → heredaban los 60s del worker, que era menor al trabajo real.
  • Reintentos planos: $this->release(60) fijo en los catch, ignorando el $backoff declarado. Los workers re-procesaban los mismos fallos cada 60s, ocupando slots y sin dejar pasar a los jobs que sí podían completar.
  • Contimarket re-encolaba sin chequear attempts() → quemaba los 3 intentos siempre, incluso ante caídas persistentes.
  • Lock de precio inefectivo: product_price_lock:{id} con TTL de 10s envolvía un trabajo de hasta 50s → expiraba a mitad y no deduplicaba nada.

5. Soluciones aplicadas

5.1 ProductItemView::forProduct() — lookup scopeado (9a6959a)

Nuevo método estático en app/Models/ProductItemView.php que replica exactamente la definición de la vista pero con vp.id = ? inyectado en el WHERE (antes del GROUP BY). El optimizador arranca por la PK de product_items y resuelve en ~1ms. Resultado idéntico a la vista.

// Antes:
$view = $productItem->productItemView()->where('channel', 'Compulandia')->first();
// Después:
$view = ProductItemView::forProduct($productItem->id, 'Compulandia');

Call sites migrados: Contimarket, Medusa (inventory), ProductPriceService (local + fallback), TiendaNaranja, UMarket, WooCommerce.

⚠️ El SQL del método debe mantenerse sincronizado con la definición de la vista (SHOW CREATE VIEW product_item_view). Si la vista cambia, actualizar scopedSelectSql(). La auditoría de equivalencia (§6.2) detecta divergencias.

5.2 Política de reintentos de jobs de salida (3da7da2)

En Medusa, Contimarket, WooCommerce, UMarket y TiendaNaranja:

  • $timeout = 120 explícito (antes heredaban 60s).
  • $backoff exponencial [60, 300, 900] (1/5/15 min) en vez de plano.
  • Nuevo trait RetriesWithBackoff: retryDelay() respeta el header Retry-After (429/503) y la escala de backoff.
  • Los release(60) fijos → release($this->retryDelay(...)).
  • Contimarket: agregado el guard attempts() < tries que faltaba.
  • config/queue.php: retry_after 90 → 150 en las 5 conexiones de salida. Obligatorio: con timeout=120 > retry_after=90 la cola re-despachaba el job mientras seguía corriendo → doble ejecución. Ahora retry_after > timeout.

Tras desplegar: php artisan config:clear && php artisan horizon:terminate (sin el config:clear, retry_after queda cacheado en 90).

6. Cómo auditar / verificar

6.1 Performance de la query

php audit/audit_scoped.php 30
Esperado: p50 en milisegundos; EXPLAIN con vp ... key=PRIMARY rows=1; sin Creating sort index.

6.2 Correctness (equivalencia con la vista)

php audit/audit_scoped_equiv.php 50
Compara forProduct() contra la vista real fila por fila. Esperado: Presencia ≠ = 0 y Valores ≠ = 0. Cualquier discrepancia = el SQL inlined divergió de la vista.

6.3 Salud de las colas (producción)

php artisan horizon:supervisors                 # workers activos por cola
# duración de jobs en el panel /horizon -> deben bajar de ~minutos a segundos
php artisan tinker --execute="echo \DB::table('failed_jobs')->where('failed_at','>',now()->subHour())->count();"
Esperado: las colas drenan, las duraciones caen, failed_jobs deja de crecer.

7. Cómo seguir optimizando

Pendientes ordenados por impacto/esfuerzo:

  1. Bajar el timeout HTTP de Medusa (MEDUSA_HTTP_TIMEOUT, hoy 25s → sugerido 5–8s; MEDUSA_HTTP_CONNECT_TIMEOUT 10 → 3). Hace que un Medusa lento corte rápido y el job use el fallback local dentro del timeout. (Mitiga; no elimina la dependencia.)
  2. No llamar a Medusa de forma síncrona por producto en cada job de salida. Pre-calcular/pre-cachear precios de Medusa en un job batch previo, o leer el precio especial desde datos locales sincronizados. Es el fix de fondo.
  3. Subir el TTL del caché de precios (ProductPriceService::CACHE_TTL, hoy 60s → varios minutos). En una corrida de miles de productos casi nunca pega.
  4. Arreglar el lock de precio: alinear LOCK_TIMEOUT_SECONDS con el trabajo real (o reducir el trabajo) para que deduplique de verdad; hoy es inefectivo.
  5. Investigar por qué Medusa responde lento (carga del server, admin price list API). Es el gatillo de fondo de toda la cascada.
  6. Materializar product_item_view como tabla indexada (o reemplazar la vista) si más lugares necesitan el dato. forProduct() resuelve el acceso de a uno, pero la vista entera sigue siendo cara para listados.
  7. Alinear uniqueFor de los jobs con su ciclo real de reintentos para que el dedup de ShouldBeUnique* sea efectivo.

8. Lecciones / anti-patrones

  • No filtrar por fuera de una vista con GROUP BY — empujar el filtro adentro del cuerpo o no usar vista para acceso por PK.
  • Todo job que hace HTTP externo debe declarar $timeout, y retry_after de la conexión debe ser mayor que ese $timeout.
  • MaxAttemptsExceededException casi siempre = job que excede el timeout del worker, no un bug de lógica. Mirar duraciones antes que el stack trace.
  • CPU ociosa + colas llenas = workers bloqueados en I/O (red/DB lenta), no falta de capacidad. No se arregla agregando workers.
  • Cuidado al mergear ramas de deploy: en este incidente casi se despliega la rama de retry sin el fix de la vista por un merge de la rama equivocada. Verificar con git merge-base --is-ancestor <commit> HEAD antes de desplegar.