From 3b172c6ec881af5ab5db540c80fab17765e8871b Mon Sep 17 00:00:00 2001 From: ggboyxkw666 <3510903266@qq.com> Date: Sat, 19 Sep 2026 20:48:31 +0800 Subject: [PATCH 1/2] feat: add submission evaluation lifecycle logs --- tasks/submission_tasks.py | 47 +++++++++++++++++++++++++++++++++ tests/test_submission_worker.py | 24 ++++++++++++++++- 2 files changed, 70 insertions(+), 1 deletion(-) diff --git a/tasks/submission_tasks.py b/tasks/submission_tasks.py index 253b00e..ebe9e51 100644 --- a/tasks/submission_tasks.py +++ b/tasks/submission_tasks.py @@ -3,7 +3,9 @@ from __future__ import annotations import json +import logging import threading +import time from models import Assignment, Submission, SystemLog, TestCase as TC, User, db from services.demo_database import activate_demo_run, is_active_demo_run @@ -12,6 +14,35 @@ from utils.scoring import normalize_evaluation_score, normalize_feedback_text +logger = logging.getLogger(__name__) + + +def _log_submission_evaluation_event( + event: str, + submission_id: int, + started_at: float, + *, + level: int = logging.INFO, + **fields, +) -> None: + """Write a bounded lifecycle signal without logging submission content.""" + + parts = [ + "submission_evaluation", + f"event={event}", + f"submission_id={int(submission_id)}", + f"elapsed_ms={int((time.perf_counter() - started_at) * 1000)}", + ] + parts.extend(f"{key}={value}" for key, value in fields.items()) + try: + from flask import current_app, has_app_context + + target_logger = current_app.logger if has_app_context() else logger + except RuntimeError: + target_logger = logger + target_logger.log(level, " ".join(parts)) + + def _demo_database_is_available(demo_run_id: str | None) -> bool: """Return whether this worker may still use its temporary database.""" @@ -123,7 +154,9 @@ def evaluate_submission_async( raise def _evaluate(): + started_at = time.perf_counter() with app.app_context(): + _log_submission_evaluation_event("started", submission_id, started_at) if demo_run_id and not activate_demo_run(demo_run_id): print("公开体验会话已失效，跳过提交评测") return @@ -337,11 +370,25 @@ def _evaluate(): user_id=student_id, icon="bi bi-check-circle-fill", ) + _log_submission_evaluation_event( + "finished", + submission_id, + started_at, + state=submission.status, + sandbox_status=submission.sandbox_status or "none", + ) print(f"提交 {submission_id} 评测全部完成") return "evaluated" except Exception as error: print(f"评测线程崩溃: {type(error).__name__}") + _log_submission_evaluation_event( + "failed", + submission_id, + started_at, + level=logging.WARNING, + error_type=type(error).__name__, + ) if not _demo_database_is_available(demo_run_id): return try: diff --git a/tests/test_submission_worker.py b/tests/test_submission_worker.py index a122c25..1975b49 100644 --- a/tests/test_submission_worker.py +++ b/tests/test_submission_worker.py @@ -1,4 +1,5 @@ import inspect +import re import sys import time from concurrent.futures import ThreadPoolExecutor @@ -193,8 +194,11 @@ def slow_completion(submission_id): assert submission_queue.get_submission_job_status(app, 42) == "failed" -def test_formal_worker_updates_submission_in_isolated_database(tmp_path, monkeypatch): +def test_formal_worker_updates_submission_in_isolated_database( + tmp_path, monkeypatch, caplog +): _require_worker_contract() + caplog.set_level("INFO") from app import create_app from config import TestingConfig as _TestingConfig from models import Assignment, StudentLearningVector, StudentVectorIndexState, Submission, User, db @@ -288,5 +292,23 @@ def test_formal_worker_updates_submission_in_isolated_database(tmp_path, monkeyp for vector in active_vectors ) + finished_events = [ + record.getMessage() + for record in caplog.records + if "submission_evaluation event=finished" in record.getMessage() + ] + started_events = [ + record.getMessage() + for record in caplog.records + if "submission_evaluation event=started" in record.getMessage() + ] + assert len(started_events) == 1 + assert len(finished_events) == 1 + finished_event = finished_events[0] + assert f"submission_id={submission_id}" in finished_event + assert "state=evaluated" in finished_event + elapsed_match = re.search(r"elapsed_ms=(\d+)", finished_event) + assert elapsed_match is not None + assert submission_queue.get_submission_job_status(app, submission_id) == "completed" assert state.operation_id == f"submission-evaluation-{submission_id}" From f211998d6e9081038793beed04450c21f053cdd5 Mon Sep 17 00:00:00 2001 From: ggboyxkw666 <3510903266@qq.com> Date: Sat, 19 Sep 2026 20:52:27 +0800 Subject: [PATCH 2/2] test: cover expired demo evaluation terminal log --- tasks/submission_tasks.py | 6 ++++++ tests/test_submission_worker.py | 34 +++++++++++++++++++++++++++++++++ 2 files changed, 40 insertions(+) diff --git a/tasks/submission_tasks.py b/tasks/submission_tasks.py index ebe9e51..1236f2e 100644 --- a/tasks/submission_tasks.py +++ b/tasks/submission_tasks.py @@ -159,6 +159,12 @@ def _evaluate(): _log_submission_evaluation_event("started", submission_id, started_at) if demo_run_id and not activate_demo_run(demo_run_id): print("公开体验会话已失效，跳过提交评测") + _log_submission_evaluation_event( + "skipped", + submission_id, + started_at, + reason="demo_run_unavailable", + ) return try: diff --git a/tests/test_submission_worker.py b/tests/test_submission_worker.py index 1975b49..828980a 100644 --- a/tests/test_submission_worker.py +++ b/tests/test_submission_worker.py @@ -92,6 +92,40 @@ def test_worker_entry_disables_web_threads_and_preset_scanner(monkeypatch): build.assert_called_once_with(app) +def test_expired_demo_run_emits_terminal_skipped_event(caplog): + _require_worker_contract() + caplog.set_level("INFO") + app = Flask(__name__) + + class ImmediateThread: + def __init__(self, target, *args, **kwargs): + self.target = target + self.daemon = False + + def start(self): + self.target() + + with patch.object(worker_tasks.threading, "Thread", ImmediateThread), \ + patch.object(worker_tasks, "activate_demo_run", return_value=False): + worker_tasks.evaluate_submission_async( + app, + 41, + "循环题", + demo_run_id="expired-demo-run", + ) + + messages = [record.getMessage() for record in caplog.records] + assert any( + "submission_evaluation event=started submission_id=41" in message + for message in messages + ) + assert any( + "submission_evaluation event=skipped submission_id=41" in message + and "reason=demo_run_unavailable" in message + for message in messages + ) + + def test_rq_backend_enqueues_without_starting_legacy_thread(): _require_worker_contract() app = Flask(__name__)