Skip to content

fix(3scale_batcher): read batched report keys while holding the lock - #1611

Open
arshad-aziz wants to merge 1 commit into
3scale:masterfrom
arshad-aziz:fix/batcher-orphaned-lock
Open

arshad-aziz wants to merge 1 commit into
3scale:masterfrom
arshad-aziz:fix/batcher-orphaned-lock

Conversation

@arshad-aziz

Copy link
Copy Markdown

Fixes #1610.

Problem

ReportsBatcher:get_all() lists the shared dict keys before acquiring the lock and reads them while holding it:

local cached_report_keys = self.storage:get_keys()   -- outside the lock
...
local elapsed, lock_err = lock:lock(service_id)
...
for _, key in ipairs(cached_report_keys) do
  local value = self.storage:get(key)
  local report, err = keys_helper.report_from_key_batched_report(key, value)

  if not err then
    if value > 0 and report and report.service_id == service_id then

The policy starts one reporting TimerTask per worker (as documented in 3scale_batcher.lua), and they all flush the same service_id through the same lock key. So two workers can both list [k1…kN], the first takes the lock and deletes them all, and the second then reads k1 and gets nil. report_from_key_batched_report(key, nil) returns err == nil, so the if not err guard does not help, and value > 0 raises.

Two separate failures follow:

  1. The lock is orphaned. lock:unlock() is never reached, so the lock sits in batched_reports_locks until resty.lock's default exptime of 30s. Meanwhile every request for that service waits the full 10s lock_timeout in add() during the access phase, logs failed to acquire the lock: timeout, and then discards its usage report. The 10s figure is a hardcoded local, so operators cannot tune around it.
  2. Reporting stops on that worker. TimerTask.run_periodic calls the task with no pcall and only reaches schedule_next() if it returns normally. ensure_timer_task_created will not recreate it either, since it guards on if not self.timer_task and the object is still non-nil. The task is gone until a configuration reload or a restart, and batched_reports stops draining — which is the mechanism behind THREESCALE-9537, closed previously by making the dict size configurable rather than by addressing why it fills.

Observed in production on 3.16 across several products on one gateway, with 4 workers:

[error] 28#28: lua entry thread aborted: runtime error:
  .../3scale_batcher/reports_batcher.lua:94: attempt to compare number with nil
  .../3scale_batcher/reports_batcher.lua: in function 'get_all'
  /opt/app-root/src/src/resty/concurrent/timer_task.lua:71: in function 'run_periodic'
  context: ngx.timer

followed by bursts of reports_batcher.lua:38: add(): failed to acquire the lock: timeout. Client-visible latency exceeded 10s while upstream_response_time_seconds stayed flat and only total_response_time_seconds spiked, consistent with the stall being entirely in the access phase.

(LuaJIT compiles value > 0 as 0 < value, hence "compare number with nil" rather than the reverse.)

Change

  • Read the key list while holding the lock, so a concurrent flush cannot delete entries between enumeration and read. Deletes already only happen under the lock, so this closes the race at its source.
  • Skip entries whose value is gone rather than raising. Defence in depth — an error on this path is expensive out of proportion to the problem, since it costs the lock and the timer.
  • Run TimerTask callbacks inside a pcall, logging failures, so that no future error in a task can silently stop it from being rescheduled. TimerTask has exactly one consumer today (this policy), so the blast radius is contained.

Tests

Added regression coverage that fails on master and passes here:

  • get_all reads the keys only after acquiring the lock (asserts call ordering).
  • get_all skips a key that has gone missing and still returns the remaining reports.
  • get_all releases the lock when a key is missing.
  • A failing timer task does not propagate its error.
  • A failing timer task still schedules the next run.

Verified against the unfixed source, where they reproduce the production error exactly:

2 failures / 3 errors
  reports_batcher.lua:94: attempt to compare number with nil

Full suite on this branch, run in quay.io/3scale/apicast-ci:openresty-1.27.1-1 with a redis sidecar:

1370 successes / 0 failures / 0 errors / 5 pending

Deliberately out of scope

self.storage:get_keys() takes no argument, so it returns only the first 1024 keys, and it enumerates across all services while get_all() filters to one — so on a gateway with many products, a busy service can crowd out another's keys indefinitely. That is a real bug, but passing 0 changes how long the lock is held on a large dict, and get_keys is documented as able to block workers. It deserves its own PR with its own performance discussion rather than riding along with a crash fix. Noted as follow-up in #1610.

🤖 Generated with Claude Code

ReportsBatcher:get_all() listed the shared dict keys before acquiring the
lock and then read them while holding it. There is one reporting timer per
worker and they all flush the same service, so a second worker could list a
key, lose the race for the lock, and find the key already deleted by the
time it ran. storage:get() then returned nil and the comparison below raised
"attempt to compare number with nil".

The raised error left the lock to expire on its own, which made every
request for that service wait the full 10s lock timeout in the access phase
before dropping its report. It also aborted the timer thread before
TimerTask could schedule the next run, so reporting stopped on that worker
until the configuration was reloaded.

Read the keys under the lock so deletes cannot interleave, skip entries that
are gone anyway, and run timer tasks inside a pcall so that a failing run
cannot stop the task from being scheduled again.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@arshad-aziz
arshad-aziz requested a review from a team as a code owner October 22, 2026 18:21
@arshad-aziz

Copy link
Copy Markdown
Author

The red checks here are not test failures — the CircleCI jobs never ran.

All four are cancelled before any step executes, which is why they report 0s duration. The CircleCI API gives the reason:

messages: [{'reason': 'block-unregistered-user', 'type': 'error'}]
lifecycle: finished | num steps: 1
 - "Error: Task information unavailable" | status: canceled

This is the gate on builds from contributors not registered on the project, so it affects any outside PR rather than this one in particular — #1609 is blocked identically, while master and 3scale-2.17-stable are green. A maintainer authorising the build should be all that's needed.

In the meantime I ran the suites locally in the project's own CI image (quay.io/3scale/apicast-ci:openresty-1.27.1-1):

Suite Result
busted, full 1370 passed / 0 failed / 0 errors / 5 pending
prove, t/apicast-policy-3scale-batcher.t + -blackbox.t 266 passed

The new unit tests were also checked against the unpatched source, where they fail with the error this PR fixes:

2 failures / 3 errors
  reports_batcher.lua:94: attempt to compare number with nil

One caveat so it isn't mistaken for a clean full-suite claim: t/apicast-http2.t fails 16/24 in my environment, but it fails identically on unmodified master, so it is a limitation of my setup rather than anything from this change. Everything else in prove passes when run serially.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3scale_batcher: unguarded nil in get_all() orphans the lock — 10s request stalls and permanently dead report timers

2 participants