Repository: projectmesa/mesa
Pull request #2506 (2024-11-13 20:13:21)

Add logging to MESA
This PR adds support for logging to MESA using the standard library logging module. It adds a new `mesa_logging` module with a couple of helper functions, and two decorators (one for adding logging to functions, and another for adding logging to methods). 

Its use is illustrated in `solara_viz` and `model`, and the boltzman wealth example shows it use.

Current log output in stderr:

```console
[2024-11-23 17:51:35,422] [MESA.mesa.model] [DEBUG] registered MoneyAgent with agent_id 45 [model.py:173]
[2024-11-23 17:51:35,422] [MESA.mesa.model] [DEBUG] registered MoneyAgent with agent_id 46 [model.py:173]
[2024-11-23 17:51:35,422] [MESA.mesa.model] [DEBUG] registered MoneyAgent with agent_id 47 [model.py:173]
[2024-11-23 17:51:35,422] [MESA.mesa.model] [DEBUG] registered MoneyAgent with agent_id 48 [model.py:173]
[2024-11-23 17:51:35,422] [MESA.mesa.model] [DEBUG] registered MoneyAgent with agent_id 49 [model.py:173]
[2024-11-23 17:51:35,422] [MESA.mesa.model] [DEBUG] registered MoneyAgent with agent_id 50 [model.py:173]
[2024-11-23 17:51:36,512] [MESA.mesa.visualization.solara_viz] [DEBUG] calling SolaraViz with (<mesa.examples.basic.boltzmann_wealth_model.model.BoltzmannWealth object at 0x15da10290>,) and {'components': [<function make_mpl_space_component.<locals>.MakeSpaceMatplotlib at 0x15dc32480>, <function make_mpl_plot_component.<locals>.MakePlotMatplotlib at 0x15dc32c00>], 'model_params': {'seed': {'type': 'InputText', 'value': 42, 'label': 'Random Seed'}, 'n': {'type': 'SliderInt', 'value': 50, 'label': 'Number of agents:', 'min': 10, 'max': 100, 'step': 1}, 'width': 10, 'height': 10}, 'name': 'Boltzmann Wealth Model'} [mesa_logging.py:131]
[2024-11-23 17:51:42,215] [MESA.mesa.visualization.solara_viz] [DEBUG] calling do_step with () and {} [mesa_logging.py:131]
[2024-11-23 17:51:42,215] [MESA.mesa.model] [INFO] calling model.step for timestep 1  [model.py:120]
[2024-11-23 17:51:42,865] [MESA.mesa.visualization.solara_viz] [DEBUG] calling do_step with () and {} [mesa_logging.py:131]
[2024-11-23 17:51:42,865] [MESA.mesa.model] [INFO] calling model.step for timestep 2  [model.py:120]
[2024-11-23 17:51:43,523] [MESA.mesa.visualization.solara_viz] [DEBUG] calling do_step with () and {} [mesa_logging.py:131]
[2024-11-23 17:51:43,524] [MESA.mesa.model] [INFO] calling model.step for timestep 3  [model.py:120]
```

feedback welcome.

I will add

- [x] - include the arguments/keyword arguments for model initialization
- [x] - add the steps counter so you know at which step you are
- [x] - add the unique_id of the agent registering. 


github-actions[bot]: Performance benchmarks:

| Model           | Size   | Init time [95% CI]         | Run time [95% CI]       |
|-----------------|--------|----------------------------|-------------------------|
| BoltzmannWealth | small  | 🔴 +16.5% [+15.0%, +18.3%] | 🔵 -0.7% [-0.8%, -0.5%] |
| BoltzmannWealth | large  | 🔴 +18.3% [+17.7%, +18.9%] | 🔵 -1.8% [-3.8%, +0.0%] |
| Schelling       | small  | 🔴 +18.3% [+18.1%, +18.6%] | 🔵 -0.8% [-1.1%, -0.6%] |
| Schelling       | large  | 🔴 +19.0% [+18.5%, +19.6%] | 🔵 -0.6% [-1.3%, +0.1%] |
| WolfSheep       | small  | 🔴 +13.5% [+13.2%, +13.8%] | 🔵 +3.0% [+2.8%, +3.1%] |
| WolfSheep       | large  | 🔴 +14.0% [+13.1%, +15.0%] | 🔵 +3.5% [+2.0%, +5.0%] |
| BoidFlockers    | small  | 🔴 +8.1% [+7.6%, +8.6%]    | 🔵 +0.1% [-0.6%, +0.8%] |
| BoidFlockers    | large  | 🔴 +7.4% [+6.8%, +8.0%]    | 🔵 -0.4% [-1.1%, +0.0%] |

Corvince: Honestly, I have very minimal knowledge about python logging best practices and not the time currently to investigate in it. Thus, I don't feel qualified to do a code review of this PR. But I still would like to have this included! I don't know how other maintainers feel about this, but since this PR is strictly add-on and should not break any existing features and you have a proven track-record of excellent code quality I am fine with approving this PR anytime you think its ready @quaquel. If there is some specific code you want me/someone else to look at, just say so.

The only question I have right now is that mesa_logging seems to do some basic generic stuff not related to mesa at all. While its great to have full control, its also something we need to maintain. Aren't there some logging libraries for these kind of things? 
quaquel: 
> Honestly, I have very minimal knowledge about python logging best practices and not the time currently to investigate in it. Thus, I don't feel qualified to do a code review of this PR. But I still would like to have this included! I don't know how other maintainers feel about this, but since this PR is strictly add-on and should not break any existing features and you have a proven track-record of excellent code quality I am fine with approving this PR anytime you think its ready @quaquel. If there is some specific code you want me/someone else to look at, just say so.

Thanks!


> The only question I have right now is that mesa_logging seems to do some basic generic stuff not related to mesa at all. While its great to have full control, its also something we need to maintain. Aren't there some logging libraries for these kind of things?

This is a good question. I have allways just used the logging library that ships with stdlib, but never bothered to look at other solutions. The built-in logging library has been part of python since 2002 and its API has not really changed (as reflected by its camelcase notation). It was heavily modelled on log4j and `java.util.loggin`. Since I came from java to python, it was easy to get up and running. 

There are various good overview pages of logging libraries. [This one](https://betterstack.com/community/guides/logging/best-python-logging-libraries/), for example is quite recent and covers some interesting libraries. My impression based on this and other posts is that everyone acknowledges the importance and value of the built-in logging library. It is feature complete, but requires some boilerplate code (as you point out), and lacks modern logging features. You can add these yourself and there are add on libraries that add features (e.g., for structured logging using json). Another popular option is [logoru](https://github.com/Delgan/loguru). Based on the docs and playing with it a bit, it offers a more modern and pythonic API as well as nice features like pretty printing, built-in support for logging from multiple processes (relevant for batchrunning). Another notable library in beta is [picologging](https://github.com/microsoft/picologging). This is a drop-in replacement for stdlib logging, developed by microsoft with the aim of being an order of magnitude faster. The fact that microsoft choses to abide by the API of the built-in logging library speaks to the status of the built in logging library. 

I am currently inklined to stick with the built in logging functionality. This avoids adding new dependencies. The API is rock-solid and has not changed since Python 2.2 or so. So maintance on our end is largely a non-issue once our boilerplate code is final and covered by tests. We can even play with picologging is we think we need the speed-up. Moreover, I am quite familiar with this library already. However, if there are features that you or any of the other maintainers would like to have in the logging that are well served by loguru, I am happy to take a closer look at that instead.
quaquel: This is ready for a last check and approval. I have added a `ColorFormatter` so logging to stderr results in color-coded messages to easily spot warnings and errors. I also slightly refined the logging of agent registration. A debug log message is created indicating the class and unique_id of each agent that is added or removed from the model. Last, for each step, an info-level log message is created indicating the timestep. 
tpike3: @quaquel can you please rebase to main and feel free to merge. 
EwoutH: (there are current no conflicts with main, so that shouldn’t be strictly necessary. only fast-forward merge requires a rebase, squashing doesn’t)

Patch:
diff --git a/docs/apis/api_main.md b/docs/apis/api_main.md
index 61b29f13..6a3ef810 100644
--- a/docs/apis/api_main.md
+++ b/docs/apis/api_main.md
@@ -10,5 +10,6 @@ space
 datacollection
 batchrunner
 visualization
+logging
 experimental
 ```
diff --git a/docs/apis/mesa_logging.md b/docs/apis/mesa_logging.md
new file mode 100644
index 00000000..d934e0c7
--- /dev/null
+++ b/docs/apis/mesa_logging.md
@@ -0,0 +1,7 @@
+# logging
+
+```{eval-rst}
+.. automodule:: mesa.mesa_logging
+   :members:
+   :inherited-members:
+```
diff --git a/mesa/examples/basic/boltzmann_wealth_model/app.py b/mesa/examples/basic/boltzmann_wealth_model/app.py
index b86c4b87..bc596ce9 100644
--- a/mesa/examples/basic/boltzmann_wealth_model/app.py
+++ b/mesa/examples/basic/boltzmann_wealth_model/app.py
@@ -1,10 +1,13 @@
 from mesa.examples.basic.boltzmann_wealth_model.model import BoltzmannWealth
+from mesa.mesa_logging import DEBUG, log_to_stderr
 from mesa.visualization import (
     SolaraViz,
     make_plot_component,
     make_space_component,
 )
 
+log_to_stderr(DEBUG)
+
 
 def agent_portrayal(agent):
     color = agent.wealth  # we are using a colormap to translate wealth to color
diff --git a/mesa/mesa_logging.py b/mesa/mesa_logging.py
new file mode 100644
index 00000000..03c11436
--- /dev/null
+++ b/mesa/mesa_logging.py
@@ -0,0 +1,190 @@
+"""This provides logging functionality for MESA.
+
+It is modeled on the default `logging approach that comes with Python <https://docs.python.org/library/logging.html>`_.
+
+
+"""
+
+import inspect
+import logging
+from functools import wraps
+from logging import DEBUG, INFO
+
+__all__ = [
+    "get_rootlogger",
+    "get_module_logger",
+    "log_to_stderr",
+    "DEBUG",
+    "INFO",
+    "DEFAULT_LEVEL",
+    "LOGGER_NAME",
+    "method_logger",
+    "function_logger",
+]
+LOGGER_NAME = "MESA"
+DEFAULT_LEVEL = DEBUG
+
+
+def create_module_logger(name: str | None = None):
+    """Helper function for creating a module logger.
+
+    Args:
+        name (str): The name to be given to the logger. If the name is None, the name defaults to the name of the module.
+
+    """
+    if name is None:
+        frm = inspect.stack()[1]
+        mod = inspect.getmodule(frm[0])
+        name = mod.__name__
+    logger = logging.getLogger(f"{LOGGER_NAME}.{name}")
+
+    _module_loggers[name] = logger
+    return logger
+
+
+def get_module_logger(name: str):
+    """Helper function for getting the module logger.
+
+    Args:
+        name (str): The name of the module in which the method being decorated is located
+
+    """
+    try:
+        logger = _module_loggers[name]
+    except KeyError:
+        logger = create_module_logger(name)
+
+    return logger
+
+
+_rootlogger = None
+_module_loggers = {}
+_logger = get_module_logger(__name__)
+
+
+class MESAColorFormatter(logging.Formatter):
+    """Custom formatter for color based formatting."""
+
+    grey = "\x1b[38;20m"
+    green = "\x1b[32m"
+    yellow = "\x1b[33;20m"
+    red = "\x1b[31;20m"
+    bold_red = "\x1b[31;1m"
+    reset = "\x1b[0m"
+    format = (
+        "[%(asctime)s] [%(name)s] [%(levelname)s] %(message)s [%(filename)s:%(lineno)d]"
+    )
+
+    FORMATS = {
+        logging.DEBUG: grey + format + reset,
+        logging.INFO: green + format + reset,
+        logging.WARNING: yellow + format + reset,
+        logging.ERROR: red + format + reset,
+        logging.CRITICAL: bold_red + format + reset,
+    }
+
+    def format(self, record):
+        """Format record."""
+        log_fmt = self.FORMATS.get(record.levelno)
+        formatter = logging.Formatter(log_fmt)
+        return formatter.format(record)
+
+
+def method_logger(name: str):
+    """Decorator for adding logging to a method.
+
+    Args:
+        name (str): The name of the module in which the method being decorated is located
+
+    """
+    logger = get_module_logger(name)
+    classname = inspect.getouterframes(inspect.currentframe())[1][3]
+
+    def real_decorator(func):
+        @wraps(func)
+        def wrapper(*args, **kwargs):
+            # hack, because log is applied to methods, we can get
+            # object instance as first arguments in args
+            logger.debug(
+                f"calling {classname}.{func.__name__} with {args[1::]} and {kwargs}"
+            )
+            res = func(*args, **kwargs)
+            return res
+
+        return wrapper
+
+    return real_decorator
+
+
+def function_logger(name):
+    """Decorator for adding logging to a Function.
+
+    Args:
+        name (str): The name of the module in which the function being decorated is located
+
+    """
+    logger = get_module_logger(name)
+
+    def real_decorator(func):
+        @wraps(func)
+        def wrapper(*args, **kwargs):
+            logger.debug(f"calling {func.__name__} with {args} and {kwargs}")
+            res = func(*args, **kwargs)
+            return res
+
+        return wrapper
+
+    return real_decorator
+
+
+def get_rootlogger():
+    """Returns root logger used by MESA.
+
+    Returns:
+        the root logger of MESA
+
+    """
+    global _rootlogger  # noqa: PLW0603
+
+    if not _rootlogger:
+        _rootlogger = logging.getLogger(LOGGER_NAME)
+        _rootlogger.handlers = []
+        _rootlogger.addHandler(logging.NullHandler())
+        _rootlogger.setLevel(DEBUG)
+
+    return _rootlogger
+
+
+def log_to_stderr(level: int | None = None, pass_root_logger_level: bool = False):
+    """Turn on logging and add a handler which prints to stderr.
+
+    Args:
+        level: minimum level of the messages that will be logged
+        pass_root_logger_level: bool, optional. Default False
+                if True, all module loggers will be set to the same logging level as the root logger.
+
+    """
+    if not level:
+        level = DEFAULT_LEVEL
+
+    logger = get_rootlogger()
+
+    # avoid creation of multiple stream handlers for logging to console
+    for entry in logger.handlers:
+        if (isinstance(entry, logging.StreamHandler)) and (
+            isinstance(entry.formatter, MESAColorFormatter)
+        ):
+            return logger
+
+    formatter = MESAColorFormatter()
+    handler = logging.StreamHandler()
+    handler.setLevel(level)
+    handler.setFormatter(formatter)
+    logger.addHandler(handler)
+    logger.propagate = False
+
+    if pass_root_logger_level:
+        for _, mod_logger in _module_loggers.items():
+            mod_logger.setLevel(level)
+
+    return logger
diff --git a/mesa/model.py b/mesa/model.py
index 5d638a01..8263926a 100644
--- a/mesa/model.py
+++ b/mesa/model.py
@@ -17,11 +17,15 @@ from typing import Any
 import numpy as np
 
 from mesa.agent import Agent, AgentSet
+from mesa.mesa_logging import create_module_logger, method_logger
 
 SeedLike = int | np.integer | Sequence[int] | np.random.SeedSequence
 RNGLike = np.random.Generator | np.random.BitGenerator
 
 
+_mesa_logger = create_module_logger()
+
+
 class Model:
     """Base class for models in the Mesa ABM library.
 
@@ -42,6 +46,7 @@ class Model:
 
     """
 
+    @method_logger(__name__)
     def __init__(
         self,
         *args: Any,
@@ -112,6 +117,7 @@ class Model:
         """Automatically increments time and steps after calling the user's step method."""
         # Automatically increment time and step counters
         self.steps += 1
+        _mesa_logger.info(f"calling model.step for timestep {self.steps} ")
         # Call the original user-defined step method
         self._user_step(*args, **kwargs)
 
@@ -164,6 +170,9 @@ class Model:
             )
 
         self._all_agents.add(agent)
+        _mesa_logger.debug(
+            f"registered {agent.__class__.__name__} with agent_id {agent.unique_id}"
+        )
 
     def deregister_agent(self, agent):
         """Deregister the agent with the model.
@@ -178,6 +187,7 @@ class Model:
         del self._agents[agent]
         self._agents_by_type[type(agent)].remove(agent)
         self._all_agents.remove(agent)
+        _mesa_logger.debug(f"deregistered agent with agent_id {agent.unique_id}")
 
     def run_model(self) -> None:
         """Run the model until the end condition is reached.
diff --git a/mesa/visualization/solara_viz.py b/mesa/visualization/solara_viz.py
index 1f3c8036..294dab34 100644
--- a/mesa/visualization/solara_viz.py
+++ b/mesa/visualization/solara_viz.py
@@ -33,14 +33,18 @@ import solara
 
 import mesa.visualization.components.altair_components as components_altair
 from mesa.experimental.devs.simulator import Simulator
+from mesa.mesa_logging import create_module_logger, function_logger
 from mesa.visualization.user_param import Slider
 from mesa.visualization.utils import force_update, update_counter
 
 if TYPE_CHECKING:
     from mesa.model import Model
 
+_mesa_logger = create_module_logger()
+
 
 @solara.component
+@function_logger(__name__)
 def SolaraViz(
     model: Model | solara.Reactive[Model],
     components: list[reacton.core.Component]
@@ -200,18 +204,25 @@ def ModelController(
         step, dependencies=[playing.value, running.value], prefer_threaded=False
     )
 
+    @function_logger(__name__)
     def do_step():
         """Advance the model by one step."""
         model.value.step()
         running.value = model.value.running
         force_update()
 
+    @function_logger(__name__)
     def do_reset():
         """Reset the model to its initial state."""
         playing.value = False
         running.value = True
+        _mesa_logger.log(
+            10,
+            f"creating new {model.value.__class__} instance with {model_parameters.value}",
+        )
         model.value = model.value = model.value.__class__(**model_parameters.value)
 
+    @function_logger(__name__)
     def do_play_pause():
         """Toggle play/pause."""
         playing.value = not playing.value
@@ -394,6 +405,7 @@ def ModelCreator(
         [],
     )
 
+    @function_logger(__name__)
     def on_change(name, value):
         model_parameters.value = {**model_parameters.value, name: value}
 


Test patch:
diff --git a/tests/test_mesa_logging.py b/tests/test_mesa_logging.py
new file mode 100644
index 00000000..f4609608
--- /dev/null
+++ b/tests/test_mesa_logging.py
@@ -0,0 +1,47 @@
+"""Unit tests for mesa_logging."""
+
+import logging
+
+import pytest
+
+from mesa import mesa_logging
+
+
+@pytest.fixture
+def tear_down():
+    """Pytest fixture to ensure all logging is disabled after testing."""
+    yield None
+    mesa_logging._logger = None
+    ema_logger = logging.getLogger(mesa_logging.LOGGER_NAME)
+    ema_logger.handlers = []
+
+
+def test_get_logger():
+    """Test get_logger."""
+    mesa_logging._rootlogger = None
+    logger = mesa_logging.get_rootlogger()
+    assert logger == logging.getLogger(mesa_logging.LOGGER_NAME)
+    assert len(logger.handlers) == 1
+    assert isinstance(logger.handlers[0], logging.NullHandler)
+
+    logger = mesa_logging.get_rootlogger()
+    assert logger, logging.getLogger(mesa_logging.LOGGER_NAME)
+    assert len(logger.handlers) == 1
+    assert isinstance(logger.handlers[0], logging.NullHandler)
+
+
+def test_log_to_stderr():
+    """Test log_to_stderr."""
+    mesa_logging._rootlogger = None
+    logger = mesa_logging.log_to_stderr(mesa_logging.DEBUG)
+    assert len(logger.handlers) == 2
+    assert logger.level == mesa_logging.DEBUG
+
+    mesa_logging._rootlogger = None
+    logger = mesa_logging.log_to_stderr()
+    assert len(logger.handlers) == 2
+    assert logger.level == mesa_logging.DEFAULT_LEVEL
+
+    logger = mesa_logging.log_to_stderr()
+    assert len(logger.handlers) == 2
+    assert logger.level == mesa_logging.DEFAULT_LEVEL