lebrice / SimpleParsing

Simple, Elegant, Typed Argument Parsing with argparse
MIT License
401 stars 50 forks source link

Fix: Cleaner logging #79

Closed wolf1986 closed 3 years ago

wolf1986 commented 3 years ago

The custom method logging_utils.get_logger() aimed to organize the logs per file, by using the full file path __file__, however it is wrong and is causing a lot of clutter -

  1. In Python, logs are organized by hierarchy - each logger may have a parent logger. when using the default getLogger('parent_name.child_name') notation, it automatically creates multiple loggers and assigns parents according to the dots (.) in the name. Note that getLogger is actually a singleton manager, and can be called multiple times. A logger will be created only if it didn't exist yet. More info here

  2. The usual case is that every module (defined by a .py file) creates a logger - by calling getLogger(__name__). While __name__ is the name of the module (including packages separated by dots) - thus the hierarchy remains.

  3. After the proposed change, every file (module) in simple-parsing package, will create its own logger with the correct hierarchy, resulting in a parent simple-parsing logger that can be retrieved by anyone, and hushed if desired using getLogger('simple-parsing').setLevel(logging.WARNING) - Note that this will set the parent logger, and all the child loggers that report to it - will be also affected this way. Before this change, there was no way to silence the multiple logs of this package.

Some suggestions about logging:

  1. Every module creates its own logger using logger = getLogger(__name__) .
  2. Log using the appropriate log-level logger.debug(...) ... logger.warning(...) - according to the situation.
  3. Only the main script (the user of the package, or some high-level entry scripts of the library) is responsible for creating log-handlers and log-formatters. Every main script is responsible to decide what logs to show and what not (for example, silence libraries a, b, c at level WARNING and libraries d, e at level INFO)
  4. Log formatting - describes how to output the message of the log - show date/time, show process-id, etc... Log formats support filenames and line-numbers More info here

In this pull request:

lebrice commented 3 years ago

I'll merge this PR right now if that's alright with you! :)

wolf1986 commented 3 years ago

Thanks that was quick. I'll write a more detailed answer to what you asked later. Regarding merge - I ran the tests - most of them pass, I think that the failed ones probably failed before my changes.

If this seems ok to you then lets go ahead and merge. I now see that "Merging is blocked, The base branch requires all commits to be signed". I'll check if I have to change something on my end.

lebrice commented 3 years ago

Are some tests failing on your end? That would be odd, since the CI check with travis (which runs pytest in python 3.6, 3.7 and 3.8) is passing!

lebrice commented 3 years ago

About the signed commits, you can just git commit --amend -s to add a signature to your last commit I think. Otherwise the link that GitHub shows might also be relevant.

edit: Oh and btw you'll have to force-push your branch to overwrite the unsigned commit.

wolf1986 commented 3 years ago

About the signed commits, you can just git commit --amend -s to add a signature to your last commit I think. Otherwise the link that GitHub shows might also be relevant.

Thanks, will try now

Are some tests failing on your end? That would be odd, since the CI check with travis (which runs pytest in python 3.6, 3.7 and 3.8) is passing!

Oh, I ran them on Windows, might have something to do with that. Travis CI should have the final say on the matter.

lebrice commented 3 years ago

Idk why GitHub is still acting up. There's probably some local configuration you need to do. But in the meantime, I'll just overrule this and merge your PR.

wolf1986 commented 3 years ago

One question then: Is it possible to add such a formatter only to the Logger of simple-parsing? Or would that have an effect globally?

Didn't try to run the following snippet, but it should be close enough.

    # Handler - handles log-records, responsible to do something with them (e.g. print to stdout)
    # Formatter - applies formatting to log-records using available metadata such as level, time, file/path
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(
        logging.Formatter('{asctime} {pathname}: {levelname} {message}', style='{')
    )

    # logging.getLogger() - Will find the pointer for the logger by the name provided. If this is the first call
    # with the specific name - it will be created.
    # Note: It doesn't matter at all who created it first. The main script will get the pointer and may decide to
    # attach a handler to it. The library - will get the pointer to the same logger, and provide log-records at
    # runtime using e.g. `logger.info()`
    # Note2: `simple_parsing.subpackage.some_module2` and similar, will all be routed to this parent logger,
    # so their messages will be handled here as well.
    specific_logger = logging.getLogger('simple_parsing')

    # Attach a handler to a specific logger (usually attached to the root logger - the one without a name ''
    # using `basicConfig()`, which only works with the root logger)
    # Note: Multiple handlers can leave peacefully together - root logger can write to both stdout and files,
    # while some specific logger will write to a separate file or a even a log-server
    specific_logger.addHandler(handler)

    logger.info('Hello')