update logging to log to console and celery systemd units

etc/patchman/local_settings.py

@@ -96,3 +96,20 @@
         'schedule': timedelta(hours=24),
     },
 }
+
+LOGGING = {
+    'version': 1,
+    'disable_existing_loggers': False,
+    'handlers': {
+        'console': {
+            'class': 'logging.StreamHandler',
+        },
+    },
+    'root': {
+        'handlers': ['console'],
+    },
+    'loggers': {
+        'urllib3': {'level': 'WARNING', 'handlers': ['console'], 'propagate': False},
+        'git': {'level': 'WARNING', 'handlers': ['console'], 'propagate': False},
+    }
+}

patchman/receivers.py

@@ -18,13 +18,13 @@
 from colorama import Fore, Style, init
 from django.conf import settings
 from django.dispatch import receiver
-from tqdm import tqdm
+from tqdm.contrib.logging import logging_redirect_tqdm
 
 from patchman.signals import (
     debug_message_s, error_message_s, info_message_s, pbar_start, pbar_update,
     warning_message_s,
 )
-from util import create_pbar, get_verbosity, update_pbar
+from util.logging import create_pbar, get_quiet_mode, logger, update_pbar
 
 init(autoreset=True)
 
@@ -53,17 +53,20 @@ def print_info_message(**kwargs):
     """ Receiver to handle an info message, no color
     """
     text = str(kwargs.get('text'))
-    if get_verbosity():
-        tqdm.write(Style.RESET_ALL + Fore.RESET + text)
+    if not get_quiet_mode():
+        with logging_redirect_tqdm(loggers=[logger]):
+            for line in text.splitlines():
+                logger.info(Style.RESET_ALL + Fore.RESET + line)
 
 
 @receiver(warning_message_s)
 def print_warning_message(**kwargs):
     """ Receiver to handle a warning message, yellow text
     """
     text = str(kwargs.get('text'))
-    if get_verbosity():
-        tqdm.write(Style.BRIGHT + Fore.YELLOW + text)
+    if not get_quiet_mode():
+        with logging_redirect_tqdm():
+            logger.warning(Style.BRIGHT + Fore.YELLOW + text)
 
 
 @receiver(error_message_s)
@@ -72,13 +75,15 @@ def print_error_message(**kwargs):
     """
     text = str(kwargs.get('text'))
     if text:
-        tqdm.write(Style.BRIGHT + Fore.RED + text)
+        with logging_redirect_tqdm():
+            logger.error(Style.BRIGHT + Fore.RED + text)
 
 
 @receiver(debug_message_s)
 def print_debug_message(**kwargs):
-    """ Receiver to handle a debug message, blue text if verbose and DEBUG are set
+    """ Receiver to handle a debug message, blue text if DEBUG is set
     """
     text = str(kwargs.get('text'))
-    if get_verbosity() and settings.DEBUG and text:
-        tqdm.write(Style.BRIGHT + Fore.BLUE + text)
+    if settings.DEBUG and text:
+        with logging_redirect_tqdm(loggers=[logger]):
+            logger.debug(Style.BRIGHT + Fore.BLUE + text)

reports/utils.py

@@ -34,7 +34,7 @@
 from patchman.signals import pbar_start, pbar_update
 from repos.models import Mirror, MirrorPackage, Repository
 from repos.utils import get_or_create_repo
-from util.logging import info_message
+from util.logging import debug_message, info_message
 
 
 def process_repos(report, host):
@@ -47,6 +47,7 @@ def process_repos(report, host):
 
         pbar_start.send(sender=None, ptext=f'{host} Repos', plen=len(repos))
         for i, repo_str in enumerate(repos):
+            debug_message(f'Processing report {report.id} repo: {repo_str}')
             repo, priority = process_repo(repo_str, report.arch)
             if repo:
                 repo_ids.append(repo.id)
@@ -93,6 +94,7 @@ def process_packages(report, host):
         packages = parse_packages(report.packages)
         pbar_start.send(sender=None, ptext=f'{host} Packages', plen=len(packages))
         for i, pkg_str in enumerate(packages):
+            debug_message(f'Processing report {report.id} package: {pkg_str}')
             package = process_package(pkg_str, report.protocol)
             if package:
                 package_ids.append(package.id)

repos/repo_types/arch.py

@@ -51,7 +51,7 @@ def refresh_arch_repo(repo):
         package_data = fetch_mirror_data(
             mirror=mirror,
             url=mirror_url,
-            text='Fetching Repo data')
+            text='Fetching Arch Repo data')
         if not package_data:
             continue
 

repos/repo_types/deb.py

@@ -95,7 +95,7 @@ def refresh_deb_repo(repo):
         package_data = fetch_mirror_data(
             mirror=mirror,
             url=mirror_url,
-            text='Fetching Repo data')
+            text='Fetching Debian Repo data')
         if not package_data:
             continue
 

repos/repo_types/gentoo.py

@@ -51,7 +51,7 @@ def refresh_gentoo_main_repo(repo):
             continue
 
         res = get_url(mirror.url + '.md5sum')
-        data = fetch_content(res, 'Fetching Repo checksum')
+        data = fetch_content(res, 'Fetching Gentoo Repo checksum')
         if data is None:
             mirror.fail()
             continue
@@ -72,7 +72,7 @@ def refresh_gentoo_main_repo(repo):
             mirror.fail()
             continue
 
-        data = fetch_content(res, 'Fetching Repo data')
+        data = fetch_content(res, 'Fetching Gentoo Repo data')
         if data is None:
             mirror.fail()
             continue

repos/repo_types/rpm.py

@@ -84,7 +84,7 @@ def refresh_rpm_repo_mirrors(repo, errata_only=False):
         repo_data = fetch_mirror_data(
             mirror=mirror,
             url=mirror_url,
-            text='Fetching Repo data')
+            text='Fetching rpm Repo data')
         if not repo_data:
             continue
 

repos/utils.py

@@ -155,7 +155,7 @@ def get_mirrorlist_urls(url):
         return
     if response_is_valid(res):
         try:
-            data = fetch_content(res, 'Fetching Repo data')
+            data = fetch_content(res, 'Fetching Repo data to check for mirrorlist')
             if data is None:
                 return
             mirror_urls = re.findall(r'^http[s]*://.*$|^ftp://.*$', data.decode('utf-8'), re.MULTILINE)

sbin/patchman

@@ -47,8 +47,8 @@ from reports.tasks import remove_reports_with_no_hosts
 from repos.models import Repository
 from repos.utils import clean_repos
 from security.utils import update_cves, update_cwes
-from util import get_datetime_now, set_verbosity
-from util.logging import info_message
+from util import get_datetime_now
+from util.logging import info_message, set_quiet_mode
 
 
 def get_host(host=None, action='Performing action'):
@@ -547,7 +547,7 @@ def main():
 
     parser = collect_args()
     args = parser.parse_args()
-    set_verbosity(not args.quiet)
+    set_quiet_mode(args.quiet)
     showhelp = process_args(args)
     if showhelp:
         parser.print_help()

util/__init__.py

@@ -41,12 +41,14 @@
 from tenacity import (
     retry, retry_if_exception_type, stop_after_attempt, wait_exponential,
 )
-from tqdm import tqdm
 
-from util.logging import debug_message, error_message, info_message
+from util.logging import (
+    create_pbar, debug_message, error_message, info_message, quiet_mode,
+    update_pbar,
+)
 
 pbar = None
-verbose = None
+verbose = not quiet_mode
 Checksum = Enum('Checksum', 'md5 sha sha1 sha256 sha512')
 
 http_proxy = os.getenv('http_proxy')
@@ -57,40 +59,6 @@
 }
 
 
-def get_verbosity():
-    """ Get the global verbosity level
-    """
-    return verbose
-
-
-def set_verbosity(value):
-    """ Set the global verbosity level
-    """
-    global verbose
-    verbose = value
-
-
-def create_pbar(ptext, plength, ljust=35, **kwargs):
-    """ Create a global progress bar if global verbose is True
-    """
-    global pbar
-    if verbose and plength > 0:
-        jtext = str(ptext).ljust(ljust)
-        pbar = tqdm(total=plength, desc=jtext, position=0, leave=True, ascii=' >=')
-        return pbar
-
-
-def update_pbar(index, **kwargs):
-    """ Update the global progress bar if global verbose is True
-    """
-    global pbar
-    if verbose and pbar:
-        pbar.update(n=index-pbar.n)
-        if index >= pbar.total:
-            pbar.close()
-            pbar = None
-
-
 def fetch_content(response, text='', ljust=35):
     """ Display a progress bar to fetch the request content if verbose is
         True. Otherwise, just return the request content

util/logging.py

@@ -15,28 +15,73 @@
 # along with Patchman. If not, see <http://www.gnu.org/licenses/>
 
 
-from datetime import datetime
+import logging
+
+from django.conf import settings
+from tqdm import tqdm
 
 from patchman.signals import (
     debug_message_s, error_message_s, info_message_s, warning_message_s,
 )
 
+log_format = '[%(asctime)s] %(levelname)s: %(message)s'
+if settings.DEBUG:
+    logging_level = logging.DEBUG
+else:
+    logging_level = logging.INFO
+logging.basicConfig(level=logging_level, format=log_format)
+logger = logging.getLogger()
+logging.getLogger('git.cmd').setLevel(logging.WARNING)
+
+quiet_mode = False
+pbar = None
+
+
+def get_quiet_mode():
+    """ Get the global quiet_mode
+    """
+    return quiet_mode
+
+
+def set_quiet_mode(value):
+    """ Set the global quiet_mode
+    """
+    global quiet_mode
+    quiet_mode = value
+
+
+def create_pbar(ptext, plength, ljust=35, **kwargs):
+    """ Create a global progress bar if global quiet_mode is False
+    """
+    global pbar
+    if not quiet_mode and plength > 0:
+        jtext = str(ptext).ljust(ljust)
+        pbar = tqdm(total=plength, desc=jtext, position=0, leave=True, ascii=' >=')
+        return pbar
+
+
+def update_pbar(index, **kwargs):
+    """ Update the global progress bar if global quiet_mode is False
+    """
+    global pbar
+    if not quiet_mode and pbar:
+        pbar.update(n=index-pbar.n)
+        if index >= pbar.total:
+            pbar.close()
+            pbar = None
+
 
 def info_message(text):
-    ts = datetime.now()
-    info_message_s.send(sender=None, text=text, ts=ts)
+    info_message_s.send(sender=None, text=text)
 
 
 def warning_message(text):
-    ts = datetime.now()
-    warning_message_s.send(sender=None, text=text, ts=ts)
+    warning_message_s.send(sender=None, text=text)
 
 
 def debug_message(text):
-    ts = datetime.now()
-    debug_message_s.send(sender=None, text=text, ts=ts)
+    debug_message_s.send(sender=None, text=text)
 
 
 def error_message(text):
-    ts = datetime.now()
-    error_message_s.send(sender=None, text=text, ts=ts)
+    error_message_s.send(sender=None, text=text)