整理代码

sync_state_machine/pipeline/factory.py

@@ -36,11 +36,9 @@ from ..config import (
     build_config,
     StrategyRuntimeConfig,
     build_config_from_file,
-    build_multi_project_config_from_file,
     apply_config_overrides,
     OrphanAction,
     UpdateDirection,
-    resolve_log_file_path,
     config_snapshot,
     is_multi_project_payload,
     load_overrides_from_file,
@@ -126,6 +124,72 @@ async def _initialize_datasource(datasource, *, endpoint_name: str) -> None:
     except Exception as exc:
         raise RuntimeError(f"Failed to initialize {endpoint_name} datasource: {type(exc).__name__}: {exc}") from exc
 
+
+async def _create_and_initialize_datasource(
+    ds_config: DataSourceConfig,
+    *,
+    datasource_override=None,
+    endpoint_name: str,
+    project_root: Path | None = None,
+):
+    datasource = await _create_datasource(
+        ds_config,
+        datasource_override=datasource_override,
+        endpoint_name=endpoint_name,
+        project_root=project_root,
+    )
+    await _initialize_datasource(datasource, endpoint_name=endpoint_name)
+    return datasource
+
+
+async def _safe_close_resource(name: str, resource) -> None:
+    if resource is None:
+        return
+    try:
+        await asyncio.wait_for(resource.close(), timeout=3.0)
+    except Exception as close_exc:
+        logger.warning("Failed to close %s during create cleanup: %s", name, close_exc)
+
+
+def _resolved_config_summary(config: PipelineRunConfig) -> tuple[str, str]:
+    summary = (
+        "Resolved Full Config Summary: node_types=%d local=%s remote=%s",
+        len(config.node_types),
+        config.local_datasource.type,
+        config.remote_datasource.type,
+    )
+    return summary[0], json.dumps(config_snapshot(config), ensure_ascii=False, indent=2)
+
+
+def _log_resolved_config(config: PipelineRunConfig) -> tuple[str, str]:
+    summary_template, resolved_cfg_text = _resolved_config_summary(config)
+    logger.info(
+        summary_template,
+        len(config.node_types),
+        config.local_datasource.type,
+        config.remote_datasource.type,
+    )
+    logger.info("Resolved Full Config:\n%s", resolved_cfg_text)
+    return summary_template, resolved_cfg_text
+
+
+def _log_pipeline_start(config: PipelineRunConfig, *, title: str) -> None:
+    logger.info("\n%s", "=" * 80)
+    logger.info("🚀 Creating %s", title)
+    logger.info("📝 Log file: %s", config.logging.file_path or "-")
+    logger.info(
+        "🔧 Resolved Full Config Summary: node_types=%d local=%s remote=%s",
+        len(config.node_types),
+        config.local_datasource.type,
+        config.remote_datasource.type,
+    )
+    logger.info("=" * 80)
+
+
+def _log_pipeline_end(config: PipelineRunConfig, *, stats: Dict[str, Any]) -> None:
+    logger.info("✅ Pipeline completed: stats=%s", stats)
+    logger.info("🗃️ Persistence DB: %s", config.persist.db_path)
+
 ensure_builtin_datasource_types_registered()
 
 
@@ -284,20 +348,18 @@ async def create_pipeline_from_config(
         persistence = create_persistence_backend(config.persist)
         await persistence.initialize()
 
-        local_ds = await _create_datasource(
+        local_ds = await _create_and_initialize_datasource(
             config.local_datasource,
             datasource_override=local_datasource_override,
             endpoint_name="local",
             project_root=_project_root(),
         )
-        await _initialize_datasource(local_ds, endpoint_name="local")
-        remote_ds = await _create_datasource(
+        remote_ds = await _create_and_initialize_datasource(
             config.remote_datasource,
             datasource_override=remote_datasource_override,
             endpoint_name="remote",
             project_root=_project_root(),
         )
-        await _initialize_datasource(remote_ds, endpoint_name="remote")
         _add_handlers(config, local_ds, remote_ds, all_types)
 
         local_collection, remote_collection, binding_manager = _build_collections_and_bindings(
@@ -332,17 +394,9 @@ async def create_pipeline_from_config(
 
         return pipeline
     except Exception:
-        async def _safe_close(name: str, resource) -> None:
-            if resource is None:
-                return
-            try:
-                await asyncio.wait_for(resource.close(), timeout=3.0)
-            except Exception as close_exc:
-                logger.warning("Failed to close %s during create cleanup: %s", name, close_exc)
-
-        await _safe_close("remote_datasource", remote_ds)
-        await _safe_close("local_datasource", local_ds)
-        await _safe_close("persistence", persistence)
+        await _safe_close_resource("remote_datasource", remote_ds)
+        await _safe_close_resource("local_datasource", local_ds)
+        await _safe_close_resource("persistence", persistence)
         raise
 
 
@@ -358,29 +412,12 @@ async def run_pipeline_from_config(
 ) -> Dict[str, Any]:
     ensure_app_logging(config.logging)
 
-    resolved_cfg = config_snapshot(config)
-    resolved_cfg_text = json.dumps(resolved_cfg, ensure_ascii=False, indent=2)
-    logger.info(
-        "Resolved Full Config Summary: node_types=%d local=%s remote=%s",
-        len(config.node_types),
-        config.local_datasource.type,
-        config.remote_datasource.type,
-    )
-    logger.info("Resolved Full Config:\n%s", resolved_cfg_text)
+    _log_resolved_config(config)
 
     pipeline: Optional[FullSyncPipeline] = None
     try:
         if print_summary:
-            logger.info("\n%s", "=" * 80)
-            logger.info("🚀 Creating %s", title)
-            logger.info("📝 Log file: %s", config.logging.file_path or "-")
-            logger.info(
-                "🔧 Resolved Full Config Summary: node_types=%d local=%s remote=%s",
-                len(config.node_types),
-                config.local_datasource.type,
-                config.remote_datasource.type,
-            )
-            logger.info("=" * 80)
+            _log_pipeline_start(config, title=title)
 
         pipeline = await create_pipeline_from_config(
             config,
@@ -393,8 +430,7 @@ async def run_pipeline_from_config(
         stats = await pipeline.run()
 
         if print_summary:
-            logger.info("✅ Pipeline completed: stats=%s", stats)
-            logger.info("🗃️ Persistence DB: %s", config.persist.db_path)
+            _log_pipeline_end(config, stats=stats)
 
         return stats
     finally:

sync_state_machine/pipeline/full_sync_pipeline.py

@@ -5,10 +5,9 @@ Full Sync Pipeline - Implements document-specified end-to-end workflow.
 from __future__ import annotations
 
 import asyncio
-import logging
 from dataclasses import dataclass
-from typing import Any, Dict, List, Optional, TYPE_CHECKING
 from pathlib import Path
+from typing import TYPE_CHECKING, Any, Dict, List, Optional
 
 if TYPE_CHECKING:
     from ..datasource.datasource import BaseDataSource
@@ -18,8 +17,8 @@ from ..common.collection import DataCollection
 from ..common.binding import BindingManager
 from ..logging import get_logger
 from ..common.persistence import PersistenceBackend
+from ..sync_system.config import UpdateDirection
 from ..sync_system.strategy import BaseSyncStrategy
-from ..sync_system.config import OrphanAction, UpdateDirection
 from ..engine import StateMachineConfig, StateMachineRuntime
 from ..engine import e41_post_create_ready
 from ..sync_system.strategy_ops import finalize_peer_creating_sources, run_phase2_cleanup
@@ -130,22 +129,73 @@ class FullSyncPipeline:
         cfg_path = Path(__file__).resolve().parents[1] / "config" / "node_state_machine.yaml"
         return StateMachineRuntime(StateMachineConfig.load(cfg_path))
 
+    def _strategy_map(self) -> Dict[str, BaseSyncStrategy]:
+        return {strategy.node_type: strategy for strategy in self.strategies}
+
+    def _iter_sync_strategies(self):
+        strategy_map = self._strategy_map()
+        for node_type in self.sync_order:
+            strategy = strategy_map.get(node_type)
+            if strategy is not None:
+                yield node_type, strategy
+
+    def _get_strategy(self, node_type: str) -> BaseSyncStrategy | None:
+        return next((item for item in self.strategies if item.node_type == node_type), None)
+
+    def _log_phase_completed(self, phase_name: str) -> None:
+        self._logger.info("✅ Phase %s completed (%s)", phase_name, self.pipeline_name)
+
+    def _log_strategy_start(self, node_type: str) -> None:
+        section_width = 96
+        self._logger.info("\n" + "-" * section_width)
+        self._logger.info("🧩 Strategy start: %s", node_type)
+        self._logger.info("-" * section_width)
+
+    def _log_strategy_result(self, action: str, node_type: str, count: int | None = None) -> None:
+        if count is None:
+            self._logger.info("✅ Strategy %s: %s", action, node_type)
+            return
+        self._logger.info("✅ Strategy %s: %s (%s=%d)", action, node_type, action, count)
+
+    def _log_strategy_done(self, node_type: str) -> None:
+        self._logger.info("✅ Strategy done: %s", node_type)
+
+    def _log_strategy_failure(self, stage: str, node_type: str, exc: Exception) -> None:
+        self._logger.error(
+            "❌ Strategy %s failed but pipeline continues: %s | %s: %s",
+            stage,
+            node_type,
+            type(exc).__name__,
+            exc,
+        )
+
+    def _log_reload_skipped(self, node_type: str, reason: str) -> None:
+        self._logger.info("⏭️  Reload skipped for JSONL pipeline: node_type=%s reason=%s", node_type, reason)
+
+    async def _safe_close(self, name: str, close_coro, timeout: float = 3.0) -> None:
+        try:
+            await asyncio.wait_for(close_coro, timeout=timeout)
+        except asyncio.TimeoutError:
+            self._logger.warning("⚠️ close timeout: %s (>%ss)", name, timeout)
+        except Exception as exc:
+            self._logger.warning("⚠️ close failed: %s (%s)", name, exc)
+
     async def run(self) -> Dict[str, Any]:
         persistence_started = False
         try:
             await self.phase_bootstrap()
-            self._logger.info("✅ Phase bootstrap completed (%s)", self.pipeline_name)
+            self._log_phase_completed("bootstrap")
 
             await self.phase_sync_by_node_type()
-            self._logger.info("✅ Phase sync-by-node-type completed (%s)", self.pipeline_name)
+            self._log_phase_completed("sync-by-node-type")
 
             post_ok = await self.phase_post_check()
             self.stats["post_check_passed"] = post_ok
-            self._logger.info("✅ Phase post-check completed (%s)", self.pipeline_name)
+            self._log_phase_completed("post-check")
 
             persistence_started = True
             await self.phase_persistence()
-            self._logger.info("✅ Phase persistence completed (%s)", self.pipeline_name)
+            self._log_phase_completed("persistence")
             return self.stats
         except Exception as exc:
             if not persistence_started:
@@ -180,29 +230,22 @@ class FullSyncPipeline:
 
     async def phase_sync_by_node_type(self) -> None:
         self._prepare_datasources()
-        strategy_map = {s.node_type: s for s in self.strategies}
-        for node_type in self.sync_order:
-            strategy = strategy_map.get(node_type)
-            if strategy is None:
-                continue
+        for node_type, strategy in self._iter_sync_strategies():
             try:
-                section_width = 96
-                self._logger.info("\n" + "-" * section_width)
-                self._logger.info(f"🧩 Strategy start: {node_type}")
-                self._logger.info("-" * section_width)
+                self._log_strategy_start(node_type)
 
                 await self._load_node_type(node_type, reason="pre-strategy refresh")
 
                 # Load failure is a hard stop: create/update cannot safely treat missing data as empty data.
                 await strategy.bind()
-                self._logger.info(f"✅ Strategy bind: {node_type}")
+                self._log_strategy_result("bind", node_type)
 
                 if strategy.skip_sync:
-                    self._logger.info(f"⏭️  Skipping create/update for {node_type} (skip_sync=True)")
+                    self._logger.info("⏭️  Skipping create/update for %s (skip_sync=True)", node_type)
                     continue
 
                 created = await strategy.create()
-                self._logger.info(f"✅ Strategy create: {node_type} (created={len(created)})")
+                self._log_strategy_result("create", node_type, len(created))
                 created_local_node_ids = {
                     node.node_id for node in created if self.local_collection.get_by_node_id(node.node_id) is not None
                 }
@@ -228,7 +271,7 @@ class FullSyncPipeline:
                     )
 
                 updated = await strategy.update()
-                self._logger.info(f"✅ Strategy update: {node_type} (updated={len(updated)})")
+                self._log_strategy_result("update", node_type, len(updated))
                 update_outcome = await self.commit_updates(node_type)
                 if update_outcome.any_written:
                     await self._reload_node_type_after_write(
@@ -238,12 +281,12 @@ class FullSyncPipeline:
                         reload_remote=update_outcome.remote_written,
                     )
 
-                self._logger.info(f"✅ Strategy done: {node_type}")
+                self._log_strategy_done(node_type)
             except NodeTypeLoadError:
                 raise
             except Exception as exc:
                 self.stats["failed"] += 1
-                self._logger.error(f"❌ Strategy failed but pipeline continues: {node_type} | {type(exc).__name__}: {exc}")
+                self._log_strategy_failure("sync", node_type, exc)
                 continue
 
     async def phase_bootstrap(self) -> None:
@@ -266,31 +309,23 @@ class FullSyncPipeline:
 
     async def phase_bind(self) -> None:
         self._prepare_datasources()
-        strategy_map = {s.node_type: s for s in self.strategies}
-        for node_type in self.sync_order:
-            strategy = strategy_map.get(node_type)
-            if strategy is None:
-                continue
+        for node_type, strategy in self._iter_sync_strategies():
             try:
                 await strategy.bind()
             except Exception as exc:
                 self.stats["failed"] += 1
-                self._logger.error(f"❌ Strategy bind failed but pipeline continues: {node_type} | {type(exc).__name__}: {exc}")
+                self._log_strategy_failure("bind", node_type, exc)
                 continue
 
     async def phase_create(self) -> None:
         self._prepare_datasources()
-        strategy_map = {s.node_type: s for s in self.strategies}
-        for node_type in self.sync_order:
-            strategy = strategy_map.get(node_type)
-            if strategy is None:
-                continue
+        for node_type, strategy in self._iter_sync_strategies():
             if strategy.skip_sync:
-                self._logger.info(f"⏭️  Skipping create for {node_type} (skip_sync=True)")
+                self._logger.info("⏭️  Skipping create for %s (skip_sync=True)", node_type)
                 continue
             try:
                 created = await strategy.create()
-                self._logger.info(f"✅ Strategy create: {node_type} (created={len(created)})")
+                self._log_strategy_result("create", node_type, len(created))
                 created_local_node_ids = {
                     node.node_id for node in created if self.local_collection.get_by_node_id(node.node_id) is not None
                 }
@@ -316,22 +351,18 @@ class FullSyncPipeline:
                     )
             except Exception as exc:
                 self.stats["failed"] += 1
-                self._logger.error(f"❌ Strategy create failed but pipeline continues: {node_type} | {type(exc).__name__}: {exc}")
+                self._log_strategy_failure("create", node_type, exc)
                 continue
 
     async def phase_update(self) -> None:
         self._prepare_datasources()
-        strategy_map = {s.node_type: s for s in self.strategies}
-        for node_type in self.sync_order:
-            strategy = strategy_map.get(node_type)
-            if strategy is None:
-                continue
+        for node_type, strategy in self._iter_sync_strategies():
             if strategy.skip_sync:
-                self._logger.info(f"⏭️  Skipping update for {node_type} (skip_sync=True)")
+                self._logger.info("⏭️  Skipping update for %s (skip_sync=True)", node_type)
                 continue
             try:
                 updated = await strategy.update()
-                self._logger.info(f"✅ Strategy update: {node_type} (updated={len(updated)})")
+                self._log_strategy_result("update", node_type, len(updated))
                 update_outcome = await self.commit_updates(node_type)
                 if update_outcome.any_written:
                     await self._reload_node_type_after_write(
@@ -343,7 +374,7 @@ class FullSyncPipeline:
                 await self._evaluate_consistency_for_node_type(node_type)
             except Exception as exc:
                 self.stats["failed"] += 1
-                self._logger.error(f"❌ Strategy update failed but pipeline continues: {node_type} | {type(exc).__name__}: {exc}")
+                self._log_strategy_failure("update", node_type, exc)
                 continue
 
     async def close(self) -> None:
@@ -352,17 +383,9 @@ class FullSyncPipeline:
             return  # 已经关闭过，避免重复关闭
         self._closed = True
 
-        async def _safe_close(name: str, close_coro, timeout: float = 3.0) -> None:
-            try:
-                await asyncio.wait_for(close_coro, timeout=timeout)
-            except asyncio.TimeoutError:
-                self._logger.warning("⚠️ close timeout: %s (>%ss)", name, timeout)
-            except Exception as exc:
-                self._logger.warning("⚠️ close failed: %s (%s)", name, exc)
-
-        await _safe_close("remote_datasource", self.remote_datasource.close())
-        await _safe_close("local_datasource", self.local_datasource.close())
-        await _safe_close("persistence", self.persistence.close())
+        await self._safe_close("remote_datasource", self.remote_datasource.close())
+        await self._safe_close("local_datasource", self.local_datasource.close())
+        await self._safe_close("persistence", self.persistence.close())
 
     async def _load_persistence_state(self) -> None:
         """加载持久化数据到内存，等待 bootstrap datasource refresh 与 E01 cleanup。"""
@@ -544,7 +567,7 @@ class FullSyncPipeline:
 
     async def _reload_node_type(self, node_type: str, *, reason: str) -> None:
         if self._should_skip_reload():
-            self._logger.info("⏭️  Reload skipped for JSONL pipeline: node_type=%s reason=%s", node_type, reason)
+            self._log_reload_skipped(node_type, reason)
             return
         await self._load_node_type(node_type, reason=reason)
 
@@ -560,7 +583,7 @@ class FullSyncPipeline:
             return
 
         if self._should_skip_reload():
-            self._logger.info("⏭️  Reload skipped for JSONL pipeline: node_type=%s reason=%s", node_type, reason)
+            self._log_reload_skipped(node_type, reason)
             return
 
         self._logger.info(
@@ -718,13 +741,13 @@ class FullSyncPipeline:
         else:
             self._logger.info("🔄 Post-check: reloading all node types for final consistency evaluation...")
             for node_type in self.node_types:
-                strategy = next((item for item in self.strategies if item.node_type == node_type), None)
+                strategy = self._get_strategy(node_type)
                 if strategy is not None and strategy.skip_post_check:
                     self._logger.info("⏭️  Post-check reload skipped: node_type=%s", node_type)
                     continue
                 await self._reload_node_type(node_type, reason="post-check final reload")
         for node_type in self.node_types:
-            strategy = next((item for item in self.strategies if item.node_type == node_type), None)
+            strategy = self._get_strategy(node_type)
             if strategy is not None and strategy.skip_post_check:
                 self._logger.info("⏭️  Post-check skipped: node_type=%s", node_type)
                 self._consistency_by_type[node_type] = {