Nornir is hijacking logger

[dmfigol]

import logging

from nornir.core import InitNornir

logging.basicConfig(
    format="[%(asctime)s] %(levelname)-8s {%(filename)s:%(lineno)d} %(message)s",
    level=logging.INFO,
    handlers=[
        logging.FileHandler("my-app.log"),
        logging.StreamHandler(),
    ],
)

logger = logging.getLogger(__name__)


def main() -> None:
    logger.info("Starting script")
    nr = InitNornir("config.yaml")
    logger.info("Ending script")

main()

-> % python main.py
[2018-08-15 20:14:29,622] INFO     {main.py:72} Starting script

Even after 6 years python logging is still a mystery to me, so I'd greatly appreciate if someone could help with triage and fixing the issue.

[dbarrosop]

Probably not the best implementation but the behavior is intended:

https://github.com/nornir-automation/nornir/blob/develop/nornir/core/__init__.py#L110

We should probably call it instead from InitNornir and move the function into a helper. Anyway, your best solution is to define a dictConfig and add it to the config:

https://github.com/nornir-automation/nornir/blob/develop/nornir/core/__init__.py#L122

Alternatively, all the parameters you are trying to set are actually supported by the configuration so it should be quite straightforward to configure all that.

[dmfigol]

I am failing to understand how this behavior is intended.
I can't recall any other Python library that hijacks your root logger and changes its configuration.
Shouldn't all nornir logs have nornir logger as root and then branch either to nornir.core or nornir.plugins?
Nornir is just part of my application and I am not sure why I would want to additionally configure nornir logging using a different way than standard Python logging configuration mechanism.

Currently I have found the following workaround - branch my loggers with different root:

import sys
import logging.config

logging_dict = {
    "version": 1,
    "disable_existing_loggers": True,
    "formatters": {
        "standard": {
            "format": "[%(asctime)s] %(levelname)-8s {%(name)s:%(lineno)d} %(message)s"
        }
    },
    "handlers": {
        "default": {
            "level": "INFO",
            "class": "logging.handlers.RotatingFileHandler",
            "filename": "lab-system.log",
            "maxBytes": 1024 * 1024 * 5,
            "backupCount": 5,
            "formatter": "standard",
        },
        "console": {
            "level": "INFO",
            "class": "logging.StreamHandler",
            "stream": sys.stdout,
            "formatter": "standard",
        },
    },
    "loggers": {
        "lab_system": {
            "handlers": ["console", "default"],
            "level": "INFO",
            "propagate": False
        }
    },
    "root": {"handlers": ["console", "default"], "level": "INFO"},
}

logging.config.dictConfig(logging_dict)

and then use it like this:

logger = logging.getLogger('lab_system.deployment')

logger = logging.getLogger('lab_system.main')

But I don't like it - I need to explicitly name the logger for my app instead of using the root logger, I can't use basicConfig, etc.

[dbarrosop]

Well, I am open for suggestions here and PRs are welcome. As long as InitNornir configures the logging by default to log to nornir.log as it is done now I don't have an opinion about logger names, hierarchies, etc, and even changes to the API. The idea is to make it as simple as possible as the logging library in python is one of the most convoluted systems I have ever seen.

[dmfigol]

@dbarrosop could you describe the requirements for the logging? What is the desired behavior? I will try evaluating possible designs to implement this.

[dbarrosop]

Basically what these options describe:

https://github.com/nornir-automation/nornir/blob/develop/nornir/core/configuration.py#L52-L80

Simplest solution, if you don't come up with anything smarter, might be to have a configure_logging: {true, false} configuration option and call that configure_logging() based on the value of that option. I'd also like to isolate that method outside of Nornir and call it only from InitNornir. I think that's cleaner.

[dmfigol]

How can a user currently call logging?
nr.logger.info("message")? Would you like to retain the current behavior?

[dbarrosop]

no, that's not intended. The correct behavior should be with getLogger("nornir") or whatever they want to retrieve

[dmfigol]

if the user needs to call logging.getLogger(<name>), why do we try to set up logging for user in the first place? Yes, logging setup in Python is not pretty, but I am not sure that is nornir's problem to solve.

[dbarrosop]

if the user needs to call logging.getLogger(), why do we try to set up logging for user in the first place

Not sure how they are related, in any case, the "nornir" logger is meant to be for the library. Not for the users code. It is the best place to look for errors and to try to see what's going on. I understand current implementation is a bit messy, that's why I think we should move it outsode the Nornir class and call the configure_logging method from InitNornir instead.

[dmfigol]

Fixed with #316