can run

fish_api/app/services/sonar_video.py

@@ -23,9 +23,9 @@ from loguru import logger
 from app.compat import to_thread
 from app.logging_config import new_run_id, stage
 from app.services.action_watch import iter_mp4
-from app.services.measure import transcode_src_to_h264_dst
+from app.services.measure import _ffprobe_video_codec_name, transcode_src_to_h264_dst
 from app.services.sonar_optical_flow import run_sonar_optical_flow_overlay
-from app.services.video_slice import _get_ffmpeg_path
+from app.services.video_slice import _get_ffmpeg_path, _get_ffprobe_path
 from app.settings import Settings
 
 DEFAULT_CLIENT_ID = "default"
@@ -34,6 +34,9 @@ DEFAULT_CLIENT_ID = "default"
 _published_url: str = ""
 _published_lock = asyncio.Lock()
 
+# 避免对同一「未就绪」文件每个 poll 都打 INFO
+_last_sonar_skip_logged_path: Optional[str] = None
+
 
 def _public_media_url(settings: Settings, basename: str) -> str:
     base = settings.public_base_url.rstrip("/")
@@ -65,20 +68,36 @@ def _is_ready_to_process(path: Path) -> bool:
 def _probe_moov_readable(path: Path) -> bool:
     """Quick check via ffprobe (fallback cv2): does the MP4/MOV have a moov atom?"""
     log = logger.bind(pipeline="sonar_watch", source=path.name)
+    ffprobe = _get_ffprobe_path()
     try:
         r = subprocess.run(
-            ["ffprobe", "-v", "error", "-show_entries", "format=duration",
-             "-of", "default=noprint_wrappers=1:nokey=1", str(path)],
-            capture_output=True, timeout=5,
+            [
+                ffprobe, "-v", "error", "-show_entries", "format=duration",
+                "-of", "default=noprint_wrappers=1:nokey=1", str(path),
+            ],
+            capture_output=True,
+            text=True,
+            timeout=5,
         )
         if r.returncode == 0 and r.stdout.strip():
             return True
-        log.debug("[声呐监控] ffprobe：moov 缺失：{}", path.name)
+        log.debug(
+            "[声呐监控] ffprobe 无有效 duration（可能缺 moov）| ffprobe={} | {}",
+            ffprobe,
+            path.name,
+        )
         return False
     except FileNotFoundError:
-        pass
+        log.warning(
+            "[声呐监控] 未找到 ffprobe（与 FFMPEG_PATH 同目录或 PATH）| 配置路径={}",
+            ffprobe,
+        )
     except Exception as e:
-        log.debug("[声呐监控] ffprobe 失败（{}），改用 cv2 探测", e)
+        log.debug(
+            "[声呐监控] ffprobe 失败（{}），改用 cv2 探测 | ffprobe={}",
+            e,
+            ffprobe,
+        )
 
     try:
         import cv2
@@ -107,6 +126,14 @@ def _extract_tail_slice(src: Path, slice_out: Path, duration_sec: float) -> bool
 
     ffmpeg = _get_ffmpeg_path()
     sec = float(duration_sec)
+    log = logger.bind(pipeline="sonar_watch", source=src.name)
+    log.info(
+        "[声呐监控] 尾段提取开始 | ffmpeg={} | 最后 {:.0f}s | {} -> {}",
+        ffmpeg,
+        sec,
+        src.name,
+        slice_out.name,
+    )
 
     # --- primary: -sseof (works on growing MKV even when duration is unknown) ---
     sseof_cmd = [
@@ -118,13 +145,16 @@ def _extract_tail_slice(src: Path, slice_out: Path, duration_sec: float) -> bool
         "-avoid_negative_ts", "make_zero",
         str(slice_out),
     ]
-    log = logger.bind(pipeline="sonar_watch", source=src.name)
     try:
         r = subprocess.run(sseof_cmd, capture_output=True, text=True, timeout=600)
         if r.returncode == 0 and slice_out.is_file() and slice_out.stat().st_size > 0:
-            log.debug(
-                "[声呐监控] 尾段提取成功（-sseof {:.0f}s）：{} -> {}",
-                sec, src.name, slice_out.name,
+            log.info(
+                "[声呐监控] 尾段提取成功（-sseof {:.0f}s copy）| ffmpeg={} | {} -> {}（{} 字节）",
+                sec,
+                ffmpeg,
+                src.name,
+                slice_out.name,
+                slice_out.stat().st_size,
             )
             return True
     except Exception as e:
@@ -141,9 +171,12 @@ def _extract_tail_slice(src: Path, slice_out: Path, duration_sec: float) -> bool
     try:
         r = subprocess.run(copy_cmd, capture_output=True, text=True, timeout=600)
         if r.returncode == 0 and slice_out.is_file() and slice_out.stat().st_size > 0:
-            log.debug(
-                "[声呐监控] 尾段提取成功（整段拷贝回退）：{} -> {}",
-                src.name, slice_out.name,
+            log.info(
+                "[声呐监控] 尾段提取成功（整段 -c copy 回退）| ffmpeg={} | {} -> {}（{} 字节）",
+                ffmpeg,
+                src.name,
+                slice_out.name,
+                slice_out.stat().st_size,
             )
             return True
     except Exception as e:
@@ -209,6 +242,13 @@ async def _publish_video(
             log.warning("[声呐监控] 尾段提取失败，跳过发布：{}", src.name)
             return None
 
+        if slice_tmp.is_file():
+            log.info(
+                "[声呐监控] 尾段切片已就绪 | {}（{:.2f} MB）→ 后续光流/H.264",
+                slice_tmp.name,
+                slice_tmp.stat().st_size / (1024 * 1024),
+            )
+
         transcode_src = slice_tmp
         if settings.biomass_sonar_optical_flow:
             flow_dst = media_root / f"{dst_stem}_optical_flow_{ts}.mp4"
@@ -237,6 +277,14 @@ async def _publish_video(
                 flow_tmp.unlink(missing_ok=True)
                 log.warning("[声呐监控] 光流叠加失败，对原切片直接转码：{}", src.name)
 
+        in_codec = _ffprobe_video_codec_name(transcode_src) or "未知"
+        log.info(
+            "[声呐监控] H.264 发布转码（FishMeasure 同款管线）| 输入编码={} | {} -> {}",
+            in_codec,
+            transcode_src.name,
+            tmp.name,
+        )
+
         with stage(
             f"声呐 H.264 转码（{src.name}）",
             pipeline="sonar_watch",
@@ -256,6 +304,14 @@ async def _publish_video(
             tmp.unlink(missing_ok=True)
             return None
 
+        out_codec = _ffprobe_video_codec_name(tmp) or "未知"
+        log.info(
+            "[声呐监控] H.264 转码产物已验证 | codec_name={} | {}（{:.2f} MB）",
+            out_codec,
+            tmp.name,
+            tmp.stat().st_size / (1024 * 1024),
+        )
+
         dst = media_root / f"{dst_stem}_{ts}.mp4"
         tmp.replace(dst)
         elapsed = time.monotonic() - t0
@@ -298,7 +354,7 @@ async def run_sonar_video_watch_loop(settings: Settings) -> None:
     extract tail slice → publish.  Each published video gets a unique timestamped
     filename; the GET endpoint always returns the most recent one.
     """
-    global _published_url
+    global _published_url, _last_sonar_skip_logged_path
 
     d = settings.biomass_sonar_video_dir
     if d is None:
@@ -354,7 +410,13 @@ async def run_sonar_video_watch_loop(settings: Settings) -> None:
 
                     if sz > 0 and last_published_key != (rp, sz):
                         ready = await to_thread(_is_ready_to_process, latest)
+                        cycle = logger.bind(pipeline="sonar_watch", source=latest.name)
                         if ready:
+                            cycle.info(
+                                "[声呐监控] 源文件已就绪，进入发布管线 | {:.2f} MB | {}",
+                                sz / (1024 * 1024),
+                                rp,
+                            )
                             published = await _publish_video(
                                 latest, media_root, dst_stem, settings,
                             )
@@ -364,11 +426,31 @@ async def run_sonar_video_watch_loop(settings: Settings) -> None:
                                         settings, published.name,
                                     )
                                 last_published_key = (rp, sz)
+                                _last_sonar_skip_logged_path = None
+                            else:
+                                cycle.warning(
+                                    "[声呐监控] 发布失败（尾段/光流/转码见上方步骤）| {}",
+                                    latest.name,
+                                )
                         else:
-                            logger.bind(pipeline="sonar_watch", source=latest.name).debug(
-                                "[声呐监控] {} 尚未就绪（仍在录制？），等待下一轮",
-                                latest.name,
-                            )
+                            if _last_sonar_skip_logged_path != rp:
+                                _last_sonar_skip_logged_path = rp
+                                cycle.info(
+                                    "[声呐监控] 最新文件尚未可处理（录制中或 MP4/MOV 缺 moov），"
+                                    "等待：{}",
+                                    latest.name,
+                                )
+                            else:
+                                cycle.debug(
+                                    "[声呐监控] 仍在等待就绪：{}",
+                                    latest.name,
+                                )
+
+                else:
+                    logger.bind(pipeline="sonar_watch").debug(
+                        "[声呐监控] 目录中暂无 .mp4/.mkv/.mov：{}",
+                        d,
+                    )
 
         except asyncio.CancelledError:
             raise