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

This way, running `slapos request n https://software.url` does not emit
logs when fetching the software schema, but it does when using the
`--verbose` flag.

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):