feat(task-assigner): add debug flag for task assignment logging

Introduce `ENABLE_TASK_ASSIGNMENT_DEBUG` configuration to control verbose
logging in task assignment, Redis subscription, and worker management flows.
This reduces log noise by default while allowing detailed debugging when
enabled.
This commit is contained in:
2025-10-27 08:42:45 +10:30
parent 54ac191f65
commit 0237024d1c
4 changed files with 36 additions and 16 deletions
+2
View File
@@ -22,6 +22,8 @@ ASSIGN_INTERVAL_SECONDS = 30
LIVENESS_CHECK_INTERVAL_SECONDS = 5 # How often to cross check connected_workers with ping results from Redis LIVENESS_CHECK_INTERVAL_SECONDS = 5 # How often to cross check connected_workers with ping results from Redis
ENABLE_WEBSOCKET_PING_DEBUG = os.getenv('ENABLE_WEBSOCKET_PING_DEBUG', 'false').lower() == 'true' ENABLE_WEBSOCKET_PING_DEBUG = os.getenv('ENABLE_WEBSOCKET_PING_DEBUG', 'false').lower() == 'true'
ENABLE_TASK_ASSIGNMENT_DEBUG = os.getenv('ENABLE_TASK_ASSIGNMENT_DEBUG', 'false').lower() == 'true'
# Database configuration # Database configuration
DATABASE_URL = "mysql://root:password@172.17.0.1:3306/theapi" DATABASE_URL = "mysql://root:password@172.17.0.1:3306/theapi"
+10 -4
View File
@@ -8,6 +8,8 @@ from websocket_server.task_assigner import assign_task_to_worker
from websocket_server.worker_manager import notify_worker_disconnect from websocket_server.worker_manager import notify_worker_disconnect
import logging import logging
from websocket_server.config import ENABLE_TASK_ASSIGNMENT_DEBUG
logger = logging.getLogger("websocket_server") logger = logging.getLogger("websocket_server")
# Shared state # Shared state
@@ -38,16 +40,20 @@ def redis_subscribe(worker_id):
message = pubsub.get_message(timeout=1.0) message = pubsub.get_message(timeout=1.0)
if message and message["type"] in ["pmessage", "message"]: if message and message["type"] in ["pmessage", "message"]:
current_status = redis_client.get(f"worker_status_{worker_id}") current_status = redis_client.get(f"worker_status_{worker_id}")
logger.debug(f"[{worker_id}] Current Redis status: {current_status}") if ENABLE_TASK_ASSIGNMENT_DEBUG:
logger.debug(f"[{worker_id}] Current Redis status: {current_status}")
if current_status and current_status.lower() == "idle": if current_status and current_status.lower() == "idle":
if redis_client.get(f"worker_queue_{worker_id}").lower() == "true": if redis_client.get(f"worker_queue_{worker_id}").lower() == "true":
logger.info(f"[{worker_id}] Queue is true, setting dispatch flag") if ENABLE_TASK_ASSIGNMENT_DEBUG:
logger.debug(f"[{worker_id}] Queue is true, setting dispatch flag")
worker_dispatch_flags[worker_id] = True worker_dispatch_flags[worker_id] = True
else: else:
logger.info(f"[{worker_id}] Queue false, no dispatch needed") if ENABLE_TASK_ASSIGNMENT_DEBUG:
logger.debug(f"[{worker_id}] Queue false, no dispatch needed")
else: else:
logger.info(f"[{worker_id}] Status is not idle, skipping") if ENABLE_TASK_ASSIGNMENT_DEBUG:
logger.debug(f"[{worker_id}] Status is not idle, skipping")
logger.warning(f"[{worker_id}] Redis pub/sub loop exited, disconnecting") logger.warning(f"[{worker_id}] Redis pub/sub loop exited, disconnecting")
notify_worker_disconnect(worker_id) notify_worker_disconnect(worker_id)
+17 -8
View File
@@ -9,6 +9,7 @@ from websocket_server.models import Task
import logging import logging
from websocket_server.shared_state import connected_workers, worker_lock from websocket_server.shared_state import connected_workers, worker_lock
from websocket_server.events import base from websocket_server.events import base
from websocket_server.config import ENABLE_TASK_ASSIGNMENT_DEBUG
logger = logging.getLogger("websocket_server") logger = logging.getLogger("websocket_server")
@@ -21,14 +22,17 @@ def assign_task_to_worker(worker_id):
max_lock_retries = 5 max_lock_retries = 5
lock_retry_wait = 0.2 lock_retry_wait = 0.2
logger.info(f"[{worker_id}] Starting task assignment process") if ENABLE_TASK_ASSIGNMENT_DEBUG:
logger.debug(f"[{worker_id}] Starting task assignment process")
try: try:
redis_client.set(f"worker_status_{worker_id}", "busy") redis_client.set(f"worker_status_{worker_id}", "busy")
logger.debug(f"[{worker_id}] Marked as 'busy' in Redis") if ENABLE_TASK_ASSIGNMENT_DEBUG:
logger.debug(f"[{worker_id}] Marked as 'busy' in Redis")
for attempt in range(max_lock_retries): for attempt in range(max_lock_retries):
logger.debug(f"[{worker_id}] Lock attempt {attempt + 1}/{max_lock_retries}") if ENABLE_TASK_ASSIGNMENT_DEBUG:
logger.debug(f"[{worker_id}] Lock attempt {attempt + 1}/{max_lock_retries}")
with get_db_session() as session: with get_db_session() as session:
now = datetime.utcnow() now = datetime.utcnow()
candidates = session.query(Task).filter( candidates = session.query(Task).filter(
@@ -50,7 +54,8 @@ def assign_task_to_worker(worker_id):
ready.append(task) ready.append(task)
if not ready: if not ready:
logger.info(f"[{worker_id}] No ready tasks with satisfied dependencies") if ENABLE_TASK_ASSIGNMENT_DEBUG:
logger.debug(f"[{worker_id}] No ready tasks with satisfied dependencies")
redis_client.set(f"worker_queue_{worker_id}", "False") redis_client.set(f"worker_queue_{worker_id}", "False")
redis_client.set(f"worker_status_{worker_id}", "idle") redis_client.set(f"worker_status_{worker_id}", "idle")
return return
@@ -63,21 +68,25 @@ def assign_task_to_worker(worker_id):
).with_for_update(skip_locked=True).limit(1).one_or_none() ).with_for_update(skip_locked=True).limit(1).one_or_none()
if selected: if selected:
logger.info(f"[{worker_id}] Task selected: {selected.id}") if ENABLE_TASK_ASSIGNMENT_DEBUG:
logger.debug(f"[{worker_id}] Task selected: {selected.id}")
break break
logger.warning(f"[{worker_id}] Lock contention, retrying...") if ENABLE_TASK_ASSIGNMENT_DEBUG:
logger.debug(f"[{worker_id}] Lock contention, retrying...")
time.sleep(lock_retry_wait) time.sleep(lock_retry_wait)
lock_retry_wait *= 2 lock_retry_wait *= 2
else: else:
logger.error(f"[{worker_id}] Failed to acquire task after {max_lock_retries} attempts") if ENABLE_TASK_ASSIGNMENT_DEBUG:
logger.debug(f"[{worker_id}] Failed to acquire task after {max_lock_retries} attempts")
redis_client.set(f"worker_status_{worker_id}", "idle") redis_client.set(f"worker_status_{worker_id}", "idle")
redis_client.set(f"worker_queue_{worker_id}", "False") redis_client.set(f"worker_queue_{worker_id}", "False")
return return
with worker_lock: with worker_lock:
if worker_id in connected_workers: if worker_id in connected_workers:
logger.debug(f"[{worker_id}] Dispatching task {selected.id}") if ENABLE_TASK_ASSIGNMENT_DEBUG:
logger.debug(f"[{worker_id}] Dispatching task {selected.id}")
base.socketio.emit("task", { base.socketio.emit("task", {
"task_id": selected.id, "task_id": selected.id,
"worker_id": worker_id, "worker_id": worker_id,
+7 -4
View File
@@ -6,7 +6,7 @@ import time
import threading import threading
import logging import logging
from websocket_server.shared_state import connected_workers, worker_lock, ping_tracker from websocket_server.shared_state import connected_workers, worker_lock, ping_tracker
from websocket_server.config import get_redis_client,PING_INTERVAL_SECONDS, ASSIGN_INTERVAL_SECONDS, LIVENESS_CHECK_INTERVAL_SECONDS, PING_EXPIRY_SECONDS, ENABLE_WEBSOCKET_PING_DEBUG from websocket_server.config import get_redis_client,PING_INTERVAL_SECONDS, ASSIGN_INTERVAL_SECONDS, LIVENESS_CHECK_INTERVAL_SECONDS, PING_EXPIRY_SECONDS, ENABLE_WEBSOCKET_PING_DEBUG, ENABLE_TASK_ASSIGNMENT_DEBUG
from websocket_server.task_assigner import assign_task_to_worker from websocket_server.task_assigner import assign_task_to_worker
from websocket_server.events import base from websocket_server.events import base
@@ -66,7 +66,8 @@ def worker_dispatch_flag_check():
logger.info("Worker dispatch flag thread started") logger.info("Worker dispatch flag thread started")
while True: while True:
for wid in list(worker_dispatch_flags.keys()): for wid in list(worker_dispatch_flags.keys()):
logger.info(f"[{wid}] Dispatch flag set. Triggering task assign.") if ENABLE_TASK_ASSIGNMENT_DEBUG:
logger.debug(f"[{wid}] Dispatch flag set. Triggering task assign.")
del worker_dispatch_flags[wid] del worker_dispatch_flags[wid]
assign_task_to_worker(wid) assign_task_to_worker(wid)
threading.Event().wait(0.01) threading.Event().wait(0.01)
@@ -109,9 +110,11 @@ def all_worker_watchdog():
# 2. Trigger task assignment if due # 2. Trigger task assignment if due
if now - last_assign_time >= ASSIGN_INTERVAL_SECONDS: if now - last_assign_time >= ASSIGN_INTERVAL_SECONDS:
if worker_ids: if worker_ids:
logger.debug("Checking for task assignment across all workers") if ENABLE_TASK_ASSIGNMENT_DEBUG:
logger.debug("Checking for task assignment across all workers")
for wid in worker_ids: for wid in worker_ids:
logger.info(f"[{wid}] Triggering assign check") if ENABLE_TASK_ASSIGNMENT_DEBUG:
logger.debug(f"[{wid}] Triggering assign check")
assign_task_to_worker(wid) assign_task_to_worker(wid)
last_assign_time = now last_assign_time = now