Avoid calling root-level logging functions

Instead, establish a named logger in each module. This will allow for
easier filtering of log messages if we ever expand the use of the
logging module.

Closes: https://github.com/gentoo/portage/pull/849
Signed-off-by: Mike Gilbert <floppym@gentoo.org>

9 files changed, 79 insertions, 67 deletions

diff --git a/bin/doins.py b/bin/doins.py
index 087756218..7905c5c0d 100644
--- a/bin/doins.py
+++ b/bin/doins.py
@@ -26,6 +26,8 @@ import sys
 from portage.util import movefile
 from portage.util.file_copy import copyfile
 
+logger = logging.getLogger("portage.bin.doins")
+
 
 def _warn(helper, msg):
     """Output warning message to stderr.
@@ -199,7 +201,7 @@ class _InsInProcessInstallRunner:
             if self._parsed_options.preserve_timestamps:
                 _set_timestamps(sstat, dest)
         except Exception:
-            logging.exception(
+            logger.exception(
                 "Failed to copy file: " "_parsed_options=%r, source=%r, dest_dir=%r",
                 self._parsed_options,
                 source,
@@ -383,7 +385,7 @@ class _InstallRunner:
         except Exception:
             if self._helpers_can_die:
                 raise
-            logging.exception("install_dir failed.")
+            logger.exception("install_dir failed.")
 
 
 def _doins(opts, install_runner, relpath, source_root):
@@ -428,7 +430,7 @@ def _doins(opts, install_runner, relpath, source_root):
                 os.symlink(linkto, dest)
                 return True
         except Exception:
-            logging.exception(
+            logger.exception(
                 "Failed to create symlink: " "opts=%r, relpath=%r, source_root=%r",
                 opts,
                 relpath,
diff --git a/lib/portage/_emirrordist/Config.py b/lib/portage/_emirrordist/Config.py
index 78b7a482a..734313c07 100644
--- a/lib/portage/_emirrordist/Config.py
+++ b/lib/portage/_emirrordist/Config.py
@@ -12,6 +12,8 @@ from portage.package.ebuild.fetch import MirrorLayoutConfig
 from portage.util import grabdict, grablines
 from .ContentDB import ContentDB
 
+logger = logging.getLogger(__name__)
+
 
 class Config:
     def __init__(self, options, portdb, event_loop):
@@ -89,13 +91,11 @@ class Config:
     def _open_log(self, log_desc, log_path, mode):
 
         if log_path is None or getattr(self.options, "dry_run", False):
-            log_func = logging.info
+            log_func = logger.info
             line_format = "%s: %%s" % log_desc
             add_newline = False
             if log_path is not None:
-                logging.warning(
-                    "dry-run: %s log " "redirected to logging.info" % log_desc
-                )
+                logger.warning("dry-run: %s log redirected to logging.info" % log_desc)
         else:
             self._open_files.append(io.open(log_path, mode=mode, encoding="utf_8"))
             line_format = "%s\n"
@@ -137,7 +137,7 @@ class Config:
                     db = dbshelve.open(db_file, flags=open_flag)
 
         if dry_run:
-            logging.warning("dry-run: %s db opened in readonly mode" % db_desc)
+            logger.warning("dry-run: %s db opened in readonly mode" % db_desc)
             if not isinstance(db, dict):
                 volatile_db = dict((k, db[k]) for k in db)
                 db.close()
diff --git a/lib/portage/_emirrordist/ContentDB.py b/lib/portage/_emirrordist/ContentDB.py
index 6a5efbe95..ac6140257 100644
--- a/lib/portage/_emirrordist/ContentDB.py
+++ b/lib/portage/_emirrordist/ContentDB.py
@@ -8,6 +8,8 @@ import typing
 
 from portage.package.ebuild.fetch import DistfileName
 
+logger = logging.getLogger(__name__)
+
 
 class ContentDB:
     """
@@ -110,10 +112,10 @@ class ContentDB:
                             pass
 
             if remaining:
-                logging.debug(("drop '%s' revision(s) from content db") % filename)
+                logger.debug(("drop '%s' revision(s) from content db") % filename)
                 self._shelve[distfile_key] = remaining
             else:
-                logging.debug(("drop '%s' from content db") % filename)
+                logger.debug(("drop '%s' from content db") % filename)
                 try:
                     del self._shelve[distfile_key]
                 except KeyError:
diff --git a/lib/portage/_emirrordist/DeletionIterator.py b/lib/portage/_emirrordist/DeletionIterator.py
index 59abce82f..6273ad281 100644
--- a/lib/portage/_emirrordist/DeletionIterator.py
+++ b/lib/portage/_emirrordist/DeletionIterator.py
@@ -9,6 +9,8 @@ from portage import os
 from portage.package.ebuild.fetch import DistfileName
 from .DeletionTask import DeletionTask
 
+logger = logging.getLogger(__name__)
+
 
 class DeletionIterator:
     def __init__(self, config):
@@ -61,7 +63,7 @@ class DeletionIterator:
                         break
             else:
                 if exceptions:
-                    logging.error(
+                    logger.error(
                         "stat failed on '%s' in distfiles: %s\n"
                         % (filename, "; ".join(str(x) for x in exceptions))
                     )
@@ -103,7 +105,7 @@ class DeletionIterator:
                     deletion_entry = deletion_db.get(filename)
 
                     if deletion_entry is None:
-                        logging.debug("add '%s' to deletion db" % filename)
+                        logger.debug("add '%s' to deletion db" % filename)
                         deletion_db[filename] = start_time
 
                     elif deletion_entry + deletion_delay <= start_time:
@@ -123,4 +125,4 @@ class DeletionIterator:
                     except KeyError:
                         pass
                     else:
-                        logging.debug("drop '%s' from deletion db" % filename)
+                        logger.debug("drop '%s' from deletion db" % filename)
diff --git a/lib/portage/_emirrordist/DeletionTask.py b/lib/portage/_emirrordist/DeletionTask.py
index 7066e57a7..a5d96a9d9 100644
--- a/lib/portage/_emirrordist/DeletionTask.py
+++ b/lib/portage/_emirrordist/DeletionTask.py
@@ -9,6 +9,8 @@ from portage.package.ebuild.fetch import ContentHashLayout
 from portage.util._async.FileCopier import FileCopier
 from _emerge.CompositeTask import CompositeTask
 
+logger = logging.getLogger(__name__)
+
 
 class DeletionTask(CompositeTask):
 
@@ -18,19 +20,17 @@ class DeletionTask(CompositeTask):
         if self.config.options.recycle_dir is not None:
             recycle_path = os.path.join(self.config.options.recycle_dir, self.distfile)
             if self.config.options.dry_run:
-                logging.info(
+                logger.info(
                     ("dry-run: move '%s' from " "distfiles to recycle") % self.distfile
                 )
             else:
-                logging.debug(
-                    ("move '%s' from " "distfiles to recycle") % self.distfile
-                )
+                logger.debug(("move '%s' from " "distfiles to recycle") % self.distfile)
                 try:
                     # note: distfile_path can be a symlink here
                     os.rename(os.path.realpath(self.distfile_path), recycle_path)
                 except OSError as e:
                     if e.errno != errno.EXDEV:
-                        logging.error(
+                        logger.error(
                             ("rename %s from distfiles to " "recycle failed: %s")
                             % (self.distfile, e)
                         )
@@ -52,14 +52,14 @@ class DeletionTask(CompositeTask):
         success = True
 
         if self.config.options.dry_run:
-            logging.info(("dry-run: delete '%s' from " "distfiles") % self.distfile)
+            logger.info(("dry-run: delete '%s' from " "distfiles") % self.distfile)
         else:
-            logging.debug(("delete '%s' from " "distfiles") % self.distfile)
+            logger.debug(("delete '%s' from " "distfiles") % self.distfile)
             try:
                 os.unlink(self.distfile_path)
             except OSError as e:
                 if e.errno not in (errno.ENOENT, errno.ESTALE):
-                    logging.error(
+                    logger.error(
                         "%s unlink failed in distfiles: %s" % (self.distfile, e)
                     )
                     success = False
@@ -85,13 +85,13 @@ class DeletionTask(CompositeTask):
                 os.unlink(copier.src_path)
             except OSError as e:
                 if e.errno not in (errno.ENOENT, errno.ESTALE):
-                    logging.error(
+                    logger.error(
                         "%s unlink failed in distfiles: %s" % (self.distfile, e)
                     )
                     success = False
 
         else:
-            logging.error(
+            logger.error(
                 ("%s copy from distfiles " "to recycle failed: %s")
                 % (self.distfile, copier.future.exception())
             )
@@ -109,7 +109,7 @@ class DeletionTask(CompositeTask):
         success = True
         for layout in self.config.layouts:
             if isinstance(layout, ContentHashLayout) and not self.distfile.digests:
-                logging.debug(("_delete_links: '%s' has " "no digests") % self.distfile)
+                logger.debug(("_delete_links: '%s' has " "no digests") % self.distfile)
                 continue
             distfile_path = os.path.join(
                 self.config.options.distfiles, layout.get_path(self.distfile)
@@ -118,7 +118,7 @@ class DeletionTask(CompositeTask):
                 os.unlink(distfile_path)
             except OSError as e:
                 if e.errno not in (errno.ENOENT, errno.ESTALE):
-                    logging.error(
+                    logger.error(
                         "%s unlink failed in distfiles: %s" % (self.distfile, e)
                     )
                     success = False
@@ -144,7 +144,7 @@ class DeletionTask(CompositeTask):
             except KeyError:
                 pass
             else:
-                logging.debug(("drop '%s' from " "distfiles db") % self.distfile)
+                logger.debug(("drop '%s' from " "distfiles db") % self.distfile)
 
         if self.config.content_db is not None:
             self.config.content_db.remove(self.distfile)
@@ -155,4 +155,4 @@ class DeletionTask(CompositeTask):
             except KeyError:
                 pass
             else:
-                logging.debug(("drop '%s' from " "deletion db") % self.distfile)
+                logger.debug(("drop '%s' from " "deletion db") % self.distfile)
diff --git a/lib/portage/_emirrordist/FetchTask.py b/lib/portage/_emirrordist/FetchTask.py
index 304837332..89fd1657e 100644
--- a/lib/portage/_emirrordist/FetchTask.py
+++ b/lib/portage/_emirrordist/FetchTask.py
@@ -17,6 +17,8 @@ from portage.util._async.PipeLogger import PipeLogger
 from portage.util._async.PopenProcess import PopenProcess
 from _emerge.CompositeTask import CompositeTask
 
+logger = logging.getLogger(__name__)
+
 default_hash_name = portage.const.MANIFEST2_HASH_DEFAULT
 
 # Use --no-check-certificate since Manifest digests should provide
@@ -91,7 +93,7 @@ class FetchTask(CompositeTask):
                     self.scheduler.output(
                         msg + "\n", background=True, log_path=self._log_path
                     )
-                    logging.error(msg)
+                    logger.error(msg)
             else:
                 break
 
@@ -100,7 +102,7 @@ class FetchTask(CompositeTask):
         if not size_ok:
             if self.config.options.dry_run:
                 if st is not None:
-                    logging.info(
+                    logger.info(
                         ("dry-run: delete '%s' with " "wrong size from distfiles")
                         % (self.distfile,)
                     )
@@ -115,7 +117,7 @@ class FetchTask(CompositeTask):
                     )
                     if self._unlink_file(unlink_path, "distfiles"):
                         if st is not None:
-                            logging.debug(
+                            logger.debug(
                                 ("delete '%s' with " "wrong size from distfiles")
                                 % (self.distfile,)
                             )
@@ -172,14 +174,14 @@ class FetchTask(CompositeTask):
 
             if self.config.options.dry_run:
                 if os.path.exists(recycle_file):
-                    logging.info("dry-run: delete '%s' from recycle" % (self.distfile,))
+                    logger.info("dry-run: delete '%s' from recycle" % (self.distfile,))
             else:
                 try:
                     os.unlink(recycle_file)
                 except OSError:
                     pass
                 else:
-                    logging.debug("delete '%s' from recycle" % (self.distfile,))
+                    logger.debug("delete '%s' from recycle" % (self.distfile,))
 
     def _distfiles_digester_exit(self, digester):
 
@@ -195,7 +197,7 @@ class FetchTask(CompositeTask):
             # from the administrator.
             msg = "%s distfiles digester failed unexpectedly" % (self.distfile,)
             self.scheduler.output(msg + "\n", background=True, log_path=self._log_path)
-            logging.error(msg)
+            logger.error(msg)
             self.config.log_failure("%s\t%s\t%s" % (self.cpv, self.distfile, msg))
             self.config.file_failures[self.distfile] = self.cpv
             self.wait()
@@ -312,7 +314,7 @@ class FetchTask(CompositeTask):
                 self.scheduler.output(
                     msg + "\n", background=True, log_path=self._log_path
                 )
-                logging.error(msg)
+                logger.error(msg)
         else:
             size_ok = st.st_size == self.digests["size"]
             self._current_stat = st
@@ -345,7 +347,7 @@ class FetchTask(CompositeTask):
                 current_mirror.name,
             )
             self.scheduler.output(msg + "\n", background=True, log_path=self._log_path)
-            logging.error(msg)
+            logger.error(msg)
         else:
             bad_digest = self._find_bad_digest(digester.digests)
             if bad_digest is not None:
@@ -359,18 +361,18 @@ class FetchTask(CompositeTask):
                 self.scheduler.output(
                     msg + "\n", background=True, log_path=self._log_path
                 )
-                logging.error(msg)
+                logger.error(msg)
             elif self.config.options.dry_run:
                 # Report success without actually touching any files
                 if self._same_device(
                     current_mirror.location, self.config.options.distfiles
                 ):
-                    logging.info(
+                    logger.info(
                         ("dry-run: hardlink '%s' from %s " "to distfiles")
                         % (self.distfile, current_mirror.name)
                     )
                 else:
-                    logging.info(
+                    logger.info(
                         "dry-run: copy '%s' from %s to distfiles"
                         % (self.distfile, current_mirror.name)
                     )
@@ -387,7 +389,7 @@ class FetchTask(CompositeTask):
                 if self._hardlink_atomic(
                     src, dest, "%s to %s" % (current_mirror.name, "distfiles")
                 ):
-                    logging.debug(
+                    logger.debug(
                         "hardlink '%s' from %s to distfiles"
                         % (self.distfile, current_mirror.name)
                     )
@@ -424,10 +426,10 @@ class FetchTask(CompositeTask):
                 copier.future.exception(),
             )
             self.scheduler.output(msg + "\n", background=True, log_path=self._log_path)
-            logging.error(msg)
+            logger.error(msg)
         else:
 
-            logging.debug(
+            logger.debug(
                 "copy '%s' from %s to distfiles" % (self.distfile, current_mirror.name)
             )
 
@@ -447,7 +449,7 @@ class FetchTask(CompositeTask):
                 self.scheduler.output(
                     msg + "\n", background=True, log_path=self._log_path
                 )
-                logging.error(msg)
+                logger.error(msg)
 
             self._success()
             self.returncode = os.EX_OK
@@ -460,7 +462,7 @@ class FetchTask(CompositeTask):
 
         if self.config.options.dry_run:
             # Simply report success.
-            logging.info("dry-run: fetch '%s' from '%s'" % (self.distfile, uri))
+            logger.info("dry-run: fetch '%s' from '%s'" % (self.distfile, uri))
             self._success()
             self.returncode = os.EX_OK
             self._async_wait()
@@ -543,7 +545,7 @@ class FetchTask(CompositeTask):
                 self._fetch_tmp_dir_info,
             )
             self.scheduler.output(msg + "\n", background=True, log_path=self._log_path)
-            logging.error(msg)
+            logger.error(msg)
         else:
             bad_digest = self._find_bad_digest(digester.digests)
             if bad_digest is not None:
@@ -608,7 +610,7 @@ class FetchTask(CompositeTask):
                 copier.future.exception(),
             )
             self.scheduler.output(msg + "\n", background=True, log_path=self._log_path)
-            logging.error(msg)
+            logger.error(msg)
             self.config.log_failure("%s\t%s\t%s" % (self.cpv, self.distfile, msg))
             self.config.file_failures[self.distfile] = self.cpv
             self.returncode = 1
@@ -662,7 +664,7 @@ class FetchTask(CompositeTask):
                 self.scheduler.output(
                     msg + "\n", background=True, log_path=self._log_path
                 )
-                logging.error(msg)
+                logger.error(msg)
                 return False
         return True
 
@@ -720,7 +722,7 @@ class FetchTask(CompositeTask):
                     self.scheduler.output(
                         msg + "\n", background=True, log_path=self._log_path
                     )
-                    logging.error(msg)
+                    logger.error(msg)
                 return False
 
             try:
@@ -734,7 +736,7 @@ class FetchTask(CompositeTask):
                 self.scheduler.output(
                     msg + "\n", background=True, log_path=self._log_path
                 )
-                logging.error(msg)
+                logger.error(msg)
                 return False
         finally:
             try:
diff --git a/lib/portage/_emirrordist/MirrorDistTask.py b/lib/portage/_emirrordist/MirrorDistTask.py
index 28164e645..9423125df 100644
--- a/lib/portage/_emirrordist/MirrorDistTask.py
+++ b/lib/portage/_emirrordist/MirrorDistTask.py
@@ -17,6 +17,8 @@ from _emerge.CompositeTask import CompositeTask
 from .FetchIterator import FetchIterator
 from .DeletionIterator import DeletionIterator
 
+logger = logging.getLogger(__name__)
+
 
 class MirrorDistTask(CompositeTask):
 
@@ -99,14 +101,14 @@ class MirrorDistTask(CompositeTask):
                 st = os.stat(recycle_file)
             except OSError as e:
                 if e.errno not in (errno.ENOENT, errno.ESTALE):
-                    logging.error(
+                    logger.error(
                         ("stat failed for '%s' in " "recycle: %s") % (filename, e)
                     )
                 continue
 
             value = recycle_db_cache.pop(filename, None)
             if value is None:
-                logging.debug(("add '%s' to " "recycle db") % filename)
+                logger.debug(("add '%s' to " "recycle db") % filename)
                 recycle_db[filename] = (st.st_size, start_time)
             else:
                 r_size, r_time = value
@@ -114,27 +116,25 @@ class MirrorDistTask(CompositeTask):
                     recycle_db[filename] = (st.st_size, start_time)
                 elif r_time + r_deletion_delay < start_time:
                     if self._config.options.dry_run:
-                        logging.info(
-                            ("dry-run: delete '%s' from " "recycle") % filename
-                        )
-                        logging.info(("drop '%s' from " "recycle db") % filename)
+                        logger.info(("dry-run: delete '%s' from " "recycle") % filename)
+                        logger.info(("drop '%s' from " "recycle db") % filename)
                     else:
                         try:
                             os.unlink(recycle_file)
                         except OSError as e:
                             if e.errno not in (errno.ENOENT, errno.ESTALE):
-                                logging.error(
+                                logger.error(
                                     ("delete '%s' from " "recycle failed: %s")
                                     % (filename, e)
                                 )
                         else:
-                            logging.debug(("delete '%s' from " "recycle") % filename)
+                            logger.debug(("delete '%s' from " "recycle") % filename)
                             try:
                                 del recycle_db[filename]
                             except KeyError:
                                 pass
                             else:
-                                logging.debug(
+                                logger.debug(
                                     ("drop '%s' from " "recycle db") % filename
                                 )
 
@@ -147,7 +147,7 @@ class MirrorDistTask(CompositeTask):
             except KeyError:
                 pass
             else:
-                logging.debug(("drop non-existent '%s' from " "recycle db") % filename)
+                logger.debug(("drop non-existent '%s' from " "recycle db") % filename)
 
     def _scheduled_deletion_log(self):
 
@@ -169,7 +169,7 @@ class MirrorDistTask(CompositeTask):
             date_files.append(filename)
 
         if dry_run:
-            logging.warning(
+            logger.warning(
                 "dry-run: scheduled-deletions log "
                 "will be summarized via logging.info"
             )
@@ -178,7 +178,7 @@ class MirrorDistTask(CompositeTask):
         for date in sorted(date_map):
             date_files = date_map[date]
             if dry_run:
-                logging.info(
+                logger.info(
                     ("dry-run: scheduled deletions for %s: %s files")
                     % (date, len(date_files))
                 )
@@ -202,12 +202,12 @@ class MirrorDistTask(CompositeTask):
         added_file_count = self._config.added_file_count
         added_byte_count = self._config.added_byte_count
 
-        logging.info("finished in %i seconds" % elapsed_time)
-        logging.info("failed to fetch %i files" % fail_count)
-        logging.info("deleted %i files" % delete_count)
-        logging.info("deletion of %i files scheduled" % scheduled_deletion_count)
-        logging.info("added %i files" % added_file_count)
-        logging.info("added %i bytes total" % added_byte_count)
+        logger.info("finished in %i seconds" % elapsed_time)
+        logger.info("failed to fetch %i files" % fail_count)
+        logger.info("deleted %i files" % delete_count)
+        logger.info("deletion of %i files scheduled" % scheduled_deletion_count)
+        logger.info("added %i files" % added_file_count)
+        logger.info("added %i bytes total" % added_byte_count)
 
     def _cleanup(self):
         """
diff --git a/lib/portage/eapi.py b/lib/portage/eapi.py
index 2c1701870..969cf9027 100644
--- a/lib/portage/eapi.py
+++ b/lib/portage/eapi.py
@@ -7,6 +7,8 @@ from typing import Optional
 
 from portage import eapi_is_supported
 
+logger = logging.getLogger(__name__)
+
 
 def eapi_has_iuse_defaults(eapi: str) -> bool:
     return _get_eapi_attrs(eapi).iuse_defaults
diff --git a/lib/portage/util/shelve.py b/lib/portage/util/shelve.py
index 6100c8719..85d5829f3 100644
--- a/lib/portage/util/shelve.py
+++ b/lib/portage/util/shelve.py
@@ -5,6 +5,8 @@ import logging
 import pickle
 import shelve
 
+logger = logging.getLogger(__name__)
+
 
 def open_shelve(db_file, flag="r"):
     """
@@ -36,7 +38,7 @@ def dump(args):
                 try:
                     value = src[key]
                 except KeyError:
-                    logging.exception(key)
+                    logger.exception(key)
                     continue
                 pickle.dump((key, value), dest)
     finally: