Skip to content

Commit 51b2954

Browse files
committed
feat: hold tasks in a per-worker in-flight list so none can be lost in transit
BLPOP removes the task from the queue and *then* writes it to the client. If that write is lost, the task exists nowhere: not in ml_tasks, not in processing_tasks (which is only populated after the reply arrives), and so invisible to requeue_stuck_processing_tasks and every other recovery path. This is not theoretical. Reproduced against production on 2026-08-15 by blackholing a worker's connection at the Redis host and pushing a marked probe task. Redis served it to the blocked client — the client's idle timer reset at the moment of the push, so the pop and the write both happened — and the task was then absent from the queue with no worker ever logging receipt. It very likely explains the generation records seen stuck in "processing" with nothing queued behind them. BLMOVE makes taking the task and recording who took it a single atomic step: - the worker moves the task into `inflight:{server_id}:{worker_id}` and holds custody until it is done, whatever the outcome, via a finally - every in-flight list is registered in a set, so recovery enumerates them instead of SCANning for them - at startup a server drains its own lists, which can only be debris from a previous run of the same id - the pruning loop drains lists whose owning server is no longer registered, running after prune_inactive_servers so the dead are already deregistered include_self is the one flag that must not be wrong. At startup our lists are debris and must be drained; from the periodic sweep they belong to our own running workers, and draining those would hand a live task to a second worker. Both directions are tested. drain_inflight is bounded by the list length read up front rather than looping until empty, so it cannot spin if the no-appender assumption ever breaks. Requires Redis 6.2+ for BLMOVE/LMOVE. The fleet runs 7.4.2. The bounded-read test from the connection-liveness work now asserts the timeout on BLMOVE rather than BLPOP; the property it pins is unchanged. Mutation-tested: reverting to BLPOP, dropping the custody release, and letting the sweep drain live workers' lists each turn a test red. The first two initially survived against weaker assertions, which is why the custody test now observes a genuinely in-flight task mid-run rather than inspecting list lengths after the fact.
1 parent afe4934 commit 51b2954

3 files changed

Lines changed: 370 additions & 92 deletions

File tree

modelq/app/base.py

Lines changed: 174 additions & 78 deletions
Original file line numberDiff line numberDiff line change
@@ -138,6 +138,17 @@ class ModelQ:
138138
HEALTH_CHECK_INTERVAL = 30 # seconds: PING a pooled connection idle this long
139139
BACKGROUND_LOOP_BACKOFF = 5 # seconds: pause before retrying a crashed loop body
140140

141+
# --- in-flight task custody ------------------------------------------------
142+
# BLPOP removes the task from the list and *then* writes it to the client. If
143+
# that write is lost, the task exists nowhere: not in the queue, not in
144+
# processing_tasks (which is only populated after the reply arrives), and so
145+
# invisible to every recovery sweep. BLMOVE instead moves the task into a
146+
# per-worker in-flight list as a single atomic step, so a task in transit to
147+
# a worker that never receives it stays parked somewhere we can find it.
148+
INFLIGHT_PREFIX = "inflight"
149+
# Registry of every in-flight list, so recovery never has to SCAN for them.
150+
INFLIGHT_REGISTRY = "inflight_lists"
151+
141152
def __init__(
142153
self,
143154
host: str = "localhost",
@@ -733,6 +744,12 @@ def start_workers(self, no_of_workers: int = 1):
733744
else:
734745
self.check_middleware("before_worker_boot")
735746

747+
# Anything still in OUR in-flight lists is debris from a previous run of
748+
# this server_id — a live worker of ours cannot exist yet. Drain before
749+
# starting workers, never after, or we would yank a task out from under
750+
# a worker that had just claimed it.
751+
self.recover_abandoned_inflight_tasks(include_self=True)
752+
736753
# 1) Delayed re-queue thread
737754
requeue_thread = threading.Thread(target=self.requeue_delayed_tasks, daemon=True)
738755
requeue_thread.start()
@@ -751,6 +768,10 @@ def start_workers(self, no_of_workers: int = 1):
751768
# 4) Worker threads
752769
def worker_loop(worker_id):
753770
self.check_middleware("after_worker_boot")
771+
inflight_key = self._inflight_key(worker_id)
772+
# Register before taking custody of anything, so a task can never be
773+
# held in a list that recovery does not know to look in.
774+
self.redis_client.sadd(self.INFLIGHT_REGISTRY, inflight_key)
754775
while True:
755776
try:
756777
# Check worker health before picking up tasks
@@ -767,91 +788,104 @@ def worker_loop(worker_id):
767788
# forgotten, while the queue behind it grows unattended.
768789
# Timing out and looping forces the read to complete, which
769790
# is what lets keepalive/health-check reap the dead socket.
770-
task_data = self.redis_client.blpop("ml_tasks", timeout=self.BLPOP_TIMEOUT)
771-
if not task_data:
772-
continue
773-
774-
self.update_server_status(f"worker_{worker_id}: busy")
775-
_, task_json = task_data
776-
task_dict = json.loads(task_json)
777-
task = Task.from_dict(task_dict)
778-
779-
# Mark task as 'processing'
780-
added = self.redis_client.sadd("processing_tasks", task.task_id)
781-
if added == 0:
782-
logger.warning(
783-
f"Task {task.task_id} is already being processed. Skipping duplicate."
784-
)
791+
# Custody handoff, not a handoff-and-hope. BLPOP removes the
792+
# task and *then* writes it; if that write is lost the task is
793+
# gone from every structure that could recover it. BLMOVE makes
794+
# taking the task and recording who took it one atomic step, so
795+
# a task in transit to a worker that never receives it stays in
796+
# `inflight_key` until a sweep returns it to the queue.
797+
task_json = self.redis_client.blmove(
798+
"ml_tasks", inflight_key, self.BLPOP_TIMEOUT, "LEFT", "RIGHT"
799+
)
800+
if not task_json:
785801
continue
786-
task.status = "processing"
787-
788-
# The task has left the queue (claimed for processing). Keep the
789-
# `queued_requests` index in sync with `ml_tasks`; otherwise it
790-
# accumulates every completed/failed task forever and badly
791-
# inflates queue_num / queue_time.
792-
self.redis_client.zrem("queued_requests", task.task_id)
793-
794-
# Set started_at
795-
task_dict["started_at"] = time.time()
796-
797-
# Update in Redis
798-
self.redis_client.set(f"task:{task.task_id}", json.dumps(task_dict),ex=86400)
799-
800-
if task.task_name in self.allowed_tasks:
801-
try:
802-
logger.info(f"Worker {worker_id} started processing: {task.task_name}")
803-
804-
# Add Sentry breadcrumb for task processing
805-
if self.sentry_enabled:
806-
add_breadcrumb(
807-
message=f"Processing task: {task.task_name}",
808-
category="task",
809-
level="info",
810-
data={"task_id": task.task_id, "worker_id": worker_id},
811-
)
812802

813-
start_time = time.time()
814-
self.process_task(task)
815-
end_time = time.time()
816-
logger.info(
817-
f"Worker {worker_id} finished {task.task_name} "
818-
f"in {end_time - start_time:.2f} seconds"
803+
# Release custody only when we are finished with it, whatever
804+
# the outcome. If this process dies mid-task the entry stays
805+
# put on purpose — that is what makes it recoverable.
806+
try:
807+
self.update_server_status(f"worker_{worker_id}: busy")
808+
task_dict = json.loads(task_json)
809+
task = Task.from_dict(task_dict)
810+
811+
# Mark task as 'processing'
812+
added = self.redis_client.sadd("processing_tasks", task.task_id)
813+
if added == 0:
814+
logger.warning(
815+
f"Task {task.task_id} is already being processed. Skipping duplicate."
819816
)
820-
821-
except TaskProcessingError as e:
822-
if self._should_ignore_sentry_exception(e.__cause__):
823-
logger.warning(
824-
"Worker %s encountered an ignored Sentry TaskProcessingError: %s",
825-
worker_id,
826-
e,
817+
continue
818+
task.status = "processing"
819+
820+
# The task has left the queue (claimed for processing). Keep the
821+
# `queued_requests` index in sync with `ml_tasks`; otherwise it
822+
# accumulates every completed/failed task forever and badly
823+
# inflates queue_num / queue_time.
824+
self.redis_client.zrem("queued_requests", task.task_id)
825+
826+
# Set started_at
827+
task_dict["started_at"] = time.time()
828+
829+
# Update in Redis
830+
self.redis_client.set(f"task:{task.task_id}", json.dumps(task_dict),ex=86400)
831+
832+
if task.task_name in self.allowed_tasks:
833+
try:
834+
logger.info(f"Worker {worker_id} started processing: {task.task_name}")
835+
836+
# Add Sentry breadcrumb for task processing
837+
if self.sentry_enabled:
838+
add_breadcrumb(
839+
message=f"Processing task: {task.task_name}",
840+
category="task",
841+
level="info",
842+
data={"task_id": task.task_id, "worker_id": worker_id},
843+
)
844+
845+
start_time = time.time()
846+
self.process_task(task)
847+
end_time = time.time()
848+
logger.info(
849+
f"Worker {worker_id} finished {task.task_name} "
850+
f"in {end_time - start_time:.2f} seconds"
827851
)
828-
else:
852+
853+
except TaskProcessingError as e:
854+
if self._should_ignore_sentry_exception(e.__cause__):
855+
logger.warning(
856+
"Worker %s encountered an ignored Sentry TaskProcessingError: %s",
857+
worker_id,
858+
e,
859+
)
860+
else:
861+
logger.error(
862+
f"Worker {worker_id} encountered a TaskProcessingError: {e}"
863+
)
864+
if task.payload.get("retries", 0) > 0:
865+
new_task_dict = task.to_dict()
866+
new_task_dict["payload"] = task.original_payload
867+
new_task_dict["payload"]["retries"] -= 1
868+
self.enqueue_delayed_task(new_task_dict, delay_seconds=self.delay_seconds)
869+
870+
except Exception as e:
829871
logger.error(
830-
f"Worker {worker_id} encountered a TaskProcessingError: {e}"
872+
f"Worker {worker_id} encountered an unexpected error: {e}"
831873
)
832-
if task.payload.get("retries", 0) > 0:
833-
new_task_dict = task.to_dict()
834-
new_task_dict["payload"] = task.original_payload
835-
new_task_dict["payload"]["retries"] -= 1
836-
self.enqueue_delayed_task(new_task_dict, delay_seconds=self.delay_seconds)
837-
838-
except Exception as e:
839-
logger.error(
840-
f"Worker {worker_id} encountered an unexpected error: {e}"
874+
if task.payload.get("retries", 0) > 0:
875+
new_task_dict = task.to_dict()
876+
new_task_dict["payload"] = task.original_payload
877+
new_task_dict["payload"]["retries"] -= 1
878+
self.enqueue_delayed_task(new_task_dict, delay_seconds=self.delay_seconds)
879+
else:
880+
# If task is not allowed on this server, re-queue it
881+
logger.warning(
882+
f"Worker {worker_id} cannot process task {task.task_name}, re-queueing..."
841883
)
842-
if task.payload.get("retries", 0) > 0:
843-
new_task_dict = task.to_dict()
844-
new_task_dict["payload"] = task.original_payload
845-
new_task_dict["payload"]["retries"] -= 1
846-
self.enqueue_delayed_task(new_task_dict, delay_seconds=self.delay_seconds)
847-
else:
848-
# If task is not allowed on this server, re-queue it
849-
logger.warning(
850-
f"Worker {worker_id} cannot process task {task.task_name}, re-queueing..."
851-
)
852-
self.redis_client.rpush("ml_tasks", task_json)
853-
self.redis_client.zadd("queued_requests", {task.task_id: task_dict.get("queued_at", time.time())})
854-
self.redis_client.srem("processing_tasks", task.task_id)
884+
self.redis_client.rpush("ml_tasks", task_json)
885+
self.redis_client.zadd("queued_requests", {task.task_id: task_dict.get("queued_at", time.time())})
886+
self.redis_client.srem("processing_tasks", task.task_id)
887+
finally:
888+
self.redis_client.lrem(inflight_key, 1, task_json)
855889

856890
except Exception as e:
857891
logger.error(
@@ -877,6 +911,65 @@ def worker_loop(worker_id):
877911
f"Registered tasks: {task_names}"
878912
)
879913

914+
def _inflight_key(self, worker_id: int) -> str:
915+
"""Per-worker custody list. Scoped by server so recovery can attribute it."""
916+
return f"{self.INFLIGHT_PREFIX}:{self.server_id}:{worker_id}"
917+
918+
def drain_inflight(self, inflight_key: str) -> int:
919+
"""Return every task held in `inflight_key` to the front of the queue.
920+
921+
Tasks land here only when a worker took custody but never finished, so
922+
they are older than anything already queued and go back to the head.
923+
Uses LMOVE so a crash mid-drain cannot lose a task: it is in one list or
924+
the other at every instant, never in neither.
925+
"""
926+
# Bounded by the length read up front. The owner is gone, so nothing is
927+
# appending; an unbounded `while True` here would spin forever the day
928+
# that assumption breaks.
929+
moved = 0
930+
for _ in range(self.redis_client.llen(inflight_key) or 0):
931+
item = self.redis_client.lmove(inflight_key, "ml_tasks", "RIGHT", "LEFT")
932+
if item is None:
933+
break
934+
moved += 1
935+
self.redis_client.srem(self.INFLIGHT_REGISTRY, inflight_key)
936+
if moved:
937+
logger.warning(f"Recovered {moved} in-flight task(s) from '{inflight_key}'.")
938+
return moved
939+
940+
def recover_abandoned_inflight_tasks(
941+
self, active_server_ids=None, include_self: bool = False
942+
) -> int:
943+
"""Re-queue tasks stranded in the in-flight lists of dead workers.
944+
945+
`include_self` is the difference between the two callers, and getting it
946+
wrong is the one way this can lose work. At startup our own lists are
947+
debris from a previous run and must be drained. From the periodic sweep
948+
they belong to our own live workers, which are mid-task — draining those
949+
would hand the same task to somebody else while it is still running.
950+
"""
951+
if active_server_ids is None:
952+
active_server_ids = set(self.get_registered_server_ids() or [])
953+
active_server_ids = {
954+
s.decode() if isinstance(s, bytes) else s for s in active_server_ids
955+
}
956+
957+
recovered = 0
958+
for raw_key in self.redis_client.smembers(self.INFLIGHT_REGISTRY) or []:
959+
key = raw_key.decode() if isinstance(raw_key, bytes) else raw_key
960+
try:
961+
_, owner, _ = key.split(":", 2)
962+
except ValueError:
963+
logger.warning(f"Ignoring malformed in-flight key '{key}'.")
964+
continue
965+
if owner == self.server_id:
966+
if not include_self:
967+
continue
968+
elif owner in active_server_ids:
969+
continue # a live worker elsewhere still owns it
970+
recovered += self.drain_inflight(key)
971+
return recovered
972+
880973
@contextlib.contextmanager
881974
def _guarded_iteration(self, loop_name: str):
882975
"""Swallow and log any exception raised by one background-loop iteration.
@@ -914,6 +1007,9 @@ def _pruning_loop(self):
9141007
while True:
9151008
with self._guarded_iteration("pruning"):
9161009
self.prune_inactive_servers(timeout_seconds=self.PRUNE_TIMEOUT)
1010+
# Runs after the prune so dead servers are already deregistered
1011+
# and their in-flight lists read as abandoned on this same pass.
1012+
self.recover_abandoned_inflight_tasks()
9171013
self.requeue_stuck_processing_tasks(threshold=180)
9181014
self.prune_old_task_results(older_than_seconds=self.TASK_RESULT_RETENTION)
9191015
time.sleep(self.PRUNE_CHECK_INTERVAL)

tests/test_connection_liveness.py

Lines changed: 15 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -32,33 +32,34 @@ def modelq_instance():
3232
# 1. the queue read must be bounded
3333
# ---------------------------------------------------------------------------
3434

35-
def test_worker_blpop_passes_a_timeout(modelq_instance):
36-
"""The worker must never issue an unbounded BLPOP.
35+
def test_worker_queue_read_passes_a_timeout(modelq_instance):
36+
"""The worker must never issue an unbounded blocking read.
3737
38-
This is the actual outage. `blpop(key)` with no timeout blocks forever on a
39-
socket Redis has already forgotten.
38+
This is the actual outage. A blocking pop with no timeout waits forever on
39+
a socket Redis has already forgotten. The command is now BLMOVE rather than
40+
BLPOP (see the in-flight custody work), but the property under test is the
41+
same one: the read is bounded.
4042
"""
4143
seen = {}
4244
stop = threading.Event()
4345

44-
def fake_blpop(key, *args, **kwargs):
45-
seen["args"] = args
46-
seen["kwargs"] = kwargs
46+
def fake_blmove(src, dst, timeout, *args, **kwargs):
47+
seen["timeout"] = timeout
4748
stop.set()
48-
# Behave like a real timed-out BLPOP so the worker loops rather than
49-
# trying to decode a task.
49+
# Behave like a real timed-out blocking move so the worker loops rather
50+
# than trying to decode a task.
5051
time.sleep(0.01)
5152
return None
5253

5354
modelq_instance.redis_client = MagicMock(wraps=modelq_instance.redis_client)
54-
modelq_instance.redis_client.blpop.side_effect = fake_blpop
55+
modelq_instance.redis_client.blmove.side_effect = fake_blmove
5556

5657
modelq_instance.start_workers(no_of_workers=1)
57-
assert stop.wait(timeout=5), "worker never called blpop"
58+
assert stop.wait(timeout=5), "worker never issued a blocking queue read"
5859

59-
timeout = seen["kwargs"].get("timeout", seen["args"][0] if seen["args"] else None)
60-
assert timeout is not None, "BLPOP was issued without a timeout"
61-
assert timeout > 0, f"BLPOP timeout must be positive, got {timeout!r}"
60+
timeout = seen["timeout"]
61+
assert timeout is not None, "blocking read was issued without a timeout"
62+
assert timeout > 0, f"timeout must be positive, got {timeout!r}"
6263

6364

6465
def test_blpop_timeout_stays_below_socket_timeout():

0 commit comments

Comments
 (0)