Improve logging (#316)

* Improve logging

Fix #302, #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

* Fix build errors
* Add .ipynb_checkpoints to sphinx ignored list
* Run black and pylama on specific folders
* Pin pydantic until 0.19.0 is released
  pydantic/pydantic#254

* Add backwards compatibility and address comments

* Fix handling_connections notebook validation

* Add nbval sanitization to Makefile

Makefile

@@ -55,7 +55,7 @@ mypy:
 .PHONY: _nbval_docker
 _nbval_docker:
 	/root/.poetry/bin/poetry install
-	pytest --nbval \
+	pytest --nbval --sanitize-with docs/nbval_sanitize.cfg \
 		docs/plugins \
 		docs/howto \
 		docs/tutorials/intro/initializing_nornir.ipynb \
@@ -67,7 +67,7 @@ nbval:
 		run nornir \
 			make _nbval_docker
 
-PHONY: tests
+.PHONY: tests
 tests: build_test_container black sphinx pylama mypy nbval
 	make pytest PYTEST=3.6
 	make pytest PYTEST=3.7

docs/_data_templates/configuration-parameters.j2

@@ -15,7 +15,7 @@
    * - **Type**
      - ``{{ v["type"] }}``
    * - **Default**
-     - {{ "``{}``".format(v["default"]) if v["default"] else "" }}
+     - {{ "``{}``".format(v.get("default")) if v.get("default") != "" else "" }}
    * - **Required**
      - ``{{ v["required"] or false }}``
    * - **Environment Variable**

docs/conf.py

@@ -83,7 +83,7 @@ def extract_version():
 # List of patterns, relative to source directory, that match files and
 # directories to ignore when looking for source files.
 # This patterns also effect to html_static_path and html_extra_path
-exclude_patterns = ["_build", "Thumbs.db", ".DS_Store"]
+exclude_patterns = ["_build", "Thumbs.db", ".DS_Store", "**/.ipynb_checkpoints"]
 
 # The name of the Pygments (syntax highlighting) style to use.
 pygments_style = "sphinx"

docs/configuration/index.rst

@@ -15,6 +15,12 @@ A similar example using a ``yaml`` file:
 .. include:: ../howto/advanced_filtering/config.yaml
    :code: yaml
 
+Logging
+------------
+
+| By default, Nornir automatically configures logging when ``InitNornir`` is called. Logging configuration can be modified and available options are described in the section below. If you want to use Python logging module to configure logging, make sure to set ``logging.enabled`` parameter to ``False`` in order to avoid potential issues.
+| In some situations Nornir will detect previous logging configuration and will emit :obj:`nornir.core.exceptions.ConflictingConfigurationWarning`
+
 Next, you can find each section and their corresponding options.
 
 .. include:: generated/parameters.rst

docs/howto/handling_connections.ipynb

@@ -136,40 +136,40 @@
      "name": "stdout",
      "output_type": "stream",
      "text": [
-      "dev1.group_1:\r\n",
-      "    port: 22\r\n",
-      "    hostname: dev1.group_1\r\n",
-      "    username:\r\n",
-      "    password: a_password\r\n",
-      "    platform: eos\r\n",
-      "    data:\r\n",
-      "        my_var: comes_from_dev1.group_1\r\n",
-      "        www_server: nginx\r\n",
-      "        role: www\r\n",
-      "        nested_data:\r\n",
-      "            a_dict:\r\n",
-      "                a: 1\r\n",
-      "                b: 2\r\n",
-      "            a_list: [1, 2]\r\n",
-      "            a_string: asdasd\r\n",
-      "    groups:\r\n",
-      "        - group_1\r\n",
-      "    connection_options:\r\n",
-      "        paramiko:\r\n",
-      "            port: 22\r\n",
-      "            hostname:\r\n",
-      "            username: root\r\n",
-      "            password: docker\r\n",
-      "            platform: linux\r\n",
-      "            extras: {}\r\n",
-      "        dummy:\r\n",
-      "            hostname: dummy_from_host\r\n",
-      "            port:\r\n",
-      "            username:\r\n",
-      "            password:\r\n",
-      "            platform:\r\n",
-      "            extras:\r\n",
-      "                blah: from_host\r\n",
+      "dev1.group_1:\n",
+      "    port: 22\n",
+      "    hostname: dev1.group_1\n",
+      "    username:\n",
+      "    password: a_password\n",
+      "    platform: eos\n",
+      "    data:\n",
+      "        my_var: comes_from_dev1.group_1\n",
+      "        www_server: nginx\n",
+      "        role: www\n",
+      "        nested_data:\n",
+      "            a_dict:\n",
+      "                a: 1\n",
+      "                b: 2\n",
+      "            a_list: [1, 2]\n",
+      "            a_string: asdasd\n",
+      "    groups:\n",
+      "        - group_1\n",
+      "    connection_options:\n",
+      "        paramiko:\n",
+      "            port: 22\n",
+      "            hostname:\n",
+      "            username: root\n",
+      "            password: docker\n",
+      "            platform: linux\n",
+      "            extras: {}\n",
+      "        dummy:\n",
+      "            hostname: dummy_from_host\n",
+      "            port:\n",
+      "            username:\n",
+      "            password:\n",
+      "            platform:\n",
+      "            extras:\n",
+      "                blah: from_host\n",
       "\u001b[0m\u001b[0m"
      ]
     }
@@ -195,7 +195,7 @@
    "name": "python",
    "nbconvert_exporter": "python",
    "pygments_lexer": "ipython3",
-   "version": "3.6.5"
+   "version": "3.6.8"
   }
  },
  "nbformat": 4,

docs/nbval_sanitize.cfg

@@ -0,0 +1,3 @@
+[regex1]
+regex: \r\n
+replace: \n

docs/plugins/tasks/data/echo_data.ipynb

@@ -148,7 +148,7 @@
    "name": "python",
    "nbconvert_exporter": "python",
    "pygments_lexer": "ipython3",
-   "version": "3.7.0"
+   "version": "3.6.8"
   }
  },
  "nbformat": 4,

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,17 @@ 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(
+                f"Running task %r with args %s on %d hosts",
+                task_name,
+                kwargs,
+                num_hosts,
             )
-        )
-        self.logger.debug(kwargs)
+        else:
+            logger.warning("Task %r has not been run – 0 hosts selected", task_name)
 
         if num_workers == 1:
             result = self._run_serial(task, run_on, **kwargs)

nornir/core/configuration.py

@@ -1,7 +1,11 @@
 import logging
-import logging.config
-from typing import Any, Callable, Dict, List, Optional, TYPE_CHECKING, Type
+import logging.handlers
+import sys
+import warnings
+from pathlib import Path
+from typing import Any, Callable, Dict, Optional, TYPE_CHECKING, Type, List
 
+from nornir.core.exceptions import ConflictingConfigurationWarning
 
 if TYPE_CHECKING:
     from nornir.core.deserializer.inventory import Inventory  # noqa
@@ -31,62 +35,75 @@ def __init__(
 
 
 class LoggingConfig(object):
-    __slots__ = "level", "file", "format", "to_console", "loggers"
+    __slots__ = "enabled", "level", "file", "format", "to_console", "loggers"
 
     def __init__(
-        self, level: str, file_: str, format_: str, to_console: bool, loggers: List[str]
+        self,
+        enabled: Optional[bool],
+        level: str,
+        file_: str,
+        format_: str,
+        to_console: bool,
+        loggers: List[str],
     ) -> None:
+        self.enabled = enabled
         self.level = level
         self.file = file_
         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",
-            }
-        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)
+        if not self.enabled:
+            return
+
+        root_logger = logging.getLogger()
+        if root_logger.hasHandlers() or root_logger.level != logging.WARNING:
+            msg = (
+                "Native Python logging configuration has been detected, but Nornir "
+                "logging is enabled too. "
+                "This can lead to unexpected logging results. "
+                "Please set logging.enabled config to False "
+                "to disable automatic Nornir logging configuration. Refer to "
+                "https://nornir.readthedocs.io/en/stable/configuration/index.html#logging"  # noqa
+            )
+            warnings.warn(msg, ConflictingConfigurationWarning)
+
+        formatter = logging.Formatter(self.format)
+        # log INFO and DEBUG to stdout
+        stdout_handler = logging.StreamHandler(sys.stdout)
+        stdout_handler.setFormatter(formatter)
+        stdout_handler.setLevel(logging.DEBUG)
+        stdout_handler.addFilter(lambda record: record.levelno <= logging.INFO)
+        # log WARNING, ERROR and CRITICAL to stderr
+        stderr_handler = logging.StreamHandler(sys.stderr)
+        stderr_handler.setFormatter(formatter)
+        stderr_handler.setLevel(logging.WARNING)
+
+        for logger_name in self.loggers:
+            logger_ = logging.getLogger(logger_name)
+            logger_.propagate = False
+            logger_.setLevel(self.level)
+            if logger_.hasHandlers():
+                # Don't add handlers if some handlers are already attached to the logger
+                # This is crucial to avoid duplicate handlers
+                # Alternative would be to clear all handlers and reconfigure them
+                # with Nornir
+                # There are several situations this branch can be executed:
+                # multiple calls to InitNornir,
+                # logging.config.dictConfig configuring 'nornir' logger, etc.
+                # The warning is not emitted in this scenario
+                continue
+            if self.file:
+                handler = logging.handlers.RotatingFileHandler(
+                    str(Path(self.file)), maxBytes=1024 * 1024 * 10, backupCount=20
+                )
+                handler.setFormatter(formatter)
+                logger_.addHandler(handler)
+
+            if self.to_console:
+                logger_.addHandler(stdout_handler)
+                logger_.addHandler(stderr_handler)
 
 
 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, Union, List, cast
 
 from nornir.core import configuration
 from nornir.core.deserializer.inventory import Inventory
@@ -71,8 +71,11 @@ 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")
+    enabled: Optional[bool] = Schema(
+        default=None, description="Whether to configure logging or not"
+    )
+    level: str = Schema(default="INFO", description="Logging level")
+    file: str = Schema(default="nornir.log", description="Logging file")
     format: str = Schema(
         default="%(asctime)s - %(name)12s - %(levelname)8s - %(funcName)10s() - %(message)s",
         description="Logging format",
@@ -87,14 +90,15 @@ class Config:
         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_=conf.file,
+            format_=conf.format,
+            to_console=conf.to_console,
+            loggers=conf.loggers,
         )
 
 
@@ -211,7 +215,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/exceptions.py

@@ -104,3 +104,7 @@ def __init__(self, task: "Task", result: "Result"):
 
     def __str__(self) -> str:
         return "Subtask: {} (failed)\n".format(self.task)
+
+
+class ConflictingConfigurationWarning(UserWarning):
+    pass