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/loggers.mmd

@@ -0,0 +1,174 @@
+flowchart LR
+    logger_0["conda"]
+    logger_1["conda.activate"]
+    logger_2["conda.auxlib.entity"]
+    logger_3["conda.auxlib.exceptions"]
+    logger_4["conda.auxlib.ish"]
+    logger_5["conda.auxlib.logz"]
+    logger_6["conda.base.context"]
+    logger_7["conda.cli.conda_argparse"]
+    logger_8["conda.cli.install"]
+    logger_9["conda.cli.main_clean"]
+    logger_10["conda.cli.main_compare"]
+    logger_11["conda.cli.main_create"]
+    logger_12["conda.cli.main_info"]
+    logger_13["conda.cli.main_init"]
+    logger_14["conda.cli.main_list"]
+    logger_15["conda.cli.main_pip"]
+    logger_16["conda.cli.main_remove"]
+    logger_17["conda.cli.main_run"]
+    logger_18["conda.cli.python_api"]
+    logger_19["conda.common.configuration"]
+    logger_20["conda.common.io"]
+    logger_21["conda.common._logic"]
+    logger_22["conda.common._os"]
+    logger_23["conda.common._os.linux"]
+    logger_24["conda.common._os.unix"]
+    logger_25["conda.common._os.windows"]
+    logger_26["conda.common.path"]
+    logger_27["conda.common.pkg_formats.python"]
+    logger_28["conda.common.serialize"]
+    logger_29["conda.common.signals"]
+    logger_30["conda.common.toposort"]
+    logger_31["conda.core.envs_manager"]
+    logger_32["conda.core.index"]
+    logger_33["conda.core.initialize"]
+    logger_34["conda.core.link"]
+    logger_35["conda.core.package_cache_data"]
+    logger_36["conda.core.path_actions"]
+    logger_37["conda.core.portability"]
+    logger_38["conda.core.prefix_data"]
+    logger_39["conda.core.solve"]
+    logger_40["conda.core.subdir_data"]
+    logger_41["conda.env.installers.pip"]
+    logger_42["conda.env.pip_util"]
+    logger_43["conda.exception_handler"]
+    logger_44["conda.exceptions"]
+    logger_45["conda.gateways.anaconda_client"]
+    logger_46["conda.gateways.connection.adapters.ftp"]
+    logger_47["conda.gateways.connection.adapters.localfs"]
+    logger_48["conda.gateways.connection.adapters.s3"]
+    logger_49["conda.gateways.connection.download"]
+    logger_50["conda.gateways.connection.session"]
+    logger_51["conda.gateways.disk"]
+    logger_52["conda.gateways.disk.create"]
+    logger_53["conda.gateways.disk.delete"]
+    logger_54["conda.gateways.disk.link"]
+    logger_55["conda.gateways.disk.permissions"]
+    logger_56["conda.gateways.disk.read"]
+    logger_57["conda.gateways.disk.test"]
+    logger_58["conda.gateways.disk.update"]
+    logger_59["conda.gateways.logging"]
+    logger_60["conda.gateways.repodata"]
+    logger_61["conda.gateways.repodata.jlap.core"]
+    logger_62["conda.gateways.repodata.jlap.fetch"]
+    logger_63["conda.gateways.repodata.jlap.interface"]
+    logger_64["conda.gateways.subprocess"]
+    logger_65["conda.history"]
+    logger_66["conda.instructions"]
+    logger_67["conda.models.channel"]
+    logger_68["conda.models.dist"]
+    logger_69["conda.models.leased_path_entry"]
+    logger_70["conda.models.match_spec"]
+    logger_71["conda.models.package_info"]
+    logger_72["conda.models.prefix_graph"]
+    logger_73["conda.models.version"]
+    logger_74["conda.notices.cache"]
+    logger_75["conda.notices.core"]
+    logger_76["conda.notices.fetch"]
+    logger_77["conda.plan"]
+    logger_78["conda.plugins.hookspec"]
+    logger_79["conda.plugins.manager"]
+    logger_80["conda.plugins.subcommands.doctor.health_checks"]
+    logger_81["conda.resolve"]
+    logger_82["conda.testing"]
+    logger_83["conda.testing.integration"]
+    logger_84["conda.trust.signature_verification"]
+    logger_85["conda.utils"]
+    logger_86["conda._vendor.distro"]
+    logger_0 --> logger_1
+    logger_0 --> logger_2
+    logger_0 --> logger_3
+    logger_0 --> logger_4
+    logger_0 --> logger_5
+    logger_0 --> logger_6
+    logger_0 --> logger_7
+    logger_0 --> logger_8
+    logger_0 --> logger_9
+    logger_0 --> logger_10
+    logger_0 --> logger_11
+    logger_0 --> logger_12
+    logger_0 --> logger_13
+    logger_0 --> logger_14
+    logger_0 --> logger_15
+    logger_0 --> logger_16
+    logger_0 --> logger_17
+    logger_0 --> logger_18
+    logger_0 --> logger_19
+    logger_0 --> logger_20
+    logger_0 --> logger_21
+    logger_0 --> logger_22
+    logger_22 --> logger_23
+    logger_22 --> logger_24
+    logger_22 --> logger_25
+    logger_0 --> logger_26
+    logger_0 --> logger_27
+    logger_0 --> logger_28
+    logger_0 --> logger_29
+    logger_0 --> logger_30
+    logger_0 --> logger_31
+    logger_0 --> logger_32
+    logger_0 --> logger_33
+    logger_0 --> logger_34
+    logger_0 --> logger_35
+    logger_0 --> logger_36
+    logger_0 --> logger_37
+    logger_0 --> logger_38
+    logger_0 --> logger_39
+    logger_0 --> logger_40
+    logger_0 --> logger_41
+    logger_0 --> logger_42
+    logger_0 --> logger_43
+    logger_0 --> logger_44
+    logger_0 --> logger_45
+    logger_0 --> logger_46
+    logger_0 --> logger_47
+    logger_0 --> logger_48
+    logger_0 --> logger_49
+    logger_0 --> logger_50
+    logger_0 --> logger_51
+    logger_51 --> logger_52
+    logger_51 --> logger_53
+    logger_51 --> logger_54
+    logger_51 --> logger_55
+    logger_51 --> logger_56
+    logger_51 --> logger_57
+    logger_51 --> logger_58
+    logger_0 --> logger_59
+    logger_0 --> logger_60
+    logger_60 --> logger_61
+    logger_60 --> logger_62
+    logger_60 --> logger_63
+    logger_0 --> logger_64
+    logger_0 --> logger_65
+    logger_0 --> logger_66
+    logger_0 --> logger_67
+    logger_0 --> logger_68
+    logger_0 --> logger_69
+    logger_0 --> logger_70
+    logger_0 --> logger_71
+    logger_0 --> logger_72
+    logger_0 --> logger_73
+    logger_0 --> logger_74
+    logger_0 --> logger_75
+    logger_0 --> logger_76
+    logger_0 --> logger_77
+    logger_0 --> logger_78
+    logger_0 --> logger_79
+    logger_0 --> logger_80
+    logger_0 --> logger_81
+    logger_0 --> logger_82
+    logger_82 --> logger_83
+    logger_0 --> logger_84
+    logger_0 --> logger_85
+    logger_0 --> logger_86

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

@@ -0,0 +1,77 @@
+(deep_dive_logging)=
+# Logging in Conda
+
+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 when logging output is immediately destined for the console, regardless of any other logging configuration that may happen in Conda or in user code.
+- `conda.stdout`
+- `conda.stderr`
+- `conda.stdoutlog`
+- `conda.stderrlog`
+- `conda.stdout.verbose`
+
+### Other loggers
+
+Three more loggers are used in `conda`:
+- `progress.update`
+- `progress.stop`
+- `auxlib`
+
+## Handlers
+
+### Auxlib
+
+The `'auxlib'` logger get's a {class}`conda.auxlib.NullHandler`.
+
+## Open questions
+
+### Potential affect of 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.
+
+(full-module-loggers)=
+## Full module level logger hierarchy
+
+```{mermaid} loggers.mmd
+:caption: All loggers used in the `conda` package and its subpackages.
+:zoom:
+
+```

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