testnode: don't log distributor URL

plus a few python3 fixes for problem that appeared now that we have more test coverage

See merge request !1128

erp5/tests/testERP5TestNode.py

@@ -618,6 +618,49 @@ shared = true
     test_node.purgeOldTestSuite(test_suite_data) # should not fail
     self.assertEqual([], os.listdir(self.working_directory))
 
+  def test_distributor_url_obfuscated_in_logs(self):
+    test_node = self.getTestNode()
+
+    runner = test_type_registry['UnitTest'](test_node)
+    node_test_suite = test_node.getNodeTestSuite('foo')
+    self.updateNodeTestSuiteData(node_test_suite)
+    node_test_suite.revision_list = ('dummy', (0, '')),
+
+    path = runner.getInstanceRoot(node_test_suite) + '/a/bin/runTestSuite'
+    os.makedirs(os.path.dirname(path))
+    with tempfile.NamedTemporaryFile(mode='r') as temp_file:
+      with open(path, 'w') as f:
+        f.write("""#!/bin/sh
+        echo runTestSuite called with: "$@" | tee {}
+        """.format(temp_file.name))
+      os.chmod(path, 0o700)
+
+      with mock.patch.object(logger, '_log') as http_logger,\
+          mock.patch.object(logging.getLogger(), '_log') as root_logger,\
+          mock.patch.object(logging.getLogger(), 'isEnabledFor', return_value=True):
+        runner.runTestSuite(node_test_suite, "https://user:secret@example.com/portal_distributions")
+      http_logger.assert_called()
+      logged_messages = [str(logged) for logged in http_logger.mock_calls]
+
+      # distributor URL is not displayed in logs
+      self.assertFalse([m for m in logged_messages if "https://user:secret@example.com/portal_distributions" in m])
+      # instead we display obfuscated $DISTRIBUTOR_URL
+      self.assertTrue([m for m in logged_messages if "--master_url $DISTRIBUTOR_URL" in m])
+
+      # but the runTestSuite program is called with the actual distributor URL
+      self.assertEqual(
+        'runTestSuite called with: --master_url https://user:secret@example.com/portal_distributions'
+        ' --revision dummy=0- --test_suite Foo --test_suite_title Foo-Test',
+        temp_file.read().strip())
+
+      # The root logger (which logs only in var/log/erp5testnode.log) contain the non obfuscated
+      # command, because it's sometimes useful for debugging.
+      root_logger.assert_called()
+      self.assertIn(
+          '--master_url https://user:secret@example.com/portal_distributions',
+          str(root_logger.mock_calls[-1]))
+
+
   def test_09_runTestSuite(self, my_test_type='UnitTest'):
     """
     Check parameters passed to runTestSuite
@@ -629,11 +672,11 @@ shared = true
     parser.add_argument('--hello_world', help='Hello world!')
     def spawn(*args, **kw):
       if args[1] == '--help':
-        return {'stdout': parser.format_help()}
+        return {'stdout': parser.format_help().encode()}
       call_parameter_list.append(args)
 
     test_node = self.getTestNode()
-    test_node.process_manager.spawn = spawn
+    with mock.patch.object(test_node.process_manager, 'spawn', side_effect=spawn):
       runner = test_type_registry[my_test_type](test_node)
       # Create and initialise/regenerate a nodetestsuite
       node_test_suite = test_node.getNodeTestSuite('foo')

erp5/util/testnode/ProcessManager.py

@@ -68,7 +68,7 @@ def format_command(*args, **kw):
     cmdline.append(v)
   return ' '.join(cmdline)
 
-def subprocess_capture(p, log_prefix, get_output=True):
+def subprocess_capture(p, log_prefix, get_output=True, output_replacers=()):
   log = logger.info
   if log_prefix:
     log_prefix += ': '
@@ -77,6 +77,8 @@ def subprocess_capture(p, log_prefix, get_output=True):
       data = input.readline()
       if not data:
         break
+      for replacer in output_replacers:
+        data = replacer(data)
       if get_output:
         buffer.append(data)
       log(log_prefix + (data if str is bytes else
@@ -158,6 +160,8 @@ class ProcessManager(object):
     log_prefix = kw.pop('log_prefix', '')
     new_session = kw.pop('new_session', True)
     subprocess_kw = {}
+
+    output_replacers = kw.pop('output_replacers', ())
     cwd = kw.pop('cwd', None)
     if cwd:
       subprocess_kw['cwd'] = cwd
@@ -166,6 +170,9 @@ class ProcessManager(object):
     raise_error_if_fail = kw.pop('raise_error_if_fail', True)
     env = dict(os.environ, **kw) if kw else None
     command = format_command(*args, **kw)
+    # obfuscate secrets from command, assuming command is utf-8
+    for replacer in output_replacers:
+      command = replacer(command.encode('utf-8')).decode('utf-8')
     logger.info('subprocess_kw : %r', subprocess_kw)
     logger.info('$ %s', command)
     sys.stdout.flush()
@@ -176,7 +183,7 @@ class ProcessManager(object):
     timer = threading.Timer(self.max_timeout, timeoutExpired, args=(p,))
     self.timer_set.add(timer)
     timer.start()
-    stdout, stderr = subprocess_capture(p, log_prefix, get_output=get_output)
+    stdout, stderr = subprocess_capture(p, log_prefix, get_output=get_output, output_replacers=output_replacers)
     timer.cancel()
     self.timer_set.discard(timer)
     result = dict(status_code=p.returncode, command=command,
@@ -189,8 +196,9 @@ class ProcessManager(object):
     return result
 
   def getSupportedParameterList(self, program_path):
-    return re.findall(r'^  (--\w+)',
-      self.spawn(program_path, '--help')['stdout'], re.M)
+    # type: (str) -> Sequence[str]
+    return (parameter.decode('utf-8') for parameter in
+        re.findall(br'^  (--\w+)', self.spawn(program_path, '--help')['stdout'], re.M))
 
   def killall(self, path):
     """

erp5/util/testnode/UnitTestRunner.py

@@ -27,8 +27,10 @@
 import os
 import glob
 import json
+import logging
+
 from . import logger
-from .ProcessManager import SubprocessError
+from .ProcessManager import SubprocessError, format_command
 from .SlapOSControler import SlapOSControler
 from .Utils import createFolder
 from slapos.grid.utils import md5digest
@@ -180,9 +182,22 @@ class UnitTestRunner(object):
     # result. We only do cleanup if the test runner itself is not able
     # to run.
     createFolder(node_test_suite.test_suite_directory, clean=True)
+
+    # Log the actual command with root logger
+    root_logger = logging.getLogger()
+    root_logger.info(
+        "Running test suite with: %s",
+        format_command(*invocation_list, PATH=PATH))
+
+    def hide_distributor_url(s):
+      # type: (bytes) -> bytes
+      return s.replace(portal_url.encode('utf-8'), b'$DISTRIBUTOR_URL')
+
     self.testnode.process_manager.spawn(*invocation_list, PATH=PATH,
                           cwd=node_test_suite.test_suite_directory,
-                          log_prefix='runTestSuite', get_output=False)
+                          log_prefix='runTestSuite',
+                          output_replacers=(hide_distributor_url,),
+                          get_output=False)
 
   def getRelativePathUsage(self):
     """