Add logging subsystem #285
Conversation
…nd leave the default at info
collijk
requested review from
albrja,
hussain-jafari,
mattkappel,
ramittal,
rmudambi and
stevebachmeier
as code owners
collijk
changed the base branch from
collijk/feature/add-unique-simulation-name
to
develop
| @@ -220,13 +228,13 @@ def report(self, print_results=True): | |||
| self._population.get_population(True).index | |||
| ) | |||
| if print_results: | |||
| logger.debug("\n" + pformat(metrics)) | |||
| self._logger.info("\n" + pformat(metrics)) | |||
There was a problem hiding this comment.
This potentially spits out a very large dictionary. Since these outputs are being written to output.hdf anyway, are you sure this needs to be logged at INFO? I think DEBUG might still make more sense.
There was a problem hiding this comment.
I think this is a good point, but one to address in a different PR focused on the results system.
| performance_metrics = self.get_performance_metrics() | ||
| performance_metrics = performance_metrics.to_string( | ||
| index=False, | ||
| float_format=lambda x: f"{x:.2f}", | ||
| ) | ||
| logger.debug("\n" + performance_metrics) | ||
| self._logger.info("\n" + performance_metrics) |
There was a problem hiding this comment.
The same argument could be made here, but since performance metrics are much smaller, I think logging at INFO still could make sense.
| log_file = output_directory / "simulation.log" | ||
| _add_logging_sink( | ||
| log_file, | ||
| verbosity=2, |
There was a problem hiding this comment.
I wish logging levels were Enums rather than ints. This would be more legible if it read verbosity=DEBUG, but there's nothing we can do about that I guess.
There was a problem hiding this comment.
Will address in a separate PR
| fmt += self.simulation_and_component + " - " | ||
| else: | ||
| fmt += self.simulation + " - " | ||
| else: |
There was a problem hiding this comment.
Is this else supposed to be for this if or the one above?
| @@ -2,6 +2,8 @@ | |||
|
|
|||
| import pytest | |||
| import tables | |||
| from _pytest.logging import LogCaptureFixture | |||
There was a problem hiding this comment.
Cargo culting. This is a pattern from the loguru docs for making pytest work correctly with loguru.
Co-authored-by: Rajan Mudambi <11376379+rmudambi@users.noreply.github.com>
Write a more extensive comment about checking for terminal logging handlers.
Add logging subsystem
Description
Category: feature
Issues: #282 and #283
The primary goal of this PR is to add a logging subsystem into vivarium and to make it have as small an impact as
possible on user facing code.
User-facing changes
add_logging_sink,configure_logging_to_terminal, andconfigure_logging_to_filehave been moved fromvivarium.interface.utilitiestovivarium.framework.logging.utilities. These functions are not used invivarium_cluster_toolsbut may be alive in user code (Abie pointed out he uses it in Logging in interactive settings is verbose and not configurable #283 to suppress noisy logging, but part of the goal here is to give a more sensible way to do that).{time} | {level} | {module}:{function}:{line} - {message}. There are two new formats. The default (long) format is{time} | {level} | {simulation_name}-{component_name}:{line} - {message}if logging from a component that has requested a named logger and{time} | {level} | {simulation_name}-{module}:{line} - {message}if logging from a component that has requested an anonymous logger or if logging from the simulation context itself. The idea here is that the component is going to be a more intuitive (and fine-grained) logging detail than the module for researchers and straightforward to translate to modules for engineers. If that turns out not to be true, user space code can just request anonymous loggers. Additionally, there is a short format log that does{time} | {module}:{line} - {message}that I think will be appropriate for things like running sims in parallel. Only the long format is currently exposed to users.ERRORat the command line andDEBUGin an interactive setting toINFOin both settings (who thought that was a good idea originally 🙃 ).-vlogs atDEBUGlevel,-qlogs atWARNINGlevel)logging_verbosityargument in the initializer (2logs atDEBUGlevel,1logs atINFOlevel [default],0logs atWARNINGlevel). This argument is ignored if an external tool (like the command line interface) has configured logging. External tools may want to log broader information to the same sinks and must have the ability to preempt.INFO(formerlyDEBUG).WARNING(formerlyDEBUG)INFO(formerlyDEBUG)conceptsection of the docs.builder.logging.get_loggerand can, if desired, pass in the component name from which they want to log.Testing
CI and manual testing.