use precise exception log info

joyguoguo · joyguoguo · commit 15a7095da456 · 2025-07-22T18:57:47.000Z
diff --git a/fuzz/run_fuzz_target.py b/fuzz/run_fuzz_target.py
@@ -4,7 +4,7 @@
 """
 run_fuzz_target.py
 
-Run OSS-Fuzz test targets in parallel with enhanced logging.
+Run OSS-Fuzz test targets in parallel with enhanced logging and precise exception handling.
 Uses multiprocessing.Pool and logging module for robust task management.
 
 Usage: python3 run_fuzz_target.py [project_list_file] [--timeout seconds] [--workers N]
@@ -16,6 +16,8 @@
 import subprocess
 import argparse
 import logging
+import time
+import shutil
 from datetime import datetime
 from pathlib import Path
 from typing import List, Optional, Tuple
@@ -28,53 +30,60 @@
 
 def setup_logging(project_name: str) -> logging.Logger:
     """Configure hierarchical logger with file and console handlers"""
-    LOG_DIR.mkdir(parents=True, exist_ok=True)
-    timestamp = datetime.now().strftime("%Y%m%d%H%M%S")
-    log_file = LOG_DIR / f"run_{project_name}_{timestamp}.log"
-    
-    # Create process-specific logger
-    logger = logging.getLogger(f"{project_name}.{current_process().name}")
-    logger.setLevel(logging.DEBUG)
-    
-    # File handler (all levels)
-    file_handler = logging.FileHandler(log_file, encoding="utf-8")
-    file_handler.setLevel(logging.DEBUG)
-    file_formatter = logging.Formatter(
-        "%(asctime)s [PID:%(process)d] %(levelname)s: %(message)s",
-        datefmt="%Y-%m-%d %H:%M:%S"
-    )
-    file_handler.setFormatter(file_formatter)
-    
-    # Console handler (INFO+ only)
-    console_handler = logging.StreamHandler()
-    console_handler.setLevel(logging.INFO)
-    console_formatter = logging.Formatter(
-        "[%(levelname)s] %(message)s"
-    )
-    console_handler.setFormatter(console_formatter)
-    
-    logger.addHandler(file_handler)
-    logger.addHandler(console_handler)
-    
-    # Capture uncaught exceptions
-    sys.excepthook = lambda exc_type, exc_value, exc_traceback: (
-        logger.critical("Unhandled exception", exc_info=(exc_type, exc_value, exc_traceback))
-    )
-    
-    return logger
+    try:
+        LOG_DIR.mkdir(parents=True, exist_ok=True)
+        timestamp = datetime.now().strftime("%Y%m%d%H%M%S")
+        log_file = LOG_DIR / f"run_{project_name}_{timestamp}.log"
+        
+        # Create process-specific logger
+        logger = logging.getLogger(f"{project_name}.{current_process().name}")
+        logger.setLevel(logging.DEBUG)
+        
+        # File handler (all levels)
+        file_handler = logging.FileHandler(log_file, encoding="utf-8")
+        file_handler.setLevel(logging.DEBUG)
+        file_formatter = logging.Formatter(
+            "%(asctime)s [PID:%(process)d] %(levelname)s: %(message)s",
+            datefmt="%Y-%m-%d %H:%M:%S"
+        )
+        file_handler.setFormatter(file_formatter)
+        
+        # Console handler (INFO+ only)
+        console_handler = logging.StreamHandler()
+        console_handler.setLevel(logging.INFO)
+        console_formatter = logging.Formatter(
+            "[%(levelname)s] %(message)s"
+        )
+        console_handler.setFormatter(console_formatter)
+        
+        logger.addHandler(file_handler)
+        logger.addHandler(console_handler)
+        
+        # Capture uncaught exceptions
+        sys.excepthook = lambda exc_type, exc_value, exc_traceback: (
+            logger.critical("Unhandled exception", exc_info=(exc_type, exc_value, exc_traceback))
+        )
+        
+        return logger
+    except (PermissionError, OSError) as e:
+        print(f"❌ Critical logging setup error: {e}")
+        sys.exit(1)
 
 def run_command(
     cmd: str, 
     log_msg: str, 
     logger: logging.Logger,
-    allowed_exit_codes: Optional[List[int]] = None
+    allowed_exit_codes: Optional[List[int]] = None,
+    timeout: int = 3600  # 1 hour default timeout
 ) -> bool:
-    """Execute command with real-time logging"""
+    """Execute command with real-time logging and precise error handling"""
     allowed_exit_codes = allowed_exit_codes or []
     logger.info(f"▶️ {log_msg}...")
     logger.debug(f"   $ {cmd}")
 
+    process = None
     try:
+        # Start process with explicit timeout handling
         process = subprocess.Popen(
             cmd,
             shell=True,
@@ -85,68 +94,124 @@ def run_command(
             errors="replace"
         )
         
-        # Stream output to logger
-        if process.stdout:
-            for line in iter(process.stdout.readline, ""):
-                logger.debug(line.strip())
-        else:
-            logger.warning("Process stdout is None")
-            
-        process.wait()
+        # Stream output to logger with timeout control
+        start_time = time.time()
+        while process.poll() is None:
+            if time.time() - start_time > timeout:
+                logger.error(f"⌛ Command timed out after {timeout} seconds")
+                process.terminate()
+                try:
+                    process.wait(timeout=5)
+                except subprocess.TimeoutExpired:
+                    process.kill()
+                return False
+                
+            # Read available output
+            if process.stdout:
+                line = process.stdout.readline()
+                if line:
+                    logger.debug(line.strip())
+            else:
+                logger.warning("Process stdout is None")
+                time.sleep(0.1)
         
-        if process.returncode not in [0, *allowed_exit_codes]:
-            logger.error(f"Command failed with exit code: {process.returncode}")
+        # Check exit code
+        exit_code = process.returncode
+        if exit_code not in [0, *allowed_exit_codes]:
+            logger.error(f"❌ Command failed with exit code: {exit_code}")
             return False
         return True
-    except Exception as e:
-        logger.exception(f"💥 Execution exception: {e}")
+        
+    except FileNotFoundError as e:
+        logger.error(f"🔍 Command not found: {cmd.split()[0]}")
         return False
+    except PermissionError as e:
+        logger.error(f"🔒 Permission denied for command: {cmd}")
+        return False
+    except subprocess.SubprocessError as e:
+        logger.exception(f"💥 Subprocess error: {e}")
+        return False
+    except OSError as e:
+        logger.exception(f"💥 OS error during command execution: {e}")
+        return False
+    finally:
+        # Ensure process is cleaned up
+        if process and process.poll() is None:
+            try:
+                process.terminate()
+                process.wait(timeout=5)
+            except:
+                pass
 
 def discover_targets(project_name: str, logger: logging.Logger) -> List[str]:
-    """Discover available Fuzz targets with error handling"""
+    """Discover available Fuzz targets with precise error handling"""
     out_dir = OSS_FUZZ_DIR / "build" / "out" / project_name
     targets = []
+    
     try:
-        if out_dir.exists():
-            for f in out_dir.iterdir():
+        if not out_dir.exists():
+            logger.warning(f"⚠️ Build directory not found: {out_dir}")
+            return targets
+            
+        for f in out_dir.iterdir():
+            try:
                 if f.is_file() and f.name.startswith("fuzz_") and os.access(f, os.X_OK):
                     targets.append(f.name)
-        else:
-            logger.warning(f"Build directory not found: {out_dir}")
-    except Exception as e:
-        logger.exception(f"Target discovery failed: {e}")
+            except OSError as e:
+                logger.warning(f"⚠️ Skipping file {f.name} due to access error: {e}")
+                
+    except FileNotFoundError:
+        logger.error(f"❌ Directory not found: {out_dir}")
+    except PermissionError:
+        logger.error(f"🔒 Permission denied accessing: {out_dir}")
+    except OSError as e:
+        logger.exception(f"💥 OS error during target discovery: {e}")
+    
     return targets
 
 def run_project(project_name: str, timeout: int) -> Tuple[bool, str]:
-    """Testing workflow for a single project with logging"""
-    logger = setup_logging(project_name)
-    os.chdir(OSS_FUZZ_DIR)
+    """Testing workflow for a single project with precise error handling"""
+    try:
+        logger = setup_logging(project_name)
+        os.chdir(OSS_FUZZ_DIR)
+    except (OSError, PermissionError) as e:
+        print(f"❌ Critical error initializing project {project_name}: {e}")
+        return (False, project_name)
     
     logger.info("=" * 60)
     logger.info(f"🚀 Starting testing for project: {project_name}")
     logger.debug(f"📝 Log path: {[h.baseFilename for h in logger.handlers if isinstance(h, logging.FileHandler)]}")
     logger.info("=" * 60)
     
     # 1. Discover test targets
-    targets = discover_targets(project_name, logger)
-    if not targets:
-        logger.error("⚠️ No test targets found")
+    try:
+        targets = discover_targets(project_name, logger)
+        if not targets:
+            logger.error("⚠️ No test targets found")
+            return (False, project_name)
+        logger.info(f"🔍 Discovered {len(targets)} test targets: {', '.join(targets)}")
+    except Exception as e:
+        logger.exception(f"💥 Target discovery failed unexpectedly: {e}")
         return (False, project_name)
-    logger.info(f"🔍 Discovered {len(targets)} test targets: {', '.join(targets)}")
     
     # 2. Run all targets
     all_success = True
     for i, target in enumerate(targets, 1):
-        cmd = f"python3 infra/helper.py run_fuzzer {project_name} {target} -- -max_total_time={timeout}"
-        success = run_command(
-            cmd,
-            f"Running target [{i}/{len(targets)}] {target} (timeout={timeout}s)",
-            logger,
-            allowed_exit_codes=[1, 124]  # Allow timeout exit codes
-        )
-        all_success &= success
-        if not success:
-            logger.error(f"❌ Target failed: {target}")
+        try:
+            cmd = f"python3 infra/helper.py run_fuzzer {project_name} {target} -- -max_total_time={timeout}"
+            success = run_command(
+                cmd,
+                f"Running target [{i}/{len(targets)}] {target} (timeout={timeout}s)",
+                logger,
+                allowed_exit_codes=[1, 124],  # Allow timeout exit codes
+                timeout=timeout + 300  # Add buffer for setup/teardown
+            )
+            all_success &= success
+            if not success:
+                logger.error(f"❌ Target failed: {target}")
+        except Exception as e:
+            logger.exception(f"💥 Unexpected error running target {target}: {e}")
+            all_success = False
     
     # 3. Final status
     if all_success:
@@ -172,24 +237,63 @@ def main():
     
     logger.info(f"🚀 Starting parallel fuzzing (workers={args.workers}, timeout={args.timeout}s)")
 
-    # Read project list
+    # Read project list with precise error handling
     try:
-        with open(args.project_list) as f:
+        project_path = Path(args.project_list)
+        if not project_path.exists():
+            raise FileNotFoundError(f"Project list file not found: {project_path}")
+            
+        if not project_path.is_file():
+            raise ValueError(f"Path is not a file: {project_path}")
+            
+        with open(project_path, "r") as f:
             projects = [line.strip() for line in f if line.strip()]
-        logger.info(f"📋 Loaded {len(projects)} projects from {args.project_list}")
-    except Exception as e:
-        logger.exception(f"❌ Failed to read project list: {e}")
+            
+        logger.info(f"📋 Loaded {len(projects)} projects from {project_path}")
+    except FileNotFoundError as e:
+        logger.error(f"❌ {e}")
+        sys.exit(1)
+    except PermissionError as e:
+        logger.error(f"🔒 Permission denied: {e}")
+        sys.exit(1)
+    except (OSError, ValueError) as e:
+        logger.exception(f"💥 Error reading project list: {e}")
         sys.exit(1)
 
-    # Parallel execution
+    # Parallel execution with error isolation
     with Pool(args.workers) as pool:
-        results = pool.starmap(run_project, [(p, args.timeout) for p in projects])
+        results = []
+        for p in projects:
+            try:
+                results.append(pool.apply_async(run_project, (p, args.timeout)))
+            except Exception as e:
+                logger.error(f"💥 Failed to schedule project {p}: {e}")
+                results.append((False, p))
+        
+        # Collect results with timeout
+        final_results = []
+        for res in results:
+            try:
+                final_results.append(res.get(timeout=args.timeout * 2))
+            except TimeoutError:
+                logger.error("⌛ Project execution timed out")
+                final_results.append((False, "unknown"))
+            except Exception as e:
+                logger.error(f"💥 Error collecting result: {e}")
+                final_results.append((False, "unknown"))
 
     # Output results
-    failed = [p for success, p in results if not success]
+    failed = [p for success, p in final_results if not success]
     logger.info(f"\n📊 Testing completed: Success {len(projects)-len(failed)}/{len(projects)}")
     if failed:
         logger.error("❌ Failed projects: " + ", ".join(failed))
 
 if __name__ == "__main__":
-    main()
+    try:
+        main()
+    except KeyboardInterrupt:
+        print("\n🛑 Operation cancelled by user")
+        sys.exit(1)
+    except Exception as e:
+        print(f"💥 Critical error in main: {e}")
+        sys.exit(1)
