Add logging to MESA

[quaquel]

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:

[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

• - include the arguments/keyword arguments for model initialization
• - add the steps counter so you know at which step you are
• - add the unique_id of the agent registering.

[github-actions]

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 modeled on log4j and java.util.logging. Since I went from Java to Python, it was easy to get up and running.

There are various good overview pages of logging libraries. This one, 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. 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 and built-in support for logging from multiple processes (relevant for batchrunning). Another notable library in beta is 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 chooses to abide by the API of the built-in logging library speaks to the status of the built-in logging library.

I am currently inclined 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.3 or so. So, maintenance on our end will largely be a non-issue once our boilerplate code is final and covered by tests. We can even play with pico logging if 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]

This is great! @quaquel Definitely useful particularly with Solara

[tpike3]

@quaquel can you please resolve the conflicts and rebase to main; feel free to merge. Thanks again!

[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)