++

backend/app/api/simulate.py

@@ -1,9 +1,10 @@
-from __future__ import annotations
-import asyncio
-import json
-import uuid
-import logging
-from typing import AsyncGenerator
+from __future__ import annotations
+import asyncio
+import json
+import logging
+import uuid
+import time
+from typing import AsyncGenerator
 
 from fastapi import APIRouter, Request, HTTPException, Query
 from pydantic import BaseModel
@@ -12,8 +13,10 @@ from sse_starlette.sse import EventSourceResponse
 from app.models.simulation import SSEEvent, SimulationStatus, SpeedMode, ForkRequest
 from app.models.world import WorldState, WorldMetrics
 from app.models.demographics import DemographicProfile
-from app.services.census import CensusService
-from app.services.i18n import locale_from_request, translate
+from app.services.census import CensusService
+from app.services.i18n import locale_from_request, translate
+from app.services.sim_logger import SimulationLogger
+from app.services.simulation_logging import bind_simulation, unbind_simulation
 
 from enum import Enum
 
@@ -97,25 +100,57 @@ async def simulate(req: SimulateRequest, request: Request):
     store = request.app.state.store
     world_gen = request.app.state.world_generator
     citizen_gen = request.app.state.citizen_generator
-    engine = request.app.state.engine
-
-    await store.create(sim_id, rules)
-
-    cancelled = request.app.state.cancelled_sims
-
-    async def run_pipeline():
-        event_queue = request.app.state.event_queues.get(sim_id)
-        if not event_queue:
-            return
-
-        try:
-            await event_queue.put(SSEEvent(type="status", data={"status": "generating_world"}))
-            await store.update_status(sim_id, SimulationStatus.GENERATING_WORLD.value)
-
-            blueprint = await world_gen.generate(
-                req.rules, req.population, req.duration_days,
-                proposed_change=req.proposed_change,
-            )
+    engine = request.app.state.engine
+
+    request_log_token = bind_simulation(sim_id)
+    try:
+        await store.create(sim_id, rules)
+        logger.info(
+            "模拟 %s 已创建：规则长度=%d，人口=%d，持续天数=%d",
+            sim_id, len(rules), req.population, req.duration_days,
+        )
+        sim_log = SimulationLogger(sim_id)
+        sim_log.log_event("pipeline_started", {
+            "population": req.population,
+            "duration_days": req.duration_days,
+            "rules_chars": len(rules),
+            "has_proposed_change": bool(req.proposed_change),
+            "has_city": bool(req.city),
+        })
+    finally:
+        unbind_simulation(request_log_token)
+
+    cancelled = request.app.state.cancelled_sims
+
+    async def run_pipeline():
+        pipeline_log_token = bind_simulation(sim_id)
+        event_queue = request.app.state.event_queues.get(sim_id)
+        if not event_queue:
+            unbind_simulation(pipeline_log_token)
+            return
+        t_pipeline_start = time.monotonic()
+        t_stage = time.monotonic()
+
+        try:
+            await event_queue.put(SSEEvent(type="status", data={"status": "generating_world"}))
+            await store.update_status(sim_id, SimulationStatus.GENERATING_WORLD.value)
+            logger.info("模拟 %s：开始生成世界", sim_id)
+
+            blueprint = await world_gen.generate(
+                req.rules, req.population, req.duration_days,
+                proposed_change=req.proposed_change,
+            )
+            logger.info(
+                "模拟 %s：世界生成完成，耗时=%.2f秒，世界=%r",
+                sim_id, time.monotonic() - t_stage, blueprint.name,
+            )
+            sim_log.log_event("world_generated", {
+                "world_name": blueprint.name,
+                "elapsed_s": round(time.monotonic() - t_stage, 3),
+                "population": req.population,
+                "duration_days": req.duration_days,
+            })
+            t_stage = time.monotonic()
 
             if sim_id in cancelled:
                 await event_queue.put(SSEEvent(type="cancelled", data={"message": translate("simulation_cancelled", locale)}))
@@ -152,10 +187,14 @@ async def simulate(req: SimulateRequest, request: Request):
                         "poverty_rate": demographics.poverty_rate,
                     }))
                 except Exception as e:
-                    logger.warning("Demographics fetch failed for %s: %s", req.city, e)
+                    logger.warning("城市人口统计数据获取失败（城市=%s）：%s", req.city, e)
 
             await event_queue.put(SSEEvent(type="status", data={"status": "generating_citizens"}))
-            await store.update_status(sim_id, SimulationStatus.GENERATING_CITIZENS.value)
+            await store.update_status(sim_id, SimulationStatus.GENERATING_CITIZENS.value)
+            logger.info(
+                "模拟 %s：开始生成居民，目标数量=%d",
+                sim_id, req.population,
+            )
 
             async def on_citizen(agent):
                 if sim_id in cancelled:
@@ -164,12 +203,21 @@ async def simulate(req: SimulateRequest, request: Request):
                 await event_queue.put(SSEEvent(type="citizen_generated", data=agent.model_dump()))
 
             segments_dicts = [s.model_dump() for s in req.segments] if req.segments else None
-            agents = await citizen_gen.generate_fast(
-                blueprint, req.population, on_citizen=on_citizen,
-                proposed_change=req.proposed_change,
-                segments=segments_dicts,
-                demographics=demographics,
-            )
+            agents = await citizen_gen.generate_fast(
+                blueprint, req.population, on_citizen=on_citizen,
+                proposed_change=req.proposed_change,
+                segments=segments_dicts,
+                demographics=demographics,
+            )
+            logger.info(
+                "模拟 %s：居民生成完成，耗时=%.2f秒，实际数量=%d",
+                sim_id, time.monotonic() - t_stage, len(agents),
+            )
+            sim_log.log_event("citizens_generated", {
+                "count": len(agents),
+                "elapsed_s": round(time.monotonic() - t_stage, 3),
+            })
+            t_stage = time.monotonic()
 
             for agent in agents:
                 await store.save_agent(sim_id, agent)
@@ -185,9 +233,9 @@ async def simulate(req: SimulateRequest, request: Request):
                     engine.deliver_enriched_agents(sim_id, enriched)
                     for agent in enriched:
                         await store.save_agent(sim_id, agent)
-                    logger.info("Background enrichment complete for %s", sim_id)
+                    logger.info("模拟 %s：居民背景信息补充完成", sim_id)
                 except Exception as e:
-                    logger.warning("Background enrichment failed for %s: %s", sim_id, e)
+                    logger.warning("模拟 %s：居民背景信息补充失败：%s", sim_id, e)
 
             asyncio.create_task(enrich_in_background())
 
@@ -197,21 +245,80 @@ async def simulate(req: SimulateRequest, request: Request):
                 community_rules=[],
             )
 
-            await store.update_status(sim_id, SimulationStatus.RUNNING.value)
+            await store.update_status(sim_id, SimulationStatus.RUNNING.value)
+            logger.info(
+                "模拟 %s：开始运行，居民=%d，天数=%d",
+                sim_id, len(agents), req.duration_days,
+            )
+            sim_log.log_event("simulation_run_started", {
+                "agent_count": len(agents),
+                "duration_days": req.duration_days,
+                "rounds_per_day": world_state.blueprint.time_config.rounds_per_day,
+                "total_rounds_planned": world_state.blueprint.time_config.total_days * world_state.blueprint.time_config.rounds_per_day,
+            })
 
             async def emit(event: SSEEvent):
                 await event_queue.put(event)
 
-            await engine.run(sim_id, world_state, agents, emit)
-
-        except asyncio.CancelledError:
-            logger.info("Pipeline cancelled for %s", sim_id)
-            await event_queue.put(SSEEvent(type="cancelled", data={"message": translate("simulation_cancelled", locale)}))
-        except Exception as e:
-            logger.error("Pipeline failed for %s: %s", sim_id, e, exc_info=True)
-            await event_queue.put(SSEEvent(type="error", data={"message": str(e)}))
-        finally:
-            cancelled.discard(sim_id)
+            await engine.run(sim_id, world_state, agents, emit, sim_log=sim_log)
+            final_sim = await store.get_simulation(sim_id)
+            if final_sim and final_sim.get("status") == SimulationStatus.ERROR.value:
+                # SimulationEngine records the detailed exception and may
+                # still generate a partial report. Do not label this path as
+                # "completed" in the pipeline log, otherwise a failed run is
+                # easy to mistake for a successful one.
+                logger.error("模拟 %s：运行未完成，已保留可用的部分结果", sim_id)
+                sim_log.log_event("simulation_run_failed", {
+                    "elapsed_s": round(time.monotonic() - t_stage, 3),
+                })
+            else:
+                logger.info(
+                    "模拟 %s：运行完成，耗时=%.2f秒，总行动数=%d",
+                    sim_id,
+                    time.monotonic() - t_stage,
+                    getattr(engine, "_total_actions", {}).get(sim_id, 0),
+                )
+                sim_log.log_event("simulation_run_complete", {
+                    "elapsed_s": round(time.monotonic() - t_stage, 3),
+                })
+                logger.info(
+                    "模拟 %s：全部流程完成，总耗时=%.2f秒",
+                    sim_id, time.monotonic() - t_pipeline_start,
+                )
+
+        except asyncio.CancelledError:
+            logger.info("模拟 %s：流程已取消", sim_id)
+            await event_queue.put(SSEEvent(type="cancelled", data={"message": translate("simulation_cancelled", locale)}))
+            # Cancellation is signalled by the user (or an upper-layer kill).
+            # Make sure the DB reflects it so a future report fetch returns
+            # terminal status instead of an old in-flight value.
+            try:
+                await store.update_status(sim_id, SimulationStatus.CANCELLED.value)
+                sim_log.log_event("pipeline_cancelled", {})
+            except Exception as status_err:
+                logger.warning("模拟 %s：写入取消状态失败：%s", sim_id, status_err)
+        except Exception as e:
+            logger.error("模拟 %s：流程失败：%s", sim_id, e, exc_info=True)
+            await event_queue.put(SSEEvent(type="error", data={"message": str(e)}))
+            # Bug fix: a failure during world/citizen generation used to leave
+            # the simulation stuck in `generating_world`/`generating_citizens`
+            # because nothing flipped the status to a terminal value. Make
+            # sure clients polling /report get a clean terminal status, and
+            # the orphan sweep on next restart doesn't keep showing it as
+            # in-flight.
+            try:
+                await store.update_status(sim_id, SimulationStatus.ERROR.value)
+                sim_log.log_event("pipeline_failed", {
+                    "error": str(e),
+                    "stage_elapsed_s": round(time.monotonic() - t_stage, 3),
+                    "total_elapsed_s": round(time.monotonic() - t_pipeline_start, 3),
+                })
+            except Exception as status_err:
+                logger.warning("模拟 %s：写入失败状态失败：%s", sim_id, status_err)
+        finally:
+            sim_log.close()
+            cancelled.discard(sim_id)
+            unbind_simulation(pipeline_log_token)
 
     request.app.state.event_queues[sim_id] = asyncio.Queue()
     asyncio.create_task(run_pipeline())
@@ -501,8 +608,9 @@ async def fork(sim_id: str, req: ForkRequest, request: Request):
     event_queue = asyncio.Queue()
     request.app.state.event_queues[fork_id] = event_queue
 
-    async def run_fork():
-        try:
+    async def run_fork():
+        fork_log_token = bind_simulation(fork_id)
+        try:
             world_state = await store.get_world_state(fork_id)
             agents = await store.get_all_agents(fork_id)
             if not world_state or not agents:
@@ -539,9 +647,11 @@ async def fork(sim_id: str, req: ForkRequest, request: Request):
 
             await engine.run(fork_id, world_state, agents, emit, start_round=fork_round)
 
-        except Exception as e:
-            logger.error("Fork pipeline failed for %s: %s", fork_id, e, exc_info=True)
-            await event_queue.put(SSEEvent(type="error", data={"message": str(e)}))
+        except Exception as e:
+            logger.error("分叉模拟 %s：流程失败：%s", fork_id, e, exc_info=True)
+            await event_queue.put(SSEEvent(type="error", data={"message": str(e)}))
+        finally:
+            unbind_simulation(fork_log_token)
 
     asyncio.create_task(run_fork())