diff --git a/abses/conf/absespy.yaml b/abses/conf/absespy.yaml index ebcef5e4..470da720 100644 --- a/abses/conf/absespy.yaml +++ b/abses/conf/absespy.yaml @@ -24,6 +24,9 @@ hydra: level: WARNING formatter: simple stream: ext://sys.stderr + # Disable Hydra's default file handler + # ABSESpy configures root logger to write user module logs to model log files + file: null root: level: INFO handlers: [console] diff --git a/abses/core/experiment.py b/abses/core/experiment.py index 3721abe5..1e2a894a 100644 --- a/abses/core/experiment.py +++ b/abses/core/experiment.py @@ -160,24 +160,56 @@ def __init__( # Setup experiment-level logger (separate from model run loggers) # This ensures experiment-level messages don't mix with model run logs # Pass DictConfig directly, don't convert to dict (log_parser needs DictConfig) + self._logger: Optional[logging.Logger] = None if isinstance(cfg, DictConfig): # Create a copy to avoid modifying original cfg_dict = OmegaConf.to_container(cfg, resolve=True) if isinstance(cfg_dict, dict): cfg_dict["outpath"] = str(self.outpath) # Convert Path to string cfg_copy = OmegaConf.create(cfg_dict) - setup_exp_logger(cfg_copy) + self._logger = setup_exp_logger(cfg_copy) elif isinstance(cfg, dict): # Create a copy to avoid modifying original input cfg_copy = cfg.copy() cfg_copy["outpath"] = str(self.outpath) # Convert Path to string - setup_exp_logger(cfg_copy) + self._logger = setup_exp_logger(cfg_copy) @property def model_cls(self) -> Type[MainModelProtocol]: """Model class.""" return self._manager.model_cls + @property + def name(self) -> str: + """Experiment name from configuration. + + Returns: + Experiment name from exp.name config, or 'experiment' if not set. + """ + exp_cfg = self._cfg.get("exp", {}) + if isinstance(exp_cfg, (dict, DictConfig)): + return exp_cfg.get("name", "experiment") + return "experiment" + + @property + def logger(self) -> logging.Logger: + """Experiment-level logger for recording experiment logs. + + Use this logger to write messages to the experiment log file + (e.g., fire_spread.log) rather than model run logs. + + Example: + exp.logger.info("Experiment started") + exp.logger.debug("Processing parameters...") + + Returns: + The experiment-level logger instance. + """ + if self._logger is None: + # Fallback to getting the logger by name + self._logger = logging.getLogger(EXP_LOGGER_NAME) + return self._logger + @property def cfg(self) -> DictConfig: """Configuration""" @@ -448,7 +480,6 @@ def _log_experiment_info( logger.info(f"Output directory: {self.outpath}") logger.info(f"Logging mode: {logging_mode}") logger.info("=" * 60) - logger.info("") def _batch_run_repeats( self, diff --git a/abses/core/model.py b/abses/core/model.py index de68bfb0..3e7662af 100644 --- a/abses/core/model.py +++ b/abses/core/model.py @@ -143,18 +143,17 @@ def __init__( reports=collector_cfg, tracker=tracker_backend ) + # Setup logging BEFORE initialize() so user logs in initialize() are captured + log_cfg = self.settings.get("log", {}) + if log_cfg: + self._setup_logger(log_cfg) + # Call initialize on model first self.initialize() # Then initialize subsystems self.do_each("_initialize", order=DEFAULT_INIT_ORDER) self.set_state(State.INIT) - # Setup logging if configured - # Check if new log structure exists - log_cfg = self.settings.get("log", {}) - if log_cfg: - self._setup_logger(log_cfg) - @functools.cached_property def name(self) -> str: """Get the model's name. diff --git a/abses/utils/analysis.py b/abses/utils/analysis.py index 5d2789c0..fca8a691 100644 --- a/abses/utils/analysis.py +++ b/abses/utils/analysis.py @@ -188,6 +188,10 @@ def data(self) -> pd.DataFrame: Raises: AttributeError: If data has not been loaded yet. """ + if not hasattr(self, "_data"): + raise AttributeError( + "Data has not been loaded yet. Call read_data() first." + ) return self._data @data.setter diff --git a/abses/utils/exp_logging.py b/abses/utils/exp_logging.py index 00dd4671..e44f8520 100644 --- a/abses/utils/exp_logging.py +++ b/abses/utils/exp_logging.py @@ -103,16 +103,18 @@ def setup_exp_logger( ) or (isinstance(exp_file_cfg_raw, DictConfig) and "name" in exp_file_cfg_raw) exp_file_name = exp_file.get("name", "experiment.log") - if ( - logging_mode == "separate" - and not name_explicitly_set - and exp_file_name == "experiment.log" - ): - # In separate mode, if name not explicitly set, use run.file.name - run_file_cfg = get_file_config(cfg, "run") - if run_file_cfg: - log_name = str(run_file_cfg.get("name", "model")).replace(".log", "") - exp_file_name = f"{log_name}.log" + if not name_explicitly_set and exp_file_name == "experiment.log": + # If name not explicitly set, use exp.name as experiment log file name + if isinstance(cfg, dict): + exp_name = cfg.get("exp", {}).get("name") + else: + try: + exp_name = OmegaConf.select(cfg, "exp.name", default=None) + except Exception: + exp_name = None + + if exp_name: + exp_file_name = f"{exp_name}.log" # Get output path if isinstance(cfg, dict): @@ -143,13 +145,17 @@ def setup_exp_logger( ) logger.addHandler(file_handler) elif logging_mode == "separate": - # In separate mode, if exp.file is not enabled, create experiment log file using run.file.name - run_file_cfg = get_file_config(cfg, "run") - log_name = ( - str(run_file_cfg.get("name", "model")).replace(".log", "") - if run_file_cfg - else "model" - ) + # In separate mode, if exp.file is not enabled, create experiment log file using exp.name + # Get exp.name from config + if isinstance(cfg, dict): + exp_name = cfg.get("exp", {}).get("name") + else: + try: + exp_name = OmegaConf.select(cfg, "exp.name", default=None) + except Exception: + exp_name = None + + log_name = exp_name if exp_name else "experiment" # Get output path if isinstance(cfg, dict): diff --git a/abses/utils/logging.py b/abses/utils/logging.py index 3cc52829..781c0b03 100644 --- a/abses/utils/logging.py +++ b/abses/utils/logging.py @@ -121,6 +121,8 @@ def setup_model_logger( """Setup logging for a model run. Configures ABSESpy and Mesa loggers (both 'mesa' and 'MESA') with integrated handlers. + Also configures the root logger so that user module logs (e.g., logging.getLogger(__name__)) + are written to the same model log file. Args: name: Log file name. @@ -176,6 +178,27 @@ def setup_model_logger( mesa_level=mesa_level, ) + # Configure root logger to use the same handlers as abses_logger + # This ensures user module logs (e.g., logging.getLogger(__name__)) are also captured + root_logger = logging.getLogger() + root_logger.setLevel(level) + + # Remove existing handlers from root logger to avoid duplicates + # But keep Hydra's handlers if any (they handle other logs) + for handler in root_logger.handlers[:]: + # Only remove handlers that are not Hydra's + # Hydra handlers typically have 'hydra' in their name or are configured differently + handler_name = getattr(handler, "name", "") or "" + if "hydra" not in handler_name.lower(): + root_logger.removeHandler(handler) + + # Add the same handlers from abses_logger to root logger + for handler in abses_logger.handlers: + # Create a copy of the handler to avoid sharing state + # For FileHandler, we can share the same file + if handler not in root_logger.handlers: + root_logger.addHandler(handler) + return abses_logger, mesa_logger, mesa_upper_logger diff --git a/docs/api/analysis.md b/docs/api/analysis.md index 5abf2286..1e74c51f 100644 --- a/docs/api/analysis.md +++ b/docs/api/analysis.md @@ -8,3 +8,4 @@ date: 2024-12-20 :::abses.utils.analysis.ExpAnalyzer + diff --git a/examples/fire_spread/config.yaml b/examples/fire_spread/config.yaml index 19c589ab..e37ae618 100644 --- a/examples/fire_spread/config.yaml +++ b/examples/fire_spread/config.yaml @@ -40,6 +40,38 @@ time: end: 100 log: - name: fire_spread - level: INFO - console: false + # Logging mode for repeated runs: once | separate | merge + mode: separate + + # Experiment-level logging (progress, summary, etc.) + exp: + stdout: + enabled: true + level: INFO + format: '[%(asctime)s][%(name)s][%(levelname)s] - %(message)s' + datefmt: '%H:%M:%S' + file: + enabled: true + level: INFO + format: '[%(asctime)s][%(name)s][%(levelname)s] - %(message)s' + datefmt: '%H:%M:%S' + + # Model run-level logging (each model execution) + run: + stdout: + enabled: false + level: INFO + format: '[%(asctime)s][%(name)s][%(levelname)s] - %(message)s' + datefmt: '%H:%M:%S' + file: + enabled: true + level: DEBUG + format: '[%(asctime)s][%(name)s][%(levelname)s] - %(message)s' + datefmt: '%H:%M:%S' + name: model # Log file name (without extension) + rotation: null # e.g., "1 day", "100 MB" + retention: null # e.g., "10 days" + # MESA-specific logging configuration + mesa: + level: null # If null, uses run.file.level + format: null # If null, uses run.file.format diff --git a/examples/fire_spread/model.py b/examples/fire_spread/model.py index 883cba51..0e4d1a6a 100644 --- a/examples/fire_spread/model.py +++ b/examples/fire_spread/model.py @@ -15,6 +15,7 @@ - Batch operations with ActorsList """ +import logging from enum import IntEnum from typing import Optional @@ -23,6 +24,8 @@ from abses import Experiment, MainModel, PatchCell, raster_attribute +logger = logging.getLogger(__name__) + class Tree(PatchCell): """ @@ -70,6 +73,7 @@ def ignite(self) -> None: """Ignite this tree if intact (tree_state transitions from INTACT to BURNING).""" if self._state == self.State.INTACT: self._state = self.State.BURNING + logger.debug(f"Tree at {self.pos} ignited") @property def state(self) -> int: @@ -116,6 +120,7 @@ def initialize(self) -> None: ) # Grow trees on selected patches chosen_patches.shuffle_do("grow") + logger.info(f"Grown {len(chosen_patches)} trees") def setup(self) -> None: """ @@ -174,6 +179,7 @@ def main(cfg: Optional[DictConfig] = None) -> None: """ exp = Experiment(Forest, cfg=cfg) exp.batch_run() + exp.logger.info(f"Experiment {exp.name} started") if __name__ == "__main__": diff --git a/tests/utils/test_logging.py b/tests/utils/test_logging.py index f690e967..a5a7c22b 100644 --- a/tests/utils/test_logging.py +++ b/tests/utils/test_logging.py @@ -49,12 +49,12 @@ class TestLogParser: """测试配置解析功能""" - def test_get_log_mode_default(self): + def test_get_log_mode_default(self) -> None: """测试获取默认日志模式""" cfg = {} assert get_log_mode(cfg) == "once" - def test_get_log_mode_from_config(self): + def test_get_log_mode_from_config(self) -> None: """测试从配置中获取日志模式""" cfg = {"log": {"mode": "separate"}} assert get_log_mode(cfg) == "separate" @@ -62,7 +62,7 @@ def test_get_log_mode_from_config(self): cfg = {"log": {"mode": "merge"}} assert get_log_mode(cfg) == "merge" - def test_get_stdout_config_enabled(self): + def test_get_stdout_config_enabled(self) -> None: """测试获取启用的 stdout 配置""" cfg = { "log": { @@ -82,13 +82,13 @@ def test_get_stdout_config_enabled(self): assert stdout_cfg["format"] == "[%(levelname)s] %(message)s" assert stdout_cfg["datefmt"] == "%Y-%m-%d" - def test_get_stdout_config_disabled(self): + def test_get_stdout_config_disabled(self) -> None: """测试获取禁用的 stdout 配置""" cfg = {"log": {"run": {"stdout": {"enabled": False}}}} stdout_cfg = get_stdout_config(cfg, "run") assert stdout_cfg == {} - def test_get_file_config_enabled(self): + def test_get_file_config_enabled(self) -> None: """测试获取启用的文件配置""" cfg = { "log": { @@ -111,7 +111,7 @@ def test_get_file_config_enabled(self): assert file_cfg["rotation"] == "1 day" assert file_cfg["retention"] == "10 days" - def test_get_file_config_defaults(self): + def test_get_file_config_defaults(self) -> None: """测试文件配置的默认值""" cfg = {"log": {"run": {"file": {"enabled": True}}}} file_cfg = get_file_config(cfg, "run") @@ -120,14 +120,14 @@ def test_get_file_config_defaults(self): assert file_cfg["format"] == DEFAULT_FORMAT assert file_cfg["datefmt"] == DEFAULT_DATEFMT - def test_get_mesa_config(self): + def test_get_mesa_config(self) -> None: """测试获取 Mesa 配置""" cfg = {"log": {"run": {"mesa": {"level": "DEBUG", "format": "%(message)s"}}}} mesa_cfg = get_mesa_config(cfg, "run") assert mesa_cfg["level"] == "DEBUG" assert mesa_cfg["format"] == "%(message)s" - def test_get_mesa_config_defaults(self): + def test_get_mesa_config_defaults(self) -> None: """测试 Mesa 配置的默认值""" cfg = {"log": {"run": {}}} mesa_cfg = get_mesa_config(cfg, "run") @@ -138,13 +138,13 @@ def test_get_mesa_config_defaults(self): class TestLogConfig: """测试日志配置功能""" - def test_create_console_handler_defaults(self): + def test_create_console_handler_defaults(self) -> None: """测试创建控制台处理器（使用默认值）""" handler = create_console_handler() assert handler.level == logging.getLevelName(DEFAULT_LEVEL) assert isinstance(handler, logging.StreamHandler) - def test_create_console_handler_custom(self): + def test_create_console_handler_custom(self) -> None: """测试创建自定义控制台处理器""" handler = create_console_handler( level="DEBUG", fmt="%(message)s", datefmt="%Y-%m-%d" @@ -154,14 +154,14 @@ def test_create_console_handler_custom(self): assert formatter._fmt == "%(message)s" assert formatter.datefmt == "%Y-%m-%d" - def test_create_file_handler_defaults(self, tmp_path): + def test_create_file_handler_defaults(self, tmp_path: Path) -> None: """测试创建文件处理器（使用默认值）""" log_file = tmp_path / "test.log" handler = create_file_handler(log_file) assert handler.level == logging.getLevelName(DEFAULT_LEVEL) assert isinstance(handler, logging.FileHandler) - def test_create_file_handler_custom(self, tmp_path): + def test_create_file_handler_custom(self, tmp_path: Path) -> None: """测试创建自定义文件处理器""" log_file = tmp_path / "test.log" handler = create_file_handler( @@ -172,7 +172,7 @@ def test_create_file_handler_custom(self, tmp_path): assert formatter._fmt == "%(message)s" assert formatter.datefmt == "%Y-%m-%d" - def test_determine_log_file_path_once_mode(self, tmp_path): + def test_determine_log_file_path_once_mode(self, tmp_path: Path) -> None: """测试确定日志文件路径（once 模式）""" # First repeat should create file path = determine_log_file_path( @@ -186,7 +186,7 @@ def test_determine_log_file_path_once_mode(self, tmp_path): ) assert path is None - def test_determine_log_file_path_separate_mode(self, tmp_path): + def test_determine_log_file_path_separate_mode(self, tmp_path: Path) -> None: """测试确定日志文件路径（separate 模式）""" path1 = determine_log_file_path( outpath=tmp_path, log_name="test", logging_mode="separate", repeat_id=1 @@ -198,7 +198,7 @@ def test_determine_log_file_path_separate_mode(self, tmp_path): ) assert path2 == tmp_path / "test_2.log" - def test_determine_log_file_path_merge_mode(self, tmp_path): + def test_determine_log_file_path_merge_mode(self, tmp_path: Path) -> None: """测试确定日志文件路径（merge 模式）""" path1 = determine_log_file_path( outpath=tmp_path, log_name="test", logging_mode="merge", repeat_id=1 @@ -210,7 +210,7 @@ def test_determine_log_file_path_merge_mode(self, tmp_path): ) assert path2 == tmp_path / "test.log" # Same file - def test_setup_abses_logger_console_only(self): + def test_setup_abses_logger_console_only(self) -> None: """测试设置 ABSESpy 日志器（仅控制台）""" logger = setup_abses_logger( name="test_logger", console=True, console_level="DEBUG" @@ -219,7 +219,7 @@ def test_setup_abses_logger_console_only(self): assert len(logger.handlers) == 1 assert isinstance(logger.handlers[0], logging.StreamHandler) - def test_setup_abses_logger_file_only(self, tmp_path): + def test_setup_abses_logger_file_only(self, tmp_path: Path) -> None: """测试设置 ABSESpy 日志器（仅文件）""" log_file = tmp_path / "test.log" logger = setup_abses_logger( @@ -234,7 +234,7 @@ def test_setup_abses_logger_file_only(self, tmp_path): class TestExpLogging: """测试实验日志功能""" - def test_setup_exp_logger_stdout_only(self, tmp_path): + def test_setup_exp_logger_stdout_only(self, tmp_path: Path) -> None: """测试设置实验日志器（仅控制台）""" cfg = OmegaConf.create( { @@ -252,7 +252,7 @@ def test_setup_exp_logger_stdout_only(self, tmp_path): assert len(logger.handlers) == 1 assert isinstance(logger.handlers[0], logging.StreamHandler) - def test_setup_exp_logger_file_only(self, tmp_path): + def test_setup_exp_logger_file_only(self, tmp_path: Path) -> None: """测试设置实验日志器（仅文件）""" cfg = OmegaConf.create( { @@ -280,7 +280,7 @@ def test_setup_exp_logger_file_only(self, tmp_path): assert len(file_handlers) == 1 assert (tmp_path / "experiment.log").exists() - def test_setup_exp_logger_both(self, tmp_path): + def test_setup_exp_logger_both(self, tmp_path: Path) -> None: """测试设置实验日志器（控制台和文件）""" cfg = OmegaConf.create( { @@ -301,11 +301,12 @@ def test_setup_exp_logger_both(self, tmp_path): assert logger.name == EXP_LOGGER_NAME assert len(logger.handlers) == 2 - def test_setup_exp_logger_separate_mode(self, tmp_path): + def test_setup_exp_logger_separate_mode(self, tmp_path: Path) -> None: """测试 separate 模式下的实验日志器""" cfg = OmegaConf.create( { "outpath": str(tmp_path), + "exp": {"name": "test_experiment"}, "log": { "mode": "separate", "run": {"file": {"name": "model"}}, @@ -314,14 +315,14 @@ def test_setup_exp_logger_separate_mode(self, tmp_path): } ) _ = setup_exp_logger(cfg) # Setup logger - # In separate mode, exp log should use run.file.name if not explicitly set - assert (tmp_path / "model.log").exists() + # In separate mode, exp log should use exp.name if not explicitly set + assert (tmp_path / "test_experiment.log").exists() class TestModelLogging: """测试模型日志功能""" - def test_setup_model_logger_console_only(self, tmp_path): + def test_setup_model_logger_console_only(self, tmp_path: Path) -> None: """测试设置模型日志器（仅控制台）""" logger, mesa_logger, mesa_upper_logger = setup_model_logger( name="test_model", @@ -335,7 +336,7 @@ def test_setup_model_logger_console_only(self, tmp_path): assert len(logger.handlers) == 1 assert isinstance(logger.handlers[0], logging.StreamHandler) - def test_setup_model_logger_file_only(self, tmp_path): + def test_setup_model_logger_file_only(self, tmp_path: Path) -> None: """测试设置模型日志器（仅文件）""" logger, mesa_logger, mesa_upper_logger = setup_model_logger( name="test_model", @@ -350,7 +351,7 @@ def test_setup_model_logger_file_only(self, tmp_path): assert isinstance(logger.handlers[0], logging.FileHandler) assert (tmp_path / "test_model.log").exists() - def test_setup_model_logger_custom_format(self, tmp_path): + def test_setup_model_logger_custom_format(self, tmp_path: Path) -> None: """测试设置模型日志器（自定义格式）""" logger, mesa_logger, mesa_upper_logger = setup_model_logger( name="test_model", @@ -386,12 +387,12 @@ class TestLoggingIntegration: """测试日志功能的集成测试""" @pytest.fixture - def temp_dir(self): + def temp_dir(self) -> Path: """创建临时目录""" with tempfile.TemporaryDirectory() as tmpdir: yield Path(tmpdir) - def test_experiment_logging_integration(self, temp_dir): + def test_experiment_logging_integration(self, temp_dir: Path) -> None: """测试实验日志的完整流程""" cfg = OmegaConf.create( { @@ -442,7 +443,7 @@ def test_experiment_logging_integration(self, temp_dir): handler.close() exp_logger.removeHandler(handler) - def test_model_logging_integration(self, temp_dir): + def test_model_logging_integration(self, temp_dir: Path) -> None: """测试模型日志的完整流程""" _ = { "outpath": str(temp_dir), @@ -480,7 +481,7 @@ def test_model_logging_integration(self, temp_dir): handler.close() log.removeHandler(handler) - def test_logging_modes(self, temp_dir): + def test_logging_modes(self, temp_dir: Path) -> None: """测试不同的日志模式""" # Test once mode path1 = determine_log_file_path( @@ -512,7 +513,7 @@ def test_logging_modes(self, temp_dir): assert path1 == temp_dir / "model.log" assert path2 == temp_dir / "model.log" - def test_experiment_with_logging(self, temp_dir): + def test_experiment_with_logging(self, temp_dir: Path) -> None: """测试实验运行时的日志功能""" # Clean ExperimentManager singleton to avoid conflicts with other tests from abses.core.job_manager import ExperimentManager @@ -574,3 +575,43 @@ def step(self): log.removeHandler(handler) # Restore the original instance ExperimentManager._instance = original_instance + + def test_user_module_logger_writes_to_model_log(self, temp_dir: Path) -> None: + """测试用户模块的 logger 是否写入模型日志文件""" + # Setup model logger + logger, mesa_logger, mesa_upper_logger = setup_model_logger( + name="model", + level="INFO", + outpath=temp_dir, + console=False, + logging_mode="once", + repeat_id=1, + ) + + try: + # Create a user module logger (simulating logging.getLogger(__name__)) + user_logger = logging.getLogger("my_custom_module") + user_logger.info("User module log message") + + # Read the log file and verify the message is present + log_file = temp_dir / "model.log" + assert log_file.exists(), f"Log file not found at {log_file}" + + log_content = log_file.read_text() + assert "User module log message" in log_content, ( + f"User module log not found in model.log. Content: {log_content}" + ) + assert "my_custom_module" in log_content, ( + f"Logger name not found in model.log. Content: {log_content}" + ) + finally: + # Close all handlers to release file handles (required on Windows) + for log in [logger, mesa_logger, mesa_upper_logger]: + for handler in log.handlers[:]: + handler.close() + log.removeHandler(handler) + # Also clean root logger handlers + root_logger = logging.getLogger() + for handler in root_logger.handlers[:]: + handler.close() + root_logger.removeHandler(handler)