Improve logging

Fix nornir-automation#302, nornir-automation#230

* Nornir logging is configured only when no changes have been done to Python logging
* No more duplicate logs
* Replace format and f-strings in logs to % strings according to best practices
* Improved messages for some logs

nornir/core/__init__.py

@@ -7,6 +7,8 @@
 from nornir.core.state import GlobalState
 from nornir.core.task import AggregatedResult, Task
 
+logger = logging.getLogger(__name__)
+
 
 class Nornir(object):
     """
@@ -27,14 +29,9 @@ class Nornir(object):
     """
 
     def __init__(
-        self,
-        inventory: Inventory,
-        config: Config = None,
-        logger: logging.Logger = None,
-        data: GlobalState = None,
+        self, inventory: Inventory, config: Config = None, data: GlobalState = None
     ) -> None:
         self.data = data if data is not None else GlobalState()
-        self.logger = logger or logging.getLogger(__name__)
 
         self.inventory = inventory
 
@@ -118,12 +115,16 @@ def run(
                 if name in self.data.failed_hosts:
                     run_on.append(host)
 
-        self.logger.info(
-            "Running task '{}' with num_workers: {}".format(
-                kwargs.get("name") or task.__name__, num_workers
+        num_hosts = len(self.inventory.hosts)
+        task_name = kwargs.get("name") or task.__name__
+        if num_hosts:
+            logger.info(
+                "Running task %r with args %s on %d hosts", task_name, kwargs, num_hosts
+            )
+        else:
+            logger.warning(
+                "Task %r has not been run due to 0 hosts selected", task_name
             )
-        )
-        self.logger.debug(kwargs)
 
         if num_workers == 1:
             result = self._run_serial(task, run_on, **kwargs)

nornir/core/configuration.py

@@ -1,6 +1,8 @@
 import logging
-import logging.config
-from typing import Any, Callable, Dict, List, Optional, TYPE_CHECKING, Type
+import logging.handlers
+import sys
+from pathlib import Path
+from typing import Any, Callable, Dict, Optional, TYPE_CHECKING, Type
 
 
 if TYPE_CHECKING:
@@ -31,62 +33,59 @@ def __init__(
 
 
 class LoggingConfig(object):
-    __slots__ = "level", "file", "format", "to_console", "loggers"
+    __slots__ = "enabled", "level", "file_path", "format", "to_console"
 
     def __init__(
-        self, level: str, file_: str, format_: str, to_console: bool, loggers: List[str]
+        self, enabled: bool, level: str, file_path: str, format: str, to_console: bool
     ) -> None:
+        self.enabled = enabled
         self.level = level
-        self.file = file_
-        self.format = format_
+        self.file_path = file_path
+        self.format = format
         self.to_console = to_console
-        self.loggers = loggers
 
     def configure(self) -> None:
-        rootHandlers: List[str] = []
-        root = {
-            "level": "CRITICAL" if self.loggers else self.level.upper(),
-            "handlers": rootHandlers,
-            "formatter": "simple",
-        }
-        handlers: Dict[str, Any] = {}
-        loggers: Dict[str, Any] = {}
-        dictConfig = {
-            "version": 1,
-            "disable_existing_loggers": False,
-            "formatters": {"simple": {"format": self.format}},
-            "handlers": handlers,
-            "loggers": loggers,
-            "root": root,
-        }
-        handlers_list = []
-        if self.file:
-            rootHandlers.append("info_file_handler")
-            handlers_list.append("info_file_handler")
-            handlers["info_file_handler"] = {
-                "class": "logging.handlers.RotatingFileHandler",
-                "level": "NOTSET",
-                "formatter": "simple",
-                "filename": self.file,
-                "maxBytes": 10485760,
-                "backupCount": 20,
-                "encoding": "utf8",
-            }
+        nornir_logger = logging.getLogger("nornir")
+        root_logger = logging.getLogger()
+        # don't configure logging when:
+        # 1) enabled equals to False
+        # 2) nornir logger's level is something different than NOTSET
+        # 3) if root logger has some handlers (which means you know how to
+        #    configure logging already)
+        # 4) if root logger's level is something different than WARNING
+        #    (which is default)
+        if (
+            not self.enabled
+            or nornir_logger.level != logging.NOTSET
+            or root_logger.hasHandlers()
+            or root_logger.level != logging.WARNING
+        ):
+            return
+
+        nornir_logger.propagate = False
+        nornir_logger.setLevel(self.level)
+        formatter = logging.Formatter(self.format)
+        if self.file_path:
+            handler = logging.handlers.RotatingFileHandler(
+                str(Path(self.file_path)), maxBytes=1024 * 1024 * 10, backupCount=20
+            )
+            handler.setFormatter(formatter)
+            nornir_logger.addHandler(handler)
+
         if self.to_console:
-            rootHandlers.append("info_console")
-            handlers_list.append("info_console")
-            handlers["info_console"] = {
-                "class": "logging.StreamHandler",
-                "level": "NOTSET",
-                "formatter": "simple",
-                "stream": "ext://sys.stdout",
-            }
-
-        for logger in self.loggers:
-            loggers[logger] = {"level": self.level, "handlers": handlers_list}
-
-        if rootHandlers:
-            logging.config.dictConfig(dictConfig)
+            # log INFO and DEBUG to stdout
+            h1 = logging.StreamHandler(sys.stdout)
+            h1.setFormatter(formatter)
+            h1.setLevel(logging.DEBUG)
+            h1.addFilter(lambda record: record.levelno <= logging.INFO)
+            nornir_logger.addHandler(h1)
+
+            # log WARNING, ERROR and CRITICAL to stderr
+            h2 = logging.StreamHandler(sys.stderr)
+            h2.setFormatter(formatter)
+            h2.setLevel(logging.WARNING)
+
+            nornir_logger.addHandler(h2)
 
 
 class Jinja2Config(object):

nornir/core/deserializer/configuration.py

@@ -1,7 +1,7 @@
 import importlib
 import logging
 from pathlib import Path
-from typing import Any, Callable, Dict, List, Optional, Type, Union, cast
+from typing import Any, Callable, Dict, Optional, Type, cast, Union
 
 from nornir.core import configuration
 from nornir.core.deserializer.inventory import Inventory
@@ -70,31 +70,33 @@ def deserialize(cls, **kwargs: Any) -> configuration.InventoryConfig:
         )
 
 
-class LoggingConfig(BaseNornirSettings):
-    level: str = Schema(default="debug", description="Logging level")
-    file: str = Schema(default="nornir.log", descritpion="Logging file")
+class LoggingConfig(BaseSettings):
+    enabled: bool = Schema(
+        default=True, description="Whether to configure logging or not"
+    )
+    level: str = Schema(default="DEBUG", description="Logging level")
+    file_path: str = Schema(default="nornir.log", description="Logging file")
     format: str = Schema(
-        default="%(asctime)s - %(name)12s - %(levelname)8s - %(funcName)10s() - %(message)s",
+        default="[%(asctime)s] %(levelname)-8s {%(name)s:%(lineno)d} %(message)s",
         description="Logging format",
     )
     to_console: bool = Schema(
         default=False, description="Whether to log to console or not"
     )
-    loggers: List[str] = Schema(default=["nornir"], description="Loggers to configure")
 
     class Config:
         env_prefix = "NORNIR_LOGGING_"
         ignore_extra = False
 
     @classmethod
-    def deserialize(cls, **kwargs: Any) -> configuration.LoggingConfig:
-        logging_config = LoggingConfig(**kwargs)
+    def deserialize(cls, **kwargs) -> configuration.LoggingConfig:
+        conf = cls(**kwargs)
         return configuration.LoggingConfig(
-            level=getattr(logging, logging_config.level.upper()),
-            file_=logging_config.file,
-            format_=logging_config.format,
-            to_console=logging_config.to_console,
-            loggers=logging_config.loggers,
+            enabled=conf.enabled,
+            level=conf.level.upper(),
+            file_path=conf.file_path,
+            format=conf.format,
+            to_console=conf.to_console,
         )
 
 
@@ -211,7 +213,7 @@ def _resolve_import_from_string(
             return import_path
         module_name, obj_name = import_path.rsplit(".", 1)
         module = importlib.import_module(module_name)
-        return cast(Callable[..., Any], getattr(module, obj_name))
-    except Exception as e:
-        logger.error(f"failed to load import_path '{import_path}'\n{e}")
+        return getattr(module, obj_name)
+    except Exception:
+        logger.error("Failed to import %r", import_path, exc_info=True)
         raise

nornir/core/task.py

@@ -9,6 +9,9 @@
     from nornir.core.inventory import Host
 
 
+logger = logging.getLogger(__name__)
+
+
 class Task(object):
     """
     A task is basically a wrapper around a function that has to be run against multiple devices.
@@ -59,21 +62,30 @@ def start(self, host, nornir):
         self.host = host
         self.nornir = nornir
 
-        logger = logging.getLogger(__name__)
         try:
-            logger.info("{}: {}: running task".format(self.host.name, self.name))
+            logger.debug("Host %r: running task %r", self.host.name, self.name)
             r = self.task(self, **self.params)
             if not isinstance(r, Result):
                 r = Result(host=host, result=r)
 
         except NornirSubTaskError as e:
             tb = traceback.format_exc()
-            logger.error("{}: {}".format(self.host, tb))
+            logger.error(
+                "Host %r: task %r failed with traceback:\n%s",
+                self.host.name,
+                self.name,
+                tb,
+            )
             r = Result(host, exception=e, result=str(e), failed=True)
 
         except Exception as e:
             tb = traceback.format_exc()
-            logger.error("{}: {}".format(self.host, tb))
+            logger.error(
+                "Host %r: task %r failed with traceback:\n%s",
+                self.host.name,
+                self.name,
+                tb,
+            )
             r = Result(host, exception=e, result=tb, failed=True)
 
         r.name = self.name

nornir/init_nornir.py

@@ -20,10 +20,7 @@ def cls_to_string(cls: Callable[..., Any]) -> str:
 
 
 def InitNornir(
-    config_file: str = "",
-    dry_run: bool = False,
-    configure_logging: bool = True,
-    **kwargs: Dict[str, Any],
+    config_file: str = "", dry_run: bool = False, **kwargs: Dict[str, Any]
 ) -> Nornir:
     """
     Arguments:
@@ -49,8 +46,7 @@ def InitNornir(
 
     data = GlobalState(dry_run=dry_run)
 
-    if configure_logging:
-        conf.logging.configure()
+    conf.logging.configure()
 
     inv = conf.inventory.plugin.deserialize(
         transform_function=conf.inventory.transform_function,

nornir/plugins/inventory/ansible.py

@@ -251,9 +251,7 @@ def parse(hostsfile: str) -> Tuple[HostsDict, GroupsDict, DefaultsDict]:
         try:
             parser = YAMLParser(hostsfile)
         except (ScannerError, ComposerError):
-            logger.error(
-                "couldn't parse '{}' as neither a ini nor yaml file".format(hostsfile)
-            )
+            logger.error("couldn't parse %r as neither a ini nor yaml file", hostsfile)
             raise
 
     parser.parse()

nornir/plugins/inventory/simple.py

@@ -6,6 +6,8 @@
 
 import ruamel.yaml
 
+logger = logging.getLogger(__name__)
+
 
 class SimpleInventory(Inventory):
     def __init__(
@@ -26,7 +28,7 @@ def __init__(
                 with open(group_file, "r") as f:
                     groups = yml.load(f) or {}
             else:
-                logging.debug("{}: doesn't exist".format(group_file))
+                logger.debug("File %r was not found", group_file)
                 groups = {}
 
         defaults: VarsDict = {}
@@ -35,6 +37,6 @@ def __init__(
                 with open(defaults_file, "r") as f:
                     defaults = yml.load(f) or {}
             else:
-                logging.debug("{}: doesn't exist".format(defaults_file))
+                logger.debug("File %r was not found", defaults_file)
                 defaults = {}
         super().__init__(hosts=hosts, groups=groups, defaults=defaults, *args, **kwargs)

setup.cfg

@@ -12,7 +12,7 @@ universal=1
 [pylama]
 linters = mccabe,pep8,pyflakes,import_order
 ignore = D203,C901
-skip = .tox/*
+skip = .tox/*,.venv/*
 
 [pylama:pep8]
 max_line_length = 100