Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Proposal for a logging module #456

Merged
merged 8 commits into from
Feb 29, 2024
Merged

Proposal for a logging module #456

merged 8 commits into from
Feb 29, 2024

Conversation

DinoBektesevic
Copy link
Member

Issue

Logging in Python is a singleton that expects a logger to be declared on a module level. Each Logger has a unique name, and is retrieved via getLogger with the corresponding name. The recommended way to uniquely achieve this Python is to register a logger on a module level, using module's name:

logger = logging.getlogger(__name__)

Occasionally we have to produce a log on the C++ side. Primary use-case are logs produced by StackSearch - a C++ class used to manage processing, but generally not by the user. Users are expected to use the SearchRunner class instead. SearchRunner produces logs of the processing progress, Python-side, using print and the StackSearch on the C++ side using std::cout. This is done so that the print-outs appear as if they are coming from the same place. If we replaced the prints Python side with logging functionality, the outputs from the two objects would diverge and the C++ side output would not follow the Python logging output configuration anymore.

Potential solutions

To restore this behavior we would need to call the Python-side logger from C++. For that, we need to (somehow) pass a reference to the logger into the "StackSearch" class. Several options exist:

  1. pass the reference at instantiation time
  2. wrap the Python-side logger in a singleton from the C++ side and keep a lookup table of logger references resolved with the same name-matching the Python side

The second approach is implemented in this proposal. I don't see many (any) benefits of the first approach, we would have to wrap all uses of the logger in a class anyhow (which is basically what 2 is minus the Py-wrapper logger) or use pre-processor directives to call either some output or the Python logger.

How it works

The Logging class is a singleton that keeps a reference to all created Loggers. The Loggers define the log format and IO method (stdout, file etc.). Logging keeps references to Loggers in a registry. This registry is exposed via the getLogger method, which doubles as a factory function for Loggers. This is modeled after Python's logging module. When getLogger is called from Python (via the pybind11 bindings) it creates a new Python-side Logger object and registers its reference. When called C++ side it creates a C++-side Logger and registers its reference. Accessing a getLogger using a name that was already registered - it returns the reference from the registry.

This allows us to access Python-side loggers directly from C++ by invoking

Logging.getLogger("module_name")

from C++. On the example of SearchRunner, placing:

Logging.getLogger("kbmod.run_search")

somewhere in the search_runner.cpp would return:
a) the Python Logger object for the module, assuming search module is being called from Python, because the loggers are defined as module-global variables; i.e. guaranteed to occur before any C++ code executes.
b) or the default std::cout logger named "kbmod.run_search" that is basically acting as a more glorified print formatted that can prune and not-emit certain "levels" of messages.

The obvious pitfall is the case when a user does not route through this Logging, and instead registers a Python-side Logger via its logging module. Because these Python-side Loggers are not registered in the Logging's registry the KBMOD Logging will default to using the C++ std::out logger. This can lead to differing output formats if the Python Logger in question is then re-configured (as the default behavior of the internal KBMOD Logger was made to match that of default Python Logger).

src/kbmod/search/logging.h Outdated Show resolved Hide resolved
src/kbmod/search/logging.h Outdated Show resolved Hide resolved
src/kbmod/search/logging.h Outdated Show resolved Hide resolved
src/kbmod/search/image_stack.cpp Outdated Show resolved Hide resolved
src/kbmod/search/logging.h Outdated Show resolved Hide resolved
src/kbmod/search/logging.h Outdated Show resolved Hide resolved
src/kbmod/search/logging.h Outdated Show resolved Hide resolved
- Fix singleton object lifetime by wrapping it into a static method
- use py::object instead of py::handle to wrap a Python Logger instance
  - this respects the refcount tracking, unlike before. Why we didn't
    get an error at the end of every program execution - I don't know.
- add destructors, call them for Logger in the registry, let the
  default per-field destructor handle the rest.
- Add virtual destructor to Logger class itself,
  - Deleting a derived class object using a pointer of base class type
    that has a non-virtual destructor results in undefined behavior.
- Add more formatting options
  - support the major formatting keywords for the whole debug string
    (asctimes, names, levelnames and messages) using regex
  - support time-zone aware timestamps
  - support more Python-like formatting options. This is
    probably exactly how they do it. Actually I know it is:
    https://github.com/python/cpython/blob/main/Modules/_datetimemodule.c#L1646
- Fix the potential memory leak on time-stamp via put_time instead
  of mallocing untill strftime does not throw an error.
- Add the missing logger call to image_stack.
@DinoBektesevic DinoBektesevic marked this pull request as ready for review February 27, 2024 12:08
src/kbmod/search/logging.h Outdated Show resolved Hide resolved
src/kbmod/search/stack_search.cpp Outdated Show resolved Hide resolved
Fix the forgotten new allocation in Logging::logging.
Convert even more prints to logging.
Add our own root logger and rework the config system.
Add DebugTimer support (how did I miss this the first time?)
Actually test that it works by hand.
@DinoBektesevic DinoBektesevic merged commit 3be19c7 into main Feb 29, 2024
2 checks passed
DinoBektesevic added a commit that referenced this pull request Feb 29, 2024
DinoBektesevic added a commit that referenced this pull request Feb 29, 2024
DinoBektesevic added a commit that referenced this pull request Mar 14, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants