WMT HOS Log Export Failure
Incident report · orion-queues · fs-prod / wmt · PSELD-4743

WMT nightly HOS log export stopped completing on Sep 24

Window
Sep 24 02:30 PT → mitigated Oct 6
UTC
2026-09-24 09:30 → 2026-10-06 20:26
Severity
High
Status
Mitigated · monitoring

Summary

The problem, plainly

Every night Orion sends Walmart a feed of the compiled HOS logs that changed that day. Walmart's safety teams build weekly reports from it. From September 24 to October 5 that nightly job did not finish on its own, so Walmart received little or no HOS log data for most of two weeks, and some records were sent more than once.

The fix, plainly

Change ExportHosLogs so each run covers at most one day, reads rows in updated_at order on an (updated_at, id) index, and saves progress as it goes. Keep the hos_bulk* workers from scaling to zero while an export is still running (done Oct 6, pltsci-orion-deploy PR 825). Alert when the export hasn't completed in 26 hours. Recommendations

Status, plainly · Oct 7

The scheduled export for Oct 5 (run Oct 6 02:30 PT) finished on its own for the first time since Sep 23: 22K rows in 20 minutes. Walmart still reported missing data, so SRE resent every log day from Sep 28 through Oct 6 with a wider "changed since" date of Sep 21. SRE also set the wmt hos_bulk* workers to a minimum of one replica, live and in PR 825, so a running export is no longer scaled away. The Oct 7 scheduled run also finished on its own: 23,931 messages in 23 minutes, and the workers scaled 1 → 3 → 1 around the midnight compile without dropping to zero. The export code is unchanged, so one missed night would still start the same pile-up.

Working theory, supported by Datadog logs, Kubernetes events, the deploy chart and a replica EXPLAIN; not yet confirmed by the HOS team. The export had been slowing at steady volume (40 → 54 min). On Sep 24 it passed about 58 minutes and its worker was killed by a KEDA scale-to-zero, 60 minutes after dispatch, matching the chart's cooldownPeriod: 3600. The job saves its last-run marker only at the end and has no upper bound on its window, so each later run covered more days (up to 151,178 rows). Those runs either hit MySQL's 65-second statement limit, because the query reads the whole 3.4M-row table through an index that narrows nothing, or were killed at the same 60-minute mark.

Oct 7 run completed · next check Oct 8 02:30 PT

Two scheduled runs have now completed on their own (Oct 6: 20 min, Oct 7: 23 min), and the workers have held at one or more replicas for about 23 hours, including one midnight compile scale-up and scale-down. Both runs were one-day windows well under 60 minutes, so the scale-down fix still hasn't been tested by the condition it targets.

How a run gets lost

One export job, one worker, and an autoscaler that can't see it
Scheduler daily 02:30 PT Redis queue hos_bulk · pending KEDA scaler cooldown 3600 s · min 0→1 Oct 6 Worker pod ExportHosLogs one job, 40–60+ min MySQL hos_logs 65 s statement limit Walmart consumer job.hos_log S3 last-run marker window start for next run dispatch reserve pending → 0 reads pending length scale 1 → 0 at ~60 min SIGTERM, 30 s, SIGKILL count + pages publish written only on completion
Once the worker picks up the job, the queue KEDA watches is empty, so KEDA counts down its cooldown and scales the worker to zero. The chart sets cooldownPeriod: 3600 for every wmt hos_bulk* worker, which matches the scale-down seen about 60 minutes after dispatch every day from Sep 21 to Oct 1. Any run still going at that point is killed without an error log, and because the marker is written only at the end, the next run starts from the same place with one more day of data. Since Oct 6 the workers keep a minimum of one replica, so this kill should no longer happen. The marker behavior is unchanged.

Every scheduled run, Sep 21 – Oct 7

Read it like a duty-status grid: one row per night, minutes after the 02:30 PT start across the top.

How long each scheduled run lasted, and how it ended
Completed Killed at worker scale-down Stopped on MySQL 3024 timeout ~60 min: worker scaled to zero
Runs on Sep 21–23 finished just inside the ceiling. From Sep 24 to Oct 5 no scheduled run completed. Oct 6 and Oct 7, with the marker current again, completed in 20 and 23 minutes. Sep 25 shows the 03:48 PT retry attempt; earlier attempts that night failed on a 3024 error and a 2-hour job timeout. The full run log is in the table below.

The window that kept growing

Rows to export at the start of each scheduled run
Completed Killed at scale-down MySQL 3024 timeout
Normal daily volume is 34–39K rows. After one failed night the job must cover every day since the last success, and a bigger window fails sooner. The Sep 28–29 manual backfills moved the marker to Sep 29 00:00, then the same growth started again. After the Oct 5 backfills the Oct 6 and Oct 7 windows were back to 22–23K rows.

Why the query hits the 65-second limit

EXPLAIN ANALYZE on a wmt read replica, Oct 5, using the Oct 5 failure's window (marker Sep 29 00:00, dates through Oct 4). Not yet run on the primary.

The export's count query: default plan vs forcing the updated_at index
MySQL picks hos_logs_deployment_id_index, whose cardinality is 1 (each tenant database holds one deployment), so it reads the whole table and throws 95% away. Forcing updated_at returns the same count (160,661 vs 160,666). MySQL rates that plan at about twice the cost, so it never picks it on its own; table statistics also look stale (2.78M estimated rows vs 3.4M read). Each page then discards every row before its OFFSET: one 25-row page at offset 1225, where the Oct 4 run died, took 8.3 s.

Root cause

Theories supported by the evidence. Not yet confirmed by the HOS team or against the live ScaledObjects. The chart configuration has been read.

Primary

KEDA scales the export worker to zero while the job is still running

The export runs as one long queue job on a hos_bulk* worker. Once reserved, the pending list is empty, and the worker is scaled to zero at the end of the chart's 3600-second cooldown. The chart gives hos_bulk1–4 a floor of one replica, yet in prod they scaled to zero until the Oct 6 live edit, while hos1–9 from the same file did not; the live objects were likely changed outside Helm (not yet checked). The pod gets 30 s and is SIGKILLed. Before Sep 24 every run finished first; on Sep 24 the run passed 58 minutes and lost 4,407 rows. The same kill happened Sep 25, Sep 30 and Oct 1.

Secondary

Unbounded window, marker written only on completion

Each run selects every row with updated_at >= lastrun and writes lastrun only when it finishes. One failure makes the next run larger (37K → 151K rows), and without an outside reset the job does not recover.

Secondary

The query uses an index that narrows nothing, and pages with OFFSET

The count reads 3.4M rows through a cardinality-1 index (387 s vs a 65 s limit). Pages walk an index without updated_at and re-produce every row before the offset. This predates the incident: it set the ~60-minute run time that met the ceiling, and it makes every widened window fail outright.

Contributing

No alert on missing success

The existing monitor watches error logs on the hos_bulk* workers. The Sep 24 kill logged no error, and nothing checks marker age or a missing completion log. Escalation came four days after the first failure. Compile failures on hos0–hos9 aren't covered either.

Contributing

The export shares workers, data and the database with HOS compiles

  • Workers. The midnight bulk compile runs on the same hos_bulk queues at 04:00 and 05:00 UTC. That scale-up is the likely reason killed exports reappeared at 04:1x UTC: the woken worker picks up the expired export job.
  • Data. Every compile updates updated_at, so that driver-day is exported again. A failed compile (1–3 a day) leaves nothing new to export for that driver-day.
  • Database. Compile throughput drops and p95 rises to about 40 s in the 09:00 UTC hour when the export starts. Not confirmed; needs RDS metrics.
Contributing

Backfills sliced by log date

Per-date manual runs sent about 18K rows a day against 34–39K for a normal scheduled run. The original theory was that per-date slices miss edits to older logs. Evidence now weighs against most of that gap being missed data. Widening the "changed since" date to Sep 21 on Oct 6 left per-day counts at about 18K. Theory: the midnight bulk compile recompiles yesterday and today for every driver, so each scheduled run carries about two log days (2 × ~18K), each sent on two nights. Still possibly missed: outage-period edits to logs dated more than a day earlier, before Sep 28.

Customer impact

Walmart: no scheduled export data from Sep 24 through Oct 5; scheduled exports resumed Oct 6 and completed again Oct 7. Partial data arrived from the killed runs (Sep 24, 25, 30, Oct 1) and from manual backfills (Sep 28–29, Oct 5). A support case was opened Oct 5: the feed is needed for the safety teams' weekly reports. On Oct 6 Walmart reported data still missing, and log days Sep 28–Oct 6 were resent.

Duplicates: retries, overlapping backfills and the Oct 6 resend re-published rows already sent. Log day Sep 29 was resent three times on Oct 6 alone. The consumer will see some records more than once.

Possible gaps: outage-period edits to logs dated before Sep 28 have not been resent with a widened date, so some may not have been delivered. Not confirmed; what Walmart found missing on Oct 6 hasn't been compared against the resend. Driver-days whose compile failed (1–3 a day) have no up-to-date row to export.

Other tenants: not affected. See run times by tenant.

Timeline

All times PT.

TimeEvent
Sep 21–23 02:30Scheduled exports complete in 40, 51 and 54 min (34–39K rows). Sep 23 is the last scheduled completion before the outage.
Sep 24 02:30Scheduled export starts: 37,382 rows on queue-hos-bulk3.
Sep 24 03:28Worker pod terminated mid-job (SIGTERM 03:28:12, SIGKILL 03:28:42) with 4,407 rows left. No marker written.
Sep 24 21:19 – Sep 25 03:48Three retries of ~63K rows, the first when the midnight bulk compile wakes the worker: 3024 error, 2-hour job timeout, then killed at scale-down.
Sep 25 21:16 – Sep 29 02:39Runs of 87K → 151K rows each stop on 3024 within minutes.
Sep 27 21:44HOS Nightly Log Compile Error alert thread for wmt in #alerts-compliance.
Sep 28 12:22Compliance engineering escalates; per-day rerun plan posted.
Sep 28 12:34 – Sep 29 14:14Seven manual per-day reruns complete. Marker set to Sep 29 00:00.
Sep 30, Oct 1 02:3050K and 75K-row runs killed at the 60-minute scale-down.
Oct 2–5 02:30Runs of 97K → 138K rows fail on 3024. On Oct 5 the opening count(*) times out.
Oct 5 08:18–08:57Walmart account team email and support case: little to no HOS log consumer data.
Oct 5 09:00 – 14:10SRE one-day backfills complete (about 18K rows each). A 72K-row run starts at 09:30 and stops on 3024; it is retried automatically at 11:31.
Oct 5 21:17Another 72K-row retry starts during the midnight bulk compile, logs no progress, and does not reappear.
Oct 6 02:30 – 02:50Scheduled export completes: 22,270 messages in 20 min. First scheduled completion since Sep 23.
Oct 6 morningWalmart reports data still missing after the scheduled run.
Oct 6 05:12 – 13:26SRE resends log days Sep 28 – Oct 6 with "changed since" Sep 21: 10 runs, 11–27 min each, all complete.
Oct 6 ~10:53Live edit sets wmt hos_bulk* minimum replicas to 1; no scale-to-zero since. Same change merged in pltsci-orion-deploy PR 825.
Oct 6 16:00 – 18:4214 CompileHosLogs timeouts on worker-hos3, tracked in the separate compile-timeouts incident.
Oct 7 02:30 – 02:53Scheduled export completes: 23,931 messages in 23 min. Second consecutive completion; workers scale 1 → 3 → 1 around the midnight compile, not to zero.

Run log

Scheduled runs, UTC dates. Start is 09:30 UTC (02:30 PT) unless noted.

DateWorkerRows at startRan forOutcome

Recommendations

P0 within hours

  1. Done Oct 6Stop the unbounded 72K-row job and backfill in one-day slices. The 72K job hasn't reappeared since Oct 6 04:17 UTC, and log days Sep 28 – Oct 6 were resent. One-day runs complete in 7–27 min.
  2. Done Oct 6Protect the Oct 6 09:30 UTC scheduled run. It completed in 20 minutes.
  3. Done Oct 6Pin wmt hos_bulk* workers to a minimum of one replica until the code fix ships. Applied live and codified in pltsci-orion-deploy PR 825. Keep it until recommendation 6 or 13 ships.
  4. Tell Walmart that duplicate records were sent and that the resend of log days Sep 28 – Oct 6 finished Oct 6 13:26 PT. Ask for specific driver-days they still see missing, to check against the resend.
  5. Try ANALYZE TABLE hos_logs on a replica. If MySQL then picks updated_at for the count, schedule it on the primary. Run plain EXPLAIN on the primary.

P1 within days

  1. Code, ExportHosLogs (HOS team):
    • Cap each run at lastrun → min(lastrun + 24h, now) and loop until caught up.
    • Keyset pagination in (updated_at, id) order instead of chunk(25) OFFSET paging. Don't just add FORCE INDEX (updated_at) to the current query: it pages in user_id, date order, so every page would sort the whole window.
    • Write the last (updated_at, id) sent as the marker every few thousand rows, so a killed run resumes.
    • Remove the opening count(*). Link to PSELD-4491.
  2. Index: add hos_logs (updated_at, id). A leading deployment_id adds nothing at cardinality 1.
  3. Alerting: marker older than 26 h per tenant; no total hos log messages queued log in 24 h; warn when run time exceeds 45 min; alert on CompileHosLogs failures on hos0–hos9.
  4. Read the live ScaledObjects and find who set hos_bulk1–4 to zero against the chart. Lower priority now that PR 825 sets the minimum, but the same cause could undo it.
  5. Check database contention during the export window: wmt RDS CPU, read IOPS, read latency and lock waits for 09:00–11:00 UTC.
  6. HOS team: review the CompileHosLogs errors: 240 s timeouts on recompiles of old dates, a missing duty_status_duration_seconds key, and Predis protocol errors.
  7. Explain the Sep 30 19:00 UTC jump in traced compile volume: sampling change or more recompiles.

P2 within weeks

  1. Run long exports outside KEDA-scaled queue workers (K8s Job/CronJob, or a scaler that counts reserved jobs) with a termination grace period the job can finish in.
  2. Check other tenants against the same ceiling before they reach it.
  3. Backfill runbook: slice by updated_at, single owner, marker handling, duplicate notification. Run manual exports outside 04:00–06:00 UTC and 09:00–11:00 UTC.
  4. Give the export its own queue instead of sharing hos_bulk with the midnight bulk compile.
Longest completed export per prod tenant, 14 days to Oct 5
SNI is next closest to the ceiling at 41 minutes. Crete had the same failure in August; a database upgrade cleared it and the code fix (PSELD-4491) is still open.

Known facts

Direct observations with their source, numbered as in the repository report. Theories live in Root cause.

  1. Scheduled runs on Sep 21, 22 and 23 completed with 34,107, 39,084 and 39,343 messages in 2,389 s, 3,038 s and 3,258 s (40, 51, 54 min).Datadog logs, "total hos log messages queued"
  2. The Sep 22 run logged three MySQL 3024 errors between 09:35 and 09:52 UTC and still completed.Datadog logs
  3. On Sep 21–23, queue-hos-bulk3 scaled 0→1 at 09:30:06–09:30:09 UTC and 1→0 at 10:30:07–10:30:12 UTC.Datadog Kubernetes events
  4. The Sep 24 run started 09:30:13 UTC with 37,382 rows on pod queue-hos-bulk3-cb4cc58fd-n2w6l. Its last progress log was 10:28:41 UTC ("4407 to go"), with no completion or error log after.Datadog logs
  5. On Sep 24, that pod's logs and logrotate containers exited 143 at 10:28:12 UTC; php-cli exited 137 at 10:28:42 UTC.Datadog containerd events
  6. Later runs started with 63,403 (Sep 25 04:19 UTC), 87,276 (Sep 26 04:16), 108,410 (Sep 27 04:17), 129,607 (Sep 28 09:30) and 151,178 (Sep 29 09:30) rows.Datadog logs, "WMT - exporting"
  7. On Sep 25 the run started 09:48 UTC logged progress until 10:48:46; queue-hos-bulk3 scaled 1→0 at 10:48:17.Datadog logs; Kubernetes events
  8. The Sep 26 scheduled run logged its last progress at 09:32:25 UTC and no error. The Sep 27, 28 and 29 runs each logged a 3024 error 8–9 minutes in and no progress after.Datadog logs
  9. On Sep 28 (19:34–21:17 UTC) five manual runs of about 18,045 rows completed in 728–928 s; on Sep 29 (20:41–21:14 UTC) two more completed (18,039 and 18,041 rows).Datadog logs; #alerts-compliance
  10. After the Sep 29 manual runs, the S3 marker showed 2026-09-29 00:00:00.#alerts-compliance, Sep 29 14:22 PT
  11. Scheduled runs after the reset started with 50,094 (Sep 30), 75,280 (Oct 1), 97,354 (Oct 2), 118,575 (Oct 3) and 138,468 (Oct 4) rows.Datadog logs
  12. On Sep 30 and Oct 1, runs on queue-hos-bulk2 logged progress until 10:30:35 and 10:30:36 UTC; the worker scaled 1→0 at 10:30:05 and 10:30:06.Datadog logs; Kubernetes events
  13. On Oct 2, 3 and 4, runs logged a 3024 error 7–8 minutes in and no progress after 09:32–09:33 UTC.Datadog logs
  14. On Oct 5 the scheduled run logged a 3024 error at 09:35:04 UTC and no "exporting" line.Datadog logs
  15. On Oct 5, three manual runs of 18,027–18,037 rows completed between 16:00 and 16:33 UTC. A 72,124-row run started 16:30:53 UTC on queue-hos-bulk0.Datadog logs
  16. Longest completed export run per prod tenant, 14 days to Oct 5: wmt 54.3, sni 41.2, crete 20.6, werner 15.7 min; all others ≤ 10.9 min.Datadog logs grouped by env
  17. Crete had the same export failure in August 2026, reported resolved by a database upgrade; PSELD-4491 (code fix) is still open.#alerts-compliance, Sep 28 12:22 PT
  18. On Oct 5 Walmart opened a support case reporting little to no HOS log consumer data "for the last few days".#amqp-events-worker, Oct 5 08:57 PT
  19. In pltsci-orion-deploy main (2beccbc, Oct 2), wmt's hos_bulk0–4 have cooldownPeriod: 3600 and QUEUE_RETRY_AFTER: 7260. helm template renders minReplicaCount 0 for hos-bulk0 and 1 for hos-bulk1–4.charts/orion-workers, helm template, Oct 5
  20. The MySQL statement execution limit hit by the export query is 65 s.EXPLAIN walkthrough, wmt read replica, Oct 5
  21. With the Oct 5 failure's values, the count used hos_logs_deployment_id_index, read 3.4M rows, kept 166,276, and took 387.2 s.EXPLAIN ANALYZE, Query 2
  22. The same count with FORCE INDEX (updated_at) read 184,803 rows, returned 160,661 (vs 160,666), and took 2.1 s warm. MySQL's cost estimate was 614,649 vs 336,586 for the default plan.EXPLAIN ANALYZE, Query 4
  23. SHOW INDEX FROM hos_logs: cardinality 1 for hos_logs_deployment_id_index, 2,039,683 for updated_at, 2,775,331 for PRIMARY.SHOW INDEX, wmt read replica
  24. A page at LIMIT 25 OFFSET 1225 used hos_logs_deployment_id_user_id_date_idx, read 27,229 entries, produced 1,250 rows before discarding 1,225, had no Sort step, and took 8.3 s warm.EXPLAIN ANALYZE, Query 3
  25. The Oct 4 scheduled run logged 49 progress batches of 25 rows (1,225) before its 3024 error.Datadog logs
  26. The EXPLAIN plans have not been run on the wmt primary.EXPLAIN walkthrough
  27. Over the 14 days to Oct 5, wmt's queue-hos-bulk1–4 logged 14–23 "from 1 to 0" scale-downs each; queue-hos1–hos9, which render the same minimum of 1, logged none. In sni, werner, kllm and ffe, queue-hos-bulk2 scaled 1→0 only during rollouts.Datadog Kubernetes events
  28. The 72,124-row run of Oct 5 logged 3024 errors 16:47–17:04 UTC and no completion. A 72,108-row run started on queue-hos-bulk0 at 18:31:59 UTC. Three one-day runs of 18,026–18,033 rows completed 17:41–18:46 UTC.Datadog logs
  29. CompileHosLogs runs on the hos0–hos9 queues: 1,766–2,082 spans per queue Sep 28 – Oct 5, p95 7.6–16.6 s. Successful compiles emit no log line.Datadog APM
  30. In the 7 days to Oct 5, CompileHosLogs logged 1–3 FAIL lines a day in wmt (16 total): timeouts, Killed, an undefined duty_status_duration_seconds key, and Predis protocol errors on compile dates as old as Jul 31.Datadog logs
  31. Oct 1–5, CompileHosLogs span counts in the 09:00 UTC hour (30–96) were lower than surrounding hours (91–365), with p95 up to 40.7 s against 4–17 s in most other hours.Datadog APM, 1-hour buckets
  32. Hourly CompileHosLogs span counts were 3–38 from Sep 29 05:00 to Sep 30 18:00 UTC and 30–365 after; wmt ran release.20260830.1 throughout.Datadog APM; change tracking
  33. The "HOS Nightly Log Compile Error - wmt - Export Failed" monitor queries hos_bulk0–9 logs with status above warn.Monitor text, #alerts-compliance
  34. The scheduler runs hos:export daily at 09:30 UTC and hos:hourly hourly; the latter recompiles yesterday and today for each driver in time zones at local midnight, on the same hos_bulk queue as the export.pltsci-orion develop f936dda77b
  35. HOS_LEGACY_LOGS_STATUS is "on" for wmt, which enables compile-on-change, the midnight bulk compile and the export.orion-config chart; pltsci-orion config
  36. Sep 30 – Oct 6, wmt's queue-hos-bulk0–4 logged 14–15 scale-ups in the 04:00 UTC hour, 10 in the 05:00 UTC hour, and 1 a day at 09:00 UTC through Oct 4.Datadog Kubernetes events, 1-hour buckets
  37. The Oct 6 scheduled run started 09:30:06 UTC with 22,137 rows on queue-hos-bulk2 and completed at 09:50:08 UTC: 22,270 messages in 1,204 s, no 3024 error. Its completion line is prefixed with log day 2026-10-05. First scheduled completion since Sep 23.Datadog logs; prefix meaning confirmed by SRE
  38. A 72,072-row run started on queue-hos-bulk0 at 04:17:40 UTC on Oct 6. It logged no progress, error or completion, and no further 72K-row run appeared through 20:30 UTC.Datadog logs
  39. Between Oct 5 21:01 and Oct 6 20:26 UTC, manual runs of 17,980–20,344 rows each completed in 554–1,615 s, for log days Oct 5, Sep 28, Sep 29 (×3), Sep 30, Oct 1–4 and Oct 6, with no 3024 errors. The Oct 6 runs used a "changed since" date of Sep 21 after Walmart reported missing data; log days Sep 28 – Oct 4 had 17,980–18,034 rows, against 18,026–18,045 for earlier per-day runs.Datadog logs; SRE, Oct 6
  40. wmt's queue-hos-bulk0–4 last scaled 1→0 between 08:39 and 09:02 UTC on Oct 6 (bulk1 again at 13:12). hos-bulk3 and 4 scaled 0→1 at 17:53 UTC with no KEDA activation, and none scaled to zero through 20:40 UTC. SRE set the minimum to 1 by live edit and merged the same change in PR 825.Datadog Kubernetes events; SRE; pltsci-orion-deploy PR 825
  41. The Oct 7 scheduled run started 09:30:05 UTC with 23,330 rows on queue-hos-bulk2 and completed at 09:53:25 UTC: 23,931 messages in 1,402 s, no 3024 error. No other export start or completion was logged in wmt between Oct 6 20:30 and Oct 7 ~17:10 UTC.Datadog logs
  42. Between Oct 6 20:30 and Oct 7 ~17:10 UTC, wmt's queue-hos-bulk0–4 logged no scale event ending at 0 replicas. On Oct 7 they scaled 1→2→3 at 04:00–04:02 UTC, back to 1 by 04:39–04:42 UTC, and up again from 05:00 UTC.Datadog Kubernetes events
  43. Between Oct 6 20:30 and Oct 7 ~17:10 UTC, wmt logged 16 CompileHosLogs timeouts: 14 on worker-hos3 (Oct 6 23:00 – Oct 7 01:42 UTC), 1 on worker-hos7 and 1 on worker-hos6, plus 28 Killed lines on worker-hos3.Datadog logs