util: make buildout.download log as debug level when fetching schema

See merge request !721

slapos/cli/cache_pypi.py

@@ -86,7 +86,7 @@ def do_lookup(logger, cache_dir, cache_url, signature_certificate_list,
         logger.info('Python egg %s version %s', name, version)
         logger.info('SHADIR URL: %s/%s\n', cache_dir, key)
 
-        resetLogger(logger)
+        with resetLogger(logger):
             for line in pt.get_string(border=True, padding_width=0, vrules=prettytable.NONE).split('\n'):
                 logger.info(line)
     except HTTPError as e:

slapos/cli/cache_url.py

@@ -84,7 +84,7 @@ def do_lookup(logger, cache_dir, cache_url, signature_certificate_list,
         logger.info('Software source URL: %s', url)
         logger.info('SHADIR URL: %s/%s\n', cache_dir, key)
 
-        resetLogger(logger)
+        with resetLogger(logger):
             for line in pt.get_string(border=True, padding_width=0, vrules=prettytable.NONE).split('\n'):
                 logger.info(line)
     except HTTPError as e:

slapos/cli/command.py

@@ -28,6 +28,7 @@
 ##############################################################################
 
 import argparse
+import contextlib
 import functools
 import logging
 import os
@@ -36,9 +37,20 @@ import sys
 from cliff import command
 
 
+@contextlib.contextmanager
 def resetLogger(logger):
+    has_propagate = hasattr(logger, 'propagate')  # XXX mocked Loggers do not have this
+    if has_propagate:
+        propagate = logger.propagate
         logger.propagate = False
-    logger.addHandler(logging.StreamHandler(sys.stdout))
+    stdout_handler = logging.StreamHandler(sys.stdout)
+    logger.addHandler(stdout_handler)
+    try:
+        yield
+    finally:
+      if has_propagate:
+          logger.propagate = propagate
+      logger.removeHandler(stdout_handler)
 
 
 class Command(command.Command):

slapos/cli/computer_info.py

@@ -58,7 +58,7 @@ class InfoCommand(ClientConfigCommand):
 
 
 def do_info(logger, conf, local):
-    resetLogger(logger)
+    with resetLogger(logger):
       try:
           computer = local['slap'].registerComputer(conf.reference).getInformation()
       except ResourceNotReady:
@@ -70,4 +70,3 @@ def do_info(logger, conf, local):
 
       logger.info('Computer Reference: %s', computer._reference)
       logger.info('Computer Title    : %s', computer._title)
-

slapos/cli/computer_list.py

@@ -51,7 +51,7 @@ class ListCommand(ClientConfigCommand):
 
 
 def do_list(logger, conf, local):
-    resetLogger(logger)
+    with resetLogger(logger):
       computer_dict = local['slap'].getComputerDict()
       if computer_dict == {}:
         logger.info('No existing computer.')

slapos/cli/computer_token.py

@@ -54,7 +54,7 @@ class TokenCommand(ClientConfigCommand):
 
 
 def do_token(logger, conf, local):
-    resetLogger(logger)
+    with resetLogger(logger):
       try:
           token = local['slap'].registerToken().request()
       except ResourceNotReady:
@@ -65,4 +65,3 @@ def do_token(logger, conf, local):
           return(2)
 
       logger.info('Computer token: %s', token)
-

slapos/cli/info.py

@@ -70,7 +70,6 @@ class InfoCommand(ClientConfigCommand):
 
 
 def do_info(logger, conf, local):
-    resetLogger(logger)
     try:
         instance = local['slap'].registerOpenOrder().getInformation(
             partition_reference=conf.reference,
@@ -126,5 +125,6 @@ def do_info(logger, conf, local):
       if conf.news:
           info['news'] = news
 
+    with resetLogger(logger):
       logger.info(json.dumps(info, indent=2))
 

slapos/cli/list.py

@@ -52,9 +52,9 @@ class ListCommand(ClientConfigCommand):
 
 
 def do_list(logger, conf, local):
-    resetLogger(logger)
     # XXX catch exception
     instance_dict = local['slap'].getOpenOrderDict()
+    with resetLogger(logger):
       logger.info(
         json.dumps(
           {title: instance._software_release_url

slapos/tests/test_slapproxy.py

@@ -80,7 +80,6 @@ class BasicMixin(object):
     """
     self._tempdir = tempfile.mkdtemp()
     self._rootdir = self.initRootDir()
-    logging.basicConfig(level=logging.DEBUG)
     self.setFiles()
     self.startProxy()
     os.environ.pop('SLAPGRID_INSTANCE_ROOT', None)

slapos/tests/test_util.py

@@ -36,6 +36,7 @@ import warnings
 from pwd import getpwnam
 
 from six.moves import SimpleHTTPServer
+import six
 
 import slapos.util
 from slapos.testing.utils import ManagedHTTPServer
@@ -469,13 +470,33 @@ class TestSoftwareReleaseSchemaEdgeCases(unittest.TestCase):
     self.assertIn("Unable to load JSON", str(w[0].message))
 
   def test_software_schema_wrong_URL(self):
-    schema = SoftwareReleaseSchema('http://slapos.invalid/software.cfg', None)
+    schema = SoftwareReleaseSchema('http://slapos.invalid/wrong-url/software.cfg', None)
     with warnings.catch_warnings(record=True) as w:
       warnings.simplefilter("always")
       self.assertIsNone(schema.getSoftwareSchema())
     self.assertEqual(len(w), 1)
     self.assertIn("Unable to load JSON", str(w[0].message))
 
+  def test_software_schema_download_does_no_log(self):
+    schema = SoftwareReleaseSchema('http://slapos.invalid/no-log/software.cfg', None)
+    debug_level_log_stream = six.StringIO()
+    debug_level_handler = logging.StreamHandler(debug_level_log_stream)
+    debug_level_handler.setLevel(logging.DEBUG)
+    default_level_log_stream = six.StringIO()
+    default_level_handler = logging.StreamHandler(default_level_log_stream)
+    default_level_handler.setLevel(logging.INFO)
+    logger = logging.getLogger()
+    self.addCleanup(functools.partial(logger.setLevel, logger.getEffectiveLevel()))
+    logger.setLevel(logging.DEBUG)
+    logger.addHandler(debug_level_handler)
+    self.addCleanup(functools.partial(logger.removeHandler, debug_level_handler))
+    logger.addHandler(default_level_handler)
+    self.addCleanup(functools.partial(logger.removeHandler, default_level_handler))
+
+    self.assertIsNone(schema.getSoftwareSchema())
+    self.assertEqual(default_level_log_stream.getvalue(), "")
+    self.assertEqual(debug_level_log_stream.getvalue(), "Downloading http://slapos.invalid/no-log/software.cfg.json\n")
+
 
 if __name__ == '__main__':
   unittest.main()

slapos/util.py

@@ -31,6 +31,7 @@ import enum
 import errno
 import hashlib
 import json
+import logging
 import os
 import pprint
 import shutil
@@ -476,7 +477,14 @@ class SoftwareReleaseSchema(object):
       software_type = None
     self.software_type = software_type or DEFAULT_SOFTWARE_TYPE
     if download is None:
-      download = zc.buildout.download.Download()
+      logger = logging.getLogger(
+        '{__name__}.{self.__class__.__name__}.download'.format(
+          __name__=__name__, self=self))
+      # zc.buildout.download logs in level info "Downloading from <URL>", which is
+      # fine for normal buildout usage, but when downloading software release schemas
+      # we want these messages to be logged with level debug
+      logger.info = logger.debug  # type: ignore
+      download = zc.buildout.download.Download(logger=logger)
     self._download = download.download
 
   def _warn(self, message, e):