membphis commented on issue #13888: URL: https://github.com/apache/apisix/issues/13888#issuecomment-6418131949
I reproduced a concrete checker-initialization race that can produce the worker-local/shared-state divergence described in this issue. The reproducer below uses the real healthcheck library and event transport. It identifies a possible trigger; it does not establish that the original Kubernetes incident had this same trigger. ### Trigger and observed failure 1. Worker A creates a checker and adds a healthy target. Both workers receive the initial event. 2. Worker B starts creating a checker with the same name. `healthcheck.new()` reads the target's healthy state from shared memory into B's local snapshot. 3. Before B registers its checker callback, initialization calls `resty.events.compat.poll()`, which yields for its existing 2 ms interval. 4. During that interval, A calls the real `checker:set_target_status(..., false)` API. The library writes unhealthy to shared memory and publishes the event normally. 5. B receives the unhealthy event while its checker is not subscribed yet. The event cannot update that checker's snapshot. 6. B completes registration and returns from `healthcheck.new()`. After a later barrier event has been processed by both workers, plus a further 10 ms observation delay, B can still report **local healthy / shared unhealthy / `status_ver = 0`**. The test observes event arrival independently of the checker subscription. It does not disconnect the event transport, suppress publication, manually overwrite shared health state, or extend the original 2 ms poll delay. It does deliberately coordinate the state transition with initialization. Active probes are disabled for this component test, and `set_target_status()` substitutes for a completed probe's state change. This is distinct from the intended lazy creation of a checker: at the observation point, creation and subscription have already completed. It is also distinct from the all-unhealthy fallback; that behavior should remain a separate case. The relevant ordering is visible in [healthcheck.new()](https://github.com/api7/lua-resty-healthcheck/blob/v3.2.3/lib/resty/healthcheck.lua#L1691): initial state is read before `poll()`, and callback registration happens in [`start()`](https://github.com/api7/lua-resty-healthcheck/blob/v3.2.3/lib/resty/healthcheck.lua#L1420) afterward. ### Results and limits - Initial batch: **83/100** rounds produced the divergence. - Five more batches using the unchanged probe: **89/100, 87/100, 85/100, 84/100, 85/100** (430/500). - All unhealthy events and subsequent barrier events in those batches reached the receiving worker. - After subscription, the healthy/unhealthy control transitions passed **1000/1000** in those five batches. - Every divergent sample had `arrival_phase = "poll"`, `arrival_registered = false`, and `status_ver = 0`. These are repeatable, scheduled race experiments, not a 100% deterministic single-trial reproducer or an estimate of production incidence. This experiment observes the state after initialization; it does not reproduce the original 6.5-minute duration or the complete HTTPS/Kubernetes deployment. A representative sample: ```json { "kind": "race", "round": 1, "local_healthy": true, "shm_status": 2, "status_ver": 0, "event_seen": true, "arrival_phase": "poll", "arrival_registered": false, "post_barrier_seen": true } ``` In a **separate routing experiment**, using a real APISIX priority roundrobin upstream with a healthy fallback, a controlled shared-memory-only unhealthy state change left the local status/version unchanged: 50/50 requests immediately, and another 50/50 after 3 seconds, still selected the primary. A normal state-change event then updated the local version and 50/50 requests selected the fallback. That experiment used one worker and suppressed automatic probe/recovery changes; it verifies the routing consequence of divergence, not the initialization trigger itself. ### Runnable component reproducer Tested with `apache/apisix:3.19.0-debian`, OpenResty 1.29.2.4, and `lua-resty-healthcheck-api7` 3.2.3. The healthcheck source in the image was byte-for-byte equal to upstream v3.2.3 (SHA256 `fbcfc1749bf1360b82319004be66642175e8ce6fea36013f25ef032f3c2947c0`). The routing experiment's `balancer.lua` and `healthcheck_manager.lua` also matched the APISIX 3.19.0 tag. Save the following three files together, then run `bash run.sh`. Requirements: Bash, Python 3, and access to a local Linux Docker daemon. The container uses `--network none`, a Unix socket, and no published ports. The runner prints a summary and a divergent sample if observed, leaves raw JSONL results in the printed temporary directory, and removes its container on exit. Re-run for additional batches; the per-batch count depends on scheduling. <details> <summary>nginx.conf</summary> ```nginx worker_processes 2; user root; daemon off; error_log /dev/stderr notice; pid /tmp/hc-race.pid; events { worker_connections 1024; } http { lua_package_path "/probe/?.lua;/usr/local/apisix/deps/share/lua/5.1/?.lua;/usr/local/apisix/deps/share/lua/5.1/?/init.lua;;"; lua_package_cpath "/usr/local/apisix/deps/lib/lua/5.1/?.so;;"; lua_shared_dict hc 20m; lua_shared_dict coord 5m; init_worker_by_lua_file /probe/probe.lua; server { listen unix:/tmp/hc-events.sock; access_log off; location / { content_by_lua_block { require("resty.events.compat").run() } } } } ``` </details> <details> <summary>probe.lua</summary> ```lua local ev = require "resty.events.compat" assert(ev.configure({listening="unix:/tmp/hc-events.sock", broker_id=0})) local hc = require "resty.healthcheck" local json = require "cjson.safe" local wid = ngx.worker.id() local coord = ngx.shared.coord local active_round, phase local objects = {} local ip, port, host = "127.0.0.2", 1234, "race.test" local function set(k,v) assert(coord:set(k,v)) end local function await(k, expected) local deadline = ngx.now() + 5 while coord:get(k) ~= expected do assert(ngx.now() < deadline, "timeout " .. k .. " expected " .. tostring(expected) .. " got " .. tostring(coord:get(k))) ngx.sleep(0.001) end end local function emit(t) local f = assert(io.open("/probe/results-"..wid..".jsonl", "a")) f:write(assert(json.encode(t)), "\n") f:close() end local function new(name) local obj = assert(hc.new({name=name, shm_name="hc", events_module="resty.events", checks={active={healthy={interval=0}, unhealthy={interval=0}}}})) objects[name] = obj return obj end local function state(obj) return {local_healthy=obj:get_target_status(ip,port,host), shm_status=ngx.shared.hc:get(obj.TARGET_STATE..":"..ip..":"..port..":"..host), status_ver=obj.status_ver} end local orig_poll = ev.poll function ev.poll(...) if wid == 1 and active_round then phase = "poll" set("gate:"..active_round, true) end local result = orig_poll(...) if wid == 1 and active_round then phase = "after_poll" end return result end local orig_register = ev.register_weak function ev.register_weak(callback, source, ...) if wid == 1 and active_round then phase = "registered" set("registered:"..active_round, true) end return orig_register(callback, source, ...) end ev.register(function(data, event, source, from) if source == "probe-barrier" then set("barrier:"..wid..":"..data.id, true) return end local r = source:match("lua%-resty%-healthcheck %[race%-(%d+)%]") if r and event == "unhealthy" then set("seen:"..wid..":"..r, true) if wid == 1 then set("arrival_phase:"..r, phase or "none") set("arrival_registered:"..r, coord:get("registered:"..r) == true) end end end) local function barrier(id) assert(ev.post("probe-barrier","passed",{id=id})) await("barrier:0:"..id,true) await("barrier:1:"..id,true) end local function main() -- Let both real event client connections become usable, then prove delivery. ngx.sleep(0.15) set("ready:"..wid,true) await("ready:0",true); await("ready:1",true) if wid == 0 then barrier("initial") for r=1,100 do local name = "race-"..r local obj = new(name) assert(obj:add_target(ip,port,host,true)) barrier("seed-"..r) set("seed:"..r,true) await("gate:"..r,true) assert(obj:set_target_status(ip,port,host,false)) await("seen:0:"..r,true) await("created:"..r,true) barrier("post-"..r) set("postbarrier:"..r,true) await("checked:"..r,true) -- Control: a fresh normal transition after receiver subscription. assert(obj:set_target_status(ip,port,host,true)) barrier("control-healthy-"..r) set("controlhealthy:"..r,true) await("checkedhealthy:"..r,true) assert(obj:set_target_status(ip,port,host,false)) barrier("control-unhealthy-"..r) set("controlunhealthy:"..r,true) await("checkedunhealthy:"..r,true) obj:stop() end emit({kind="done",worker=wid}) else local divergent, pre_registration, control_failures = 0,0,0 for r=1,100 do await("seed:"..r,true) active_round = tostring(r) phase = "before_new" local obj = new("race-"..r) phase = "created" set("created:"..r,true) await("postbarrier:"..r,true) -- More than the poll interval has elapsed, and a later event was delivered. ngx.sleep(0.01) local s=state(obj) s.kind="race"; s.round=r s.event_seen=coord:get("seen:1:"..r)==true s.arrival_phase=coord:get("arrival_phase:"..r) s.arrival_registered=coord:get("arrival_registered:"..r) s.post_barrier_seen=coord:get("barrier:1:post-"..r)==true if s.local_healthy and s.shm_status==2 then divergent=divergent+1 end if not s.arrival_registered then pre_registration=pre_registration+1 end emit(s) set("checked:"..r,true) await("controlhealthy:"..r,true) local a=state(obj) a.kind="control_healthy";a.round=r;emit(a) if not a.local_healthy or a.shm_status~=1 then control_failures=control_failures+1 end set("checkedhealthy:"..r,true) await("controlunhealthy:"..r,true) local b=state(obj) b.kind="control_unhealthy";b.round=r;emit(b) if b.local_healthy or b.shm_status~=2 then control_failures=control_failures+1 end set("checkedunhealthy:"..r,true) obj:stop() active_round=nil end emit({kind="summary",rounds=100,divergent=divergent,event_arrived_before_registration=pre_registration,control_failures=control_failures,poll_delay_seconds=0.002,added_poll_delay_seconds=0}) end end assert(ngx.timer.at(0, function(premature) if premature then return end local ok,err=xpcall(main,debug.traceback) if not ok then emit({kind="error",worker=wid,error=err}) end end)) ``` </details> <details> <summary>run.sh</summary> ```bash #!/usr/bin/env bash set -euo pipefail probe_dir="$(mktemp -d "${TMPDIR:-/tmp}/apisix-13888.XXXXXX")" chmod 0777 "$probe_dir" cp nginx.conf probe.lua "$probe_dir/" container_name="apisix-13888-${probe_dir##*.}" cleanup() { docker rm -f "$container_name" >/dev/null 2>&1 || true; } trap cleanup EXIT docker run -d --rm --network none --name "$container_name" --mount "type=bind,src=$probe_dir,dst=/probe" --entrypoint /usr/local/openresty/nginx/sbin/nginx apache/apisix:3.19.0-debian -p /tmp/ -c /probe/nginx.conf python3 - "$probe_dir" <<'PY_CHECK' import json, pathlib, sys, time root = pathlib.Path(sys.argv[1]) deadline = time.monotonic() + 60 while time.monotonic() < deadline: rows = [] for path in root.glob("results-*.jsonl"): for line in path.read_text().splitlines(): try: rows.append(json.loads(line)) except json.JSONDecodeError: pass # The last line may still be being written. errors = [r for r in rows if r["kind"] == "error"] if errors: raise RuntimeError(errors) summaries = [r for r in rows if r["kind"] == "summary"] if summaries and any(r["kind"] == "done" for r in rows): break time.sleep(0.1) else: raise RuntimeError("No completed run within 60 seconds; check Docker startup/output and rerun") races = [r for r in rows if r["kind"] == "race"] assert len(races) == 100 assert all(r["event_seen"] and r["post_barrier_seen"] for r in races) assert summaries[0]["control_failures"] == 0 stale = [r for r in races if r["local_healthy"] and r["shm_status"] == 2] assert len(stale) == summaries[0]["divergent"] assert all(r["status_ver"] == 0 and r["arrival_phase"] == "poll" and not r["arrival_registered"] for r in stale) print(json.dumps(summaries[0], indent=2)) if stale: print("Example:", json.dumps(stale[0])) else: print("No race observed in this batch; scheduling is nondeterministic.") print("Raw results:", root) PY_CHECK ``` </details> ### Regression scenario for a fix The regression should exercise this initialization handoff and then route real requests through the affected worker with a healthy fallback available. After initialization and event processing have settled, those requests must exclude the target recorded as unhealthy in shared memory; normal recovery must allow it again. A dependency-level fix may restore the local snapshot. An APISIX-level fix may instead make health filtering and picker invalidation use shared state. For the latter approach, a stale local snapshot alone is not sufficient to call the fix unsuccessful: the decisive assertion is the affected worker's actual routing decision. A test that only writes unhealthy directly to shared memory covers the consequence, but does not by itself cover the initialization trigger above. -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
