Configurable logging for libraries (#10614)

* Make library level logging to be configurable

Fixes #10203

* Create log level documentation under cheatsheet in Rasa docs

* Add log docs to `rasa shell --debug` (and others)

changelog/10203.feature.md

@@ -0,0 +1 @@
+Add configuration options (via env variables) for library logging.

docs/docs/command-line-interface.mdx

@@ -28,6 +28,33 @@ abstract: The command line interface (CLI) gives you easy-to-remember commands f
 |`rasa x`                |Launches Rasa X in local mode.                                                                                                            |
 |`rasa -h`               |Shows all available commands.                                                                                                             |
 
+## Log Level
+
+Rasa produces log messages at several different levels (eg. warning, info, error and so on). You can control which level of logs you would like to see with `--verbose` (same as `-v`) or `--debug` (same as `-vv`) as optional command line arguments. See each command below for more explanation on what these arguments mean.
+
+In addition to CLI arguments, several environment variables allow you to control log output in a more granular way. With these environment variables, you can configure log levels for messages created by external libraries such as matplotlib, pika, and kafka. Currently, following environment variables are supported:
+
+1. LOG_LEVEL_LIBRARIES: This is the general environment variable to configure log level for all libraries.
+2. LOG_LEVEL_MATPLOTLIB: This is the specialized environment variable to configure log level only for Matplotlib.
+3. LOG_LEVEL_RABBITMQ: This is the specialized environment variable to configure log level only for AMQP libraries, at the moment it handles log levels from `aio_pika` and `aiormq`.
+4. LOG_LEVEL_KAFKA: This is the specialized environment variable to configure log level only for kafka.
+
+General configuration (`LOG_LEVEL_LIBRARIES`) has less priority than library level specific configuration (`LOG_LEVEL_MATPLOTLIB`, `LOG_LEVEL_RABBITMQ` etc); and CLI parameter sets the lowest level log messages which will be handled. This means variables can be used together with a predictable result. As an example:
+
+```bash
+LOG_LEVEL_LIBRARIES=ERROR LOG_LEVEL_MATPLOTLIB=WARNING LOG_LEVEL_KAFKA=DEBUG rasa shell --debug
+```
+
+Above command run will result seeing `DEBUG` level messages by default (due to `--debug`), `WARNING` level for Matplotlib,`DEBUG` level for kafka and `ERROR` level for other libraries not configured.
+
+Note that CLI config sets the lowest level log messages to be handled, hence following command will set log level to INFO (due to `--verbose`) and no debug messages will be seen (library level configuration will not have an effect):
+
+```bash
+LOG_LEVEL_LIBRARIES=DEBUG LOG_LEVEL_MATPLOTLIB=DEBUG rasa shell --verbose
+```
+
+As an aside, CLI log level sets the level at the root logger (which has the important handler - coloredlogs handler); this means even if an environment variable sets a library logger to a lower level, root logger will reject messages from that library. By default CLI log level is set to `INFO` if not given.
+
 ## rasa init
 
 This command sets up a complete assistant for you with some example training data:
@@ -233,7 +260,7 @@ you need to add the `--ssl-password` as well.
 rasa run --ssl-certificate myssl.crt --ssl-keyfile myssl.key --ssl-password mypassword
 ```
 
-Rasa by default listens on each available network interface. You can limit this to a specific 
+Rasa by default listens on each available network interface. You can limit this to a specific
 network interface using the `-i` command line option.
 
 ```bash
@@ -398,7 +425,7 @@ rasa data migrate --help
 
 ## rasa data validate
 
-You can check your domain, NLU data, or story data for mistakes and inconsistencies. 
+You can check your domain, NLU data, or story data for mistakes and inconsistencies.
 To validate your data, run this command:
 
 ```bash
@@ -407,12 +434,12 @@ rasa data validate
 
 The validator searches for errors in the data, e.g. two intents that have some
 identical training examples.
-The validator also checks if you have any stories where different assistant actions follow from the same 
+The validator also checks if you have any stories where different assistant actions follow from the same
 dialogue history. Conflicts between stories will prevent a model from learning the correct
-pattern for a dialogue. 
+pattern for a dialogue.
 
-If you pass a `max_history` value to one or more policies in your `config.yml` file, provide the 
-smallest of those values in the validator command using the `--max-history <max_history>` flag. 
+If you pass a `max_history` value to one or more policies in your `config.yml` file, provide the
+smallest of those values in the validator command using the `--max-history <max_history>` flag.
 
 You can also validate only the story structure by running this command:
 
@@ -421,12 +448,12 @@ rasa data validate stories
 ```
 
 :::note
-Running `rasa data validate` does **not** test if your [rules](./rules.mdx) are consistent with your stories. 
+Running `rasa data validate` does **not** test if your [rules](./rules.mdx) are consistent with your stories.
 However, during training, the `RulePolicy` checks for conflicts between rules and stories. Any such conflict will abort training.
 
 Also, if you use end-to-end stories, then this might not capture all conflicts. Specifically, if two user inputs
 result in different tokens yet exactly the same featurization, then conflicting actions after these inputs
-may exist but will not be reported by the tool. 
+may exist but will not be reported by the tool.
 :::
 
 To interrupt validation even for minor issues such as unused intents or responses, use the `--fail-on-warnings` flag.
@@ -435,7 +462,7 @@ To interrupt validation even for minor issues such as unused intents or response
 The `rasa data validate stories` command assumes that all your story names are unique!
 :::
 
-You can use `rasa data validate` with additional arguments, e.g. to specify the location of your data and 
+You can use `rasa data validate` with additional arguments, e.g. to specify the location of your data and
 domain files:
 
 ```text [rasa data validate --help]

rasa/__main__.py

@@ -100,9 +100,7 @@ def main() -> None:
     arg_parser = create_argument_parser()
     cmdline_arguments = arg_parser.parse_args()
 
-    log_level = (
-        cmdline_arguments.loglevel if hasattr(cmdline_arguments, "loglevel") else None
-    )
+    log_level = getattr(cmdline_arguments, "loglevel", None)
     configure_logging_and_warnings(
         log_level, warn_only_once=True, filter_repeated_logs=True
     )

rasa/cli/arguments/default_arguments.py

@@ -125,8 +125,12 @@ def add_data_param(
 
 def add_logging_options(parser: argparse.ArgumentParser) -> None:
     """Add options to an argument parser to configure logging levels."""
-
-    logging_arguments = parser.add_argument_group("Python Logging Options")
+    logging_arguments = parser.add_argument_group(
+        "Python Logging Options",
+        "You can control level of log messages printed. "
+        "In addition to these arguments, a more fine grained configuration can be "
+        "achieved with environment variables. See online documentation for more info.",
+    )
 
     # arguments for logging configuration
     logging_arguments.add_argument(

rasa/constants.py

@@ -29,6 +29,9 @@
 DEFAULT_LOG_LEVEL_RASA_X = "WARNING"
 DEFAULT_LOG_LEVEL_LIBRARIES = "ERROR"
 ENV_LOG_LEVEL_LIBRARIES = "LOG_LEVEL_LIBRARIES"
+ENV_LOG_LEVEL_MATPLOTLIB = "LOG_LEVEL_MATPLOTLIB"
+ENV_LOG_LEVEL_RABBITMQ = "LOG_LEVEL_RABBITMQ"
+ENV_LOG_LEVEL_KAFKA = "LOG_LEVEL_KAFKA"
 
 DEFAULT_SANIC_WORKERS = 1
 ENV_SANIC_WORKERS = "SANIC_WORKERS"

rasa/core/brokers/kafka.py

@@ -35,7 +35,6 @@ def __init__(
         ssl_keyfile: Optional[Text] = None,
         ssl_check_hostname: bool = False,
         security_protocol: Text = "SASL_PLAINTEXT",
-        loglevel: Union[int, Text] = logging.ERROR,
         **kwargs: Any,
     ) -> None:
         """Kafka event broker.
@@ -69,7 +68,6 @@ def __init__(
                 should verify that the certificate matches the brokers hostname.
             security_protocol: Protocol used to communicate with brokers.
                 Valid values are: PLAINTEXT, SSL, SASL_PLAINTEXT, SASL_SSL.
-            loglevel: Logging level of the kafka logger.
         """
         import kafka
 
@@ -87,8 +85,6 @@ def __init__(
         self.ssl_keyfile = ssl_keyfile
         self.ssl_check_hostname = ssl_check_hostname
 
-        logging.getLogger("kafka").setLevel(loglevel)
-
     @classmethod
     async def from_endpoint_config(
         cls,
@@ -216,4 +212,4 @@ def _close(self) -> None:
     @rasa.shared.utils.common.lazy_property
     def rasa_environment(self) -> Optional[Text]:
         """Get value of the `RASA_ENVIRONMENT` environment variable."""
-        return os.environ.get("RASA_ENVIRONMENT")
+        return os.environ.get("RASA_ENVIRONMENT", "RASA_ENVIRONMENT_NOT_SET")

rasa/core/brokers/pika.py

@@ -10,7 +10,6 @@
 
 import aio_pika
 
-from rasa.constants import DEFAULT_LOG_LEVEL_LIBRARIES, ENV_LOG_LEVEL_LIBRARIES
 from rasa.shared.exceptions import RasaException
 from rasa.shared.constants import DOCS_URL_PIKA_EVENT_BROKER
 from rasa.core.brokers.broker import EventBroker
@@ -37,9 +36,6 @@ def __init__(
         queues: Union[List[Text], Tuple[Text], Text, None] = None,
         should_keep_unpublished_messages: bool = True,
         raise_on_failure: bool = False,
-        log_level: Union[Text, int] = os.environ.get(
-            ENV_LOG_LEVEL_LIBRARIES, DEFAULT_LOG_LEVEL_LIBRARIES
-        ),
         event_loop: Optional[AbstractEventLoop] = None,
         connection_attempts: int = 20,
         retry_delay_in_seconds: float = 5,
@@ -59,7 +55,6 @@ def __init__(
                 case of errors.
             raise_on_failure: Whether to raise an exception if publishing fails. If
                 `False`, keep retrying.
-            log_level: Logging level.
             event_loop: The event loop which will be used to run `async` functions. If
                 `None` `asyncio.get_event_loop()` is used to get a loop.
             connection_attempts: Number of attempts for connecting to RabbitMQ before
@@ -69,7 +64,6 @@ def __init__(
                 If nothing is mentioned then the default exchange name would be used.
         """
         super().__init__()
-        _set_pika_log_levels(log_level)
 
         self.host = host
         self.username = username
@@ -349,9 +343,3 @@ def _create_rabbitmq_ssl_options(
         }
 
     return None
-
-
-def _set_pika_log_levels(log_level: Union[Text, int]) -> None:
-    pika_loggers = ["aio_pika", "aiormq"]
-    for logger_name in pika_loggers:
-        logging.getLogger(logger_name).setLevel(log_level)

rasa/utils/common.py

@@ -23,7 +23,13 @@
 from socket import SOCK_DGRAM, SOCK_STREAM
 import numpy as np
 import rasa.utils.io
-from rasa.constants import DEFAULT_LOG_LEVEL_LIBRARIES, ENV_LOG_LEVEL_LIBRARIES
+from rasa.constants import (
+    DEFAULT_LOG_LEVEL_LIBRARIES,
+    ENV_LOG_LEVEL_LIBRARIES,
+    ENV_LOG_LEVEL_MATPLOTLIB,
+    ENV_LOG_LEVEL_RABBITMQ,
+    ENV_LOG_LEVEL_KAFKA,
+)
 from rasa.shared.constants import DEFAULT_LOG_LEVEL, ENV_LOG_LEVEL, TCP_PROTOCOL
 import rasa.shared.utils.io
 
@@ -90,28 +96,26 @@ def configure_logging_and_warnings(
     """Sets log levels of various loggers and sets up filters for warnings and logs.
 
     Args:
-        log_level: The lo level to be used for the 'Rasa' logger. Pass `None` to use
+        log_level: The log level to be used for the 'Rasa' logger. Pass `None` to use
             either the environment variable 'LOG_LEVEL' if it is specified, or the
             default log level otherwise.
         warn_only_once: determines whether user warnings should be filtered by the
             `warnings` module to appear only "once"
         filter_repeated_logs: determines whether `RepeatedLogFilter`s are added to
             the handlers of the root logger
     """
-    if not log_level:
+    if log_level is None:  # Log level NOTSET is 0 so we use `is None` here
         log_level = os.environ.get(ENV_LOG_LEVEL, DEFAULT_LOG_LEVEL)
+        # Change log level from str to int (note that log_level in function parameter
+        # int already, coming from CLI argparse parameter).
         log_level = logging.getLevelName(log_level)
 
     logging.getLogger("rasa").setLevel(log_level)
-
-    update_tensorflow_log_level()
-    update_asyncio_log_level()
-    update_matplotlib_log_level()
-    update_apscheduler_log_level()
-    update_socketio_log_level()
-
+    # Assign log level to env variable in str format (not int). Why do we assign?
     os.environ[ENV_LOG_LEVEL] = logging.getLevelName(log_level)
 
+    configure_library_logging()
+
     if filter_repeated_logs:
         for handler in logging.getLogger().handlers:
             handler.addFilter(RepeatedLogFilter())
@@ -137,6 +141,20 @@ def _filter_warnings(log_level: Optional[int], warn_only_once: bool = True) -> N
             )
 
 
+def configure_library_logging() -> None:
+    """Configures log levels of used libraries such as kafka, matplotlib, pika."""
+    library_log_level = os.environ.get(
+        ENV_LOG_LEVEL_LIBRARIES, DEFAULT_LOG_LEVEL_LIBRARIES,
+    )
+    update_tensorflow_log_level()
+    update_asyncio_log_level()
+    update_apscheduler_log_level()
+    update_socketio_log_level()
+    update_matplotlib_log_level(library_log_level)
+    update_kafka_log_level(library_log_level)
+    update_rabbitmq_log_level(library_log_level)
+
+
 def update_apscheduler_log_level() -> None:
     """Configures the log level of `apscheduler.*` loggers."""
     log_level = os.environ.get(ENV_LOG_LEVEL_LIBRARIES, DEFAULT_LOG_LEVEL_LIBRARIES)
@@ -154,6 +172,7 @@ def update_apscheduler_log_level() -> None:
 
 
 def update_socketio_log_level() -> None:
+    """Set the log level of socketio."""
     log_level = os.environ.get(ENV_LOG_LEVEL_LIBRARIES, DEFAULT_LOG_LEVEL_LIBRARIES)
 
     socketio_loggers = ["websockets.protocol", "engineio.server", "socketio.server"]
@@ -230,16 +249,32 @@ def update_asyncio_log_level() -> None:
     logging.getLogger("asyncio").setLevel(log_level)
 
 
-def update_matplotlib_log_level() -> None:
-    """Set the log level of matplotlib to the log level.
+def update_matplotlib_log_level(library_log_level: Text) -> None:
+    """Set the log level of matplotlib.
 
-    Uses the log level specified in the environment variable 'LOG_LEVEL_LIBRARIES'.
+    Uses the library specific log level or the general libraries log level.
     """
-    log_level = os.environ.get(ENV_LOG_LEVEL_LIBRARIES, DEFAULT_LOG_LEVEL_LIBRARIES)
-    logging.getLogger("matplotlib.backends.backend_pdf").setLevel(log_level)
-    logging.getLogger("matplotlib.colorbar").setLevel(log_level)
-    logging.getLogger("matplotlib.font_manager").setLevel(log_level)
-    logging.getLogger("matplotlib.ticker").setLevel(log_level)
+    log_level = os.environ.get(ENV_LOG_LEVEL_MATPLOTLIB, library_log_level)
+    logging.getLogger("matplotlib").setLevel(log_level)
+
+
+def update_kafka_log_level(library_log_level: Text) -> None:
+    """Set the log level of kafka.
+
+    Uses the library specific log level or the general libraries log level.
+    """
+    log_level = os.environ.get(ENV_LOG_LEVEL_KAFKA, library_log_level)
+    logging.getLogger("kafka").setLevel(log_level)
+
+
+def update_rabbitmq_log_level(library_log_level: Text) -> None:
+    """Set the log level of pika.
+
+    Uses the library specific log level or the general libraries log level.
+    """
+    log_level = os.environ.get(ENV_LOG_LEVEL_RABBITMQ, library_log_level)
+    logging.getLogger("aio_pika").setLevel(log_level)
+    logging.getLogger("aiormq").setLevel(log_level)
 
 
 def sort_list_of_dicts_by_first_key(dicts: List[Dict]) -> List[Dict]:
@@ -302,8 +337,8 @@ def update_existing_keys(
     """Iterate through all the updates and update a value in the original dictionary.
 
     If the updates contain a key that is not present in the original dict, it will
-    be ignored."""
-
+    be ignored.
+    """
     updated = original.copy()
     for k, v in updates.items():
         if k in updated: