Improve logging

conda/common/io.py

@@ -16,7 +16,7 @@
 from functools import partial, wraps
 from io import BytesIO, StringIO
 from itertools import cycle
-from logging import CRITICAL, NOTSET, WARN, Formatter, StreamHandler, getLogger
+from logging import CRITICAL, WARN, Formatter, StreamHandler, getLogger
 from os.path import dirname, isdir, isfile, join
 from threading import Event, Lock, RLock, Thread
 from time import sleep, time
@@ -323,6 +323,20 @@ def stderr_log_level(level, logger_name=None):
 def attach_stderr_handler(
     level=WARN, logger_name=None, propagate=False, formatter=None
 ):
+    """Attach a new `stderr` handler to the given logger and configure both.
+
+    This function creates a new StreamHandler that writes to `stderr` and attaches it
+    to the logger given by `logger_name` (which maybe `None`, in which case the root
+    logger is used). If the logger already has a handler by the name of `stderr`, it is
+    removed first.
+
+    The given `level` is set **for the handler**, not for the logger; however, this
+    function also sets the level of the given logger to the minimum of its current
+    effective level and the new handler level, ensuring that the handler will receive the
+    required log records, while minimizing the number of unnecessary log events. It also
+    sets the loggers `propagate` property according to the `propagate` argument.
+    The `formatter` argument can be used to set the formatter of the handler.
+    """
     # get old stderr logger
     logr = getLogger(logger_name)
     old_stderr_handler = next(
@@ -340,7 +354,8 @@ def attach_stderr_handler(
         if old_stderr_handler:
             logr.removeHandler(old_stderr_handler)
         logr.addHandler(new_stderr_handler)
-        logr.setLevel(NOTSET)
+        if level < logr.getEffectiveLevel():
+            logr.setLevel(level)
         logr.propagate = propagate
 
 

conda/gateways/logging.py

@@ -141,8 +141,10 @@ def emit(self, record):
 
 @lru_cache(maxsize=None)
 def initialize_logging():
-    # root gets level ERROR; 'conda' gets level WARN and propagates to root.
+    # root gets level ERROR
+    # 'conda' gets level WARN and does not propagate to root.
     initialize_root_logger()
+    getLogger("conda").setLevel(WARN)
     set_conda_log_level()
     initialize_std_loggers()
 
@@ -184,14 +186,12 @@ def initialize_std_loggers():
 
 
 def initialize_root_logger(level=ERROR):
+    getLogger().setLevel(ERROR)
     attach_stderr_handler(level=level)
 
 
 def set_conda_log_level(level=WARN):
-    conda_logger = getLogger("conda")
-    conda_logger.setLevel(logging.NOTSET)
     attach_stderr_handler(level=level, logger_name="conda")
-    conda_logger.propagate = False
 
 
 def set_all_logger_level(level=DEBUG):

docs/requirements.txt

@@ -18,6 +18,7 @@ sphinxcontrib-applehelp==1.0.7
 sphinxcontrib-devhelp==1.0.5
 sphinxcontrib-htmlhelp==2.0.4
 sphinxcontrib-jsmath==1.0.1
+sphinxcontrib-mermaid==0.9.2
 sphinxcontrib-plantuml==0.21
 sphinxcontrib-programoutput==0.17
 sphinxcontrib-qthelp==1.0.6

docs/source/conf.py

@@ -40,6 +40,7 @@
     "sphinx_reredirects",
     "sphinx_sitemap",
     "sphinxarg.ext",
+    "sphinxcontrib.mermaid",
     "sphinxcontrib.plantuml",
     "sphinxcontrib.programoutput",
     "sphinx_design",

docs/source/dev-guide/deep-dives/index.md

@@ -12,4 +12,5 @@ install
 activation
 context
 solvers
+logging
 ```

docs/source/dev-guide/deep-dives/logging.md

@@ -0,0 +1,60 @@
+(deep_dive_logging)=
+# Logging
+
+Logging in conda is based on the [Python logging framework](https://docs.python.org/3/library/logging.html).
+In this guide, we'll describe the loggers and handlers used in conda, as well as how they are used.
+
+## Logger hierarchy
+Python logging uses loggers as the source of logging messages.
+These loggers are organized as a single hierarchy defined by names given to individual loggers, with one nameless root logger.
+Other logger names are given as dot separated strings, such that, for example, the logger named `a.b.c` has the parent `a.b`, which in turn has the parent `a`, which in turn has the root logger as its parent.
+Python programs are free to use any name for loggers they like, but often the name will bear a relationship to the Python entity that is using it, most commonly there will be a module level logger, which is called `__name__`, i.e. `conda.<pkg>.<module>`, e.g. `conda.gateways.logging`.
+This approach naturally arranges loggers used in a single code base into a hierarchy that follows the package structure.
+
+Conda largely follows this approach, however, it also makes use of some additional loggers.
+
+```{mermaid}
+:caption: The conda logger hierarchy. Dotted lines represent relations with `propagate = False`.
+
+flowchart LR
+    root["&lt;root&gt;"] -.-> conda
+    conda --> modules["conda.&lt;pkg&gt;.&lt;module&gt;"]
+    conda -.-> conda.stdout -.-> conda.stdout.verbose
+    conda -.-> conda.stderr
+    conda -.-> conda.stdoutlog
+    conda -.-> conda.stderrlog
+    root --> auxlib
+    root --> progress.update & progress.stop
+```
+
+The full hierarchy of all module level loggers is given below at {ref}`full-module-loggers`.
+
+### The root logger
+
+The root logger is not used directly as a logging target, but it is used as a building block in the configuration of the logging system.
+
+### The `conda` subhierarchy
+
+The `conda` subhierarchy consists of all loggers whose name starts with `conda.` and it is mostly configured via the `conda` logger itself in {func}`conda.gateways.logging.initialize_logging`.
+
+Additionally, the following five loggers are used for other output.
+These are likely to be replaced and should not be used in new code.
+- `conda.stdout`
+- `conda.stderr`
+- `conda.stdoutlog`
+- `conda.stderrlog`
+- `conda.stdout.verbose`
+
+### Other loggers
+
+Three more loggers appear in conda, namely `progress.update`and `progress.stop`, which only appear in `conda.plan.execute_actions`, which in turn is
+being deprecated (c.f. https://github.com/conda/conda/pull/13881); and `auxlib` which likely is a remnant from before the auxlib code was completely
+absorbed into conda, since it only appears to be adorned with {class}`conda.auxlib.NullHandler` in `conda.auxlib.__init__`.
+
+## Potential effect on other loggers
+
+There are three other functions that use {func}`logging.getLogger` and hence might affect other loggers. They are {func}`conda.gateways.logging.set_file_logging` that is never used in the code base and the context managers {func}`conda.common.io.disable_logger` and {func}`conda.common.io.stderr_log_level`, which are only used in testing.
+
+## Root logger in auxlib
+
+In {module}`conda.auxlib.logz`, the root logger is modified.

news/13735-improve-logging

@@ -0,0 +1,19 @@
+### Enhancements
+
+* <news item>
+
+### Bug fixes
+
+* Improve treatment of logger levels (#13735)
+
+### Deprecations
+
+* <news item>
+
+### Docs
+
+* Add logging overview as deep-dive (#13735)
+
+### Other
+
+* <news item>

tests/cli/test_main_clean.py

@@ -4,6 +4,7 @@
 
 import json
 from datetime import datetime
+from logging import WARN
 from pathlib import Path
 from typing import TYPE_CHECKING
 
@@ -16,7 +17,7 @@
 )
 from conda.cli.main_clean import _get_size
 from conda.core.subdir_data import create_cache_dir
-from conda.gateways.logging import set_verbosity
+from conda.gateways.logging import set_log_level
 
 if TYPE_CHECKING:
     from typing import Iterable
@@ -331,7 +332,7 @@ def test_clean_all(
     assert not has_pkg(pkg, tars)
     assert not cache
 
-    set_verbosity(0)  # reset verbosity
+    set_log_level(WARN)  # reset verbosity
 
 
 # conda clean --all --verbose
@@ -371,7 +372,7 @@ def test_clean_all_mock_lstat(
         assert has_pkg(pkg, tars)
         assert cache
 
-    set_verbosity(0)  # reset verbosity
+    set_log_level(WARN)  # reset verbosity
 
 
 # _get_size unittest, valid file

tests/common/test_io.py

@@ -62,6 +62,7 @@ def test_attach_stderr_handler():
     assert logr.handlers[0].name == "stderr"
     assert logr.handlers[0].level is WARN
     assert logr.level is NOTSET
+    assert logr.getEffectiveLevel() is WARN
     assert c.stdout == ""
     assert "test message" in c.stderr
     assert debug_message not in c.stderr
@@ -76,7 +77,7 @@ def test_attach_stderr_handler():
     assert len(logr.handlers) == 1
     assert logr.handlers[0].name == "stderr"
     assert logr.handlers[0].level is DEBUG
-    assert logr.level is NOTSET
+    assert logr.level is DEBUG
     assert c.stdout == ""
     assert "test message" in c.stderr
     assert debug_message in c.stderr