testnode: simplify logging

Conflicts:
	erp5/util/testnode/ProcessManager.py

erp5/tests/testERP5TestNode.py

 import unittest
 from unittest import TestCase
+from contextlib import contextmanager
 
+from erp5.util.testnode import logger
 from erp5.util.testnode.testnode import TestNode, test_type_registry
 from erp5.util.testnode.NodeTestSuite import SlapOSInstance, NodeTestSuite
 from erp5.util.testnode.ProcessManager import ProcessManager, SubprocessError
@@ -13,17 +15,26 @@ from erp5.util.testnode.SlapOSControler import createFolder
 from erp5.util.taskdistribution import TaskDistributor
 from erp5.util.taskdistribution import TestResultProxy
 import argparse
+import logging
 import os
 import shutil
 import subprocess
+import sys
 import tempfile
 import json
 import time
 import types
 import re
 
+@contextmanager
+def dummySuiteLog(_):
+  yield
+
 class ERP5TestNode(TestCase):
 
+  _handler = logging.StreamHandler(sys.stdout)
+  _handler.setFormatter(logging.Formatter('TESTNODE LOG: %(message)s'))
+
   def setUp(self):
     self._temp_dir = tempfile.mkdtemp()
     self.working_directory = os.path.join(self._temp_dir, 'testnode')
@@ -49,13 +60,11 @@ class ERP5TestNode(TestCase):
     os.mkdir(self.remote_repository0)
     os.mkdir(self.remote_repository1)
     os.mkdir(self.remote_repository2)
-    def log(*args,**kw):
-      for arg in args:
-        print "TESTNODE LOG : %r, %r" % (arg, kw)
-    self.log = log
+    logging.getLogger().addHandler(self._handler)
 
   def tearDown(self):
     shutil.rmtree(self._temp_dir, True)
+    logging.getLogger().removeHandler(self._handler)
 
   def getTestNode(self):
     # XXX how to get property the git path ?
@@ -80,7 +89,12 @@ class ERP5TestNode(TestCase):
     config["frontend_url"] = "http://frontend/"
     config["software_list"] = ["foo", "bar"]
 
-    return TestNode(self.log, config)
+    testnode = TestNode(config)
+    # By default, keep suite logs to stdout for easier debugging
+    # (stdout/stderr are automatically reported to ERP5).
+    # This is unset by test methods that check normal suite logging.
+    testnode.suiteLog = dummySuiteLog
+    return testnode
 
   def getTestSuiteData(self, add_third_repository=False,
                        add_broken_repository=False, reference="foo"):
@@ -634,13 +648,10 @@ shared = true
             allow_restart=False, test_title=None, project_title=None):
       global counter
       # return no test to check if run method will run the next test suite
-      if counter == 3 and project_title != 'qux':
-        result = None
-      else:
+      if counter != 3 or project_title == 'qux':
         test_result_path = os.path.join(test_result_path_root, test_title)
-        result =  TestResultProxy(self._proxy, self._retry_time,
-                self._logger, test_result_path, node_title, revision)
-      return result
+        return TestResultProxy(self._proxy, self._retry_time,
+                logger, test_result_path, node_title, revision)
     def patch_runTestSuite(self, *argv, **kw):
       return {'status_code':0}
     original_sleep = time.sleep
@@ -707,7 +718,7 @@ shared = true
     def _checkCorrectStatus(expected_status,*args):
       result = process_manager.spawn(*args)
       self.assertEqual(result['status_code'], expected_status)
-    process_manager = ProcessManager(log=self.log, max_timeout=1)
+    process_manager = ProcessManager(max_timeout=1)
     _checkCorrectStatus(0, *['sleep','0'])
     # We must make sure that if the command is too long that
     # it will be automatically killed
@@ -715,8 +726,7 @@ shared = true
 
   def test_13_SlaposControlerResetSoftware(self):
     test_node = self.getTestNode()
-    controler = SlapOSControler(self.working_directory,
-                                test_node.config, self.log)
+    controler = SlapOSControler(self.working_directory, test_node.config)
     os.mkdir(controler.software_root)
     file_name = 'AC_Ra\xc3\xadzertic\xc3\xa1ma'
     non_ascii_file = open(os.path.join(controler.software_root, file_name), 'w')
@@ -778,30 +788,26 @@ shared = true
     def patch_createTestResult(self, revision, test_name_list, node_title,
             allow_restart=False, test_title=None, project_title=None):
       test_result_path = os.path.join(test_result_path_root, test_title)
-      result = TestResultProxy(self._proxy, self._retry_time,
-               self._logger, test_result_path, node_title, revision)
-      return result
+      return TestResultProxy(self._proxy, self._retry_time,
+                logger, test_result_path, node_title, revision)
     def patch_runTestSuite(self,*argv, **kw):
       return {'status_code':0}
     def checkTestSuite(test_node):
       test_node.node_test_suite_dict
       rand_part_set = set()
       self.assertEquals(2, len(test_node.node_test_suite_dict))
-      self.assertIsNot(test_node.suite_log, None)
-      self.assertTrue(isinstance(test_node.suite_log, types.MethodType))
       for ref, suite in test_node.node_test_suite_dict.items():
         self.assertTrue('var/log/testnode/%s' % suite.reference in \
                          suite.suite_log_path,
                          "Incorrect suite log path : %r" % suite.suite_log_path)
-        self.assertTrue(suite.suite_log_path.endswith('suite.log'))
-        m = re.match('.*\-(.*)\/suite.log', suite.suite_log_path)
+        m = re.search('-(.*)/suite.log$', suite.suite_log_path)
         rand_part = m.groups()[0]
         self.assertEqual(len(rand_part), 10)
         self.assertNotIn(rand_part, rand_part_set)
         rand_part_set.add(rand_part)
-        suite_log = open(suite.suite_log_path, 'r')
-        self.assertEquals(1, len([x for x in suite_log.readlines() \
-                              if x.find("Activated logfile")>=0]))
+        with open(suite.suite_log_path) as suite_log:
+          self.assertIn("Getting configuration from test suite",
+                        suite_log.readline())
 
     RunnerClass = test_type_registry[my_test_type]
     original_sleep = time.sleep
@@ -837,6 +843,7 @@ shared = true
     original_createTestResult = TaskDistributor.createTestResult
     TaskDistributor.createTestResult = patch_createTestResult
     test_node = self.getTestNode()
+    del test_node.suiteLog
     # Change UnitTestRunner class methods
     original_prepareSlapOS = RunnerClass._prepareSlapOS
 
@@ -934,7 +941,7 @@ shared = true
     SlapOSControler.runSoftwareRelease = runSoftwareRelease
     def callPrepareSlapOS():
       runner._prepareSlapOS(self.working_directory, node_test_suite,
-         test_node.log, create_partition=0)
+         create_partition=0)
     def callRaisingPrepareSlapos():
       self.assertRaises(SubprocessError, callPrepareSlapOS)
 
@@ -989,9 +996,8 @@ shared = true
     def patch_createTestResult(self, revision, test_name_list, node_title,
             allow_restart=False, test_title=None, project_title=None):
       test_result_path = os.path.join(test_result_path_root, test_title)
-      result =  TestResultProxy(self._proxy, self._retry_time,
-                self._logger, test_result_path, node_title, revision)
-      return result
+      return TestResultProxy(self._proxy, self._retry_time,
+                logger, test_result_path, node_title, revision)
     global startTestSuiteDone
     startTestSuiteDone = False
     def patch_startTestSuite(self,node_title,computer_guid='unknown'):

erp5/util/testnode/ProcessManager.py

@@ -32,6 +32,7 @@ import threading
 import signal
 import sys
 import time
+from . import logger
 
 MAX_TIMEOUT = 3600 * 4
 
@@ -67,28 +68,28 @@ def format_command(*args, **kw):
     cmdline.append(v)
   return ' '.join(cmdline)
 
-def subprocess_capture(p, log, log_prefix, get_output=True):
-  def readerthread(input, output, buffer):
+def subprocess_capture(p, log_prefix, get_output=True):
+  log = logger.info
+  if log_prefix:
+    log_prefix += ': '
+  def readerthread(input, buffer):
     while True:
       data = input.readline()
       if not data:
         break
       if get_output:
         buffer.append(data)
-      if log_prefix:
-        data = "%s : " % log_prefix +  data
-      data = data.rstrip('\n')
-      output(data)
+      log(log_prefix + data.rstrip('\n'))
   if p.stdout:
     stdout = []
     stdout_thread = threading.Thread(target=readerthread,
-                                     args=(p.stdout, log, stdout))
+                                     args=(p.stdout, stdout))
     stdout_thread.daemon = True
     stdout_thread.start()
   if p.stderr:
     stderr = []
     stderr_thread = threading.Thread(target=readerthread,
-                                     args=(p.stderr, log, stderr))
+                                     args=(p.stderr, stderr))
     stderr_thread.daemon = True
     stderr_thread.start()
   p.wait()
@@ -99,7 +100,7 @@ def subprocess_capture(p, log, log_prefix, get_output=True):
   return (p.stdout and ''.join(stdout),
           p.stderr and ''.join(stderr))
 
-def killCommand(pid, log):
+def killCommand(pid):
   """
   To prevent processes from reacting to the KILL of other processes,
   we STOP them all first, and we repeat until the list of children does not
@@ -118,21 +119,20 @@ def killCommand(pid, log):
       try:
         child.suspend()
       except psutil.Error, e:
-        log("killCommand/suspend: %s", e)
+        logger.debug("killCommand/suspend: %s", e)
     time.sleep(1)
     new_list = set(process.children(recursive=True)).difference(process_list)
   for process in process_list:
     try:
       process.kill()
     except psutil.Error, e:
-      log("killCommand/kill: %s", e)
+      logger.debug("killCommand/kill: %s", e)
 
 class ProcessManager(object):
 
   stdin = file(os.devnull)
 
-  def __init__(self, log, max_timeout=MAX_TIMEOUT):
-    self.log = log
+  def __init__(self, max_timeout=MAX_TIMEOUT):
     self.process_pid_set = set()
     signal.signal(signal.SIGTERM, self.sigterm_handler)
     self.under_cancellation = False
@@ -142,19 +142,17 @@ class ProcessManager(object):
     self.timer_set = set()
 
   def spawn(self, *args, **kw):
-    def timeoutExpired(p, log):
+    def timeoutExpired(p):
       if p.poll() is None:
-        log('PROCESS TOO LONG OR DEAD, GOING TO BE TERMINATED')
-        killCommand(p.pid, log)
+        logger.warning('PROCESS TOO LONG OR DEAD, GOING TO BE TERMINATED')
+        killCommand(p.pid)
+        raise SubprocessError('Dead or too long process killed')
 
     if self.under_cancellation:
       raise CancellationError("Test Result was cancelled")
     get_output = kw.pop('get_output', True)
     log_prefix = kw.pop('log_prefix', '')
     new_session = kw.pop('new_session', True)
-    log = kw.pop('log', None)
-    if log is None:
-      log = self.log
     subprocess_kw = {}
     cwd = kw.pop('cwd', None)
     if cwd:
@@ -164,17 +162,16 @@ class ProcessManager(object):
     raise_error_if_fail = kw.pop('raise_error_if_fail', True)
     env = kw and dict(os.environ, **kw) or None
     command = format_command(*args, **kw)
-    log('subprocess_kw : %r' % (subprocess_kw,))
-    log('$ ' + command)
+    logger.info('subprocess_kw : %r', subprocess_kw)
+    logger.info('$ %s', command)
     sys.stdout.flush()
     p = subprocess.Popen(args, stdin=self.stdin, stdout=subprocess.PIPE,
                          stderr=subprocess.PIPE, env=env, **subprocess_kw)
     self.process_pid_set.add(p.pid)
-    timer = threading.Timer(self.max_timeout, timeoutExpired, args=(p, log))
+    timer = threading.Timer(self.max_timeout, timeoutExpired, args=(p,))
     self.timer_set.add(timer)
     timer.start()
-    stdout, stderr = subprocess_capture(p, log, log_prefix,
-                                        get_output=get_output)
+    stdout, stderr = subprocess_capture(p, log_prefix, get_output=get_output)
     timer.cancel()
     self.timer_set.discard(timer)
     result = dict(status_code=p.returncode, command=command,
@@ -211,32 +208,39 @@ class ProcessManager(object):
             continue
       except (psutil.AccessDenied, psutil.NoSuchProcess):
         continue
-      self.log('ProcesssManager, killall on %s having pid %s',
+      logger.debug('ProcesssManager, killall on %s having pid %s',
                name, process.pid)
       to_kill_list.append(process.pid)
     for pid in to_kill_list:
-      killCommand(pid, self.log)
+      killCommand(pid)
 
   def killPreviousRun(self, cancellation=False):
-    self.log('ProcessManager killPreviousRun, going to kill %r',
+    logger.debug('ProcessManager killPreviousRun, going to kill %r',
              self.process_pid_set)
     if cancellation:
       self.under_cancellation = True
     for timer in self.timer_set:
       timer.cancel()
     for pgpid in self.process_pid_set:
-      killCommand(pgpid, self.log)
+      killCommand(pgpid)
+    try:
+      pid_file = self.supervisord_pid_file
+    except AttributeError:
+      pass
+    else:
+      del self.supervisord_pid_file
       try:
-      if os.path.exists(self.supervisord_pid_file):
-        with open(self.supervisord_pid_file) as f:
-          supervisor_pid = int(f.read().strip())
-        self.log('ProcessManager killPreviousRun, going to kill supervisor with pid %r',
-                 supervisor_pid)
-        os.kill(supervisor_pid, signal.SIGTERM)
+        if os.path.exists(pid_file):
+          with open(pid_file) as f:
+            pid = int(f.read().strip())
+          logger.debug('ProcessManager killPreviousRun,'
+                       ' going to kill supervisor with pid %r', pid)
+          os.kill(pid, signal.SIGTERM)
       except Exception:
-      self.log('ProcessManager killPreviousRun, exception when killing supervisor')
+        logger.exception(
+          'ProcessManager killPreviousRun, exception when killing supervisor')
     self.process_pid_set.clear()
 
   def sigterm_handler(self, signal, frame):
-    self.log('SIGTERM_HANDLER')
+    logger.debug('SIGTERM_HANDLER')
     sys.exit(1)

erp5/util/testnode/SlapOSControler.py

@@ -30,9 +30,9 @@ import slapos.slap
 import subprocess
 import time
 import xml_marshaller
-import sys
 import argparse
 from slapos import client
+from . import logger
 from .Utils import createFolder
 
 MAX_PARTITIONS = 10
@@ -40,12 +40,11 @@ MAX_SR_RETRIES = 3
 
 class SlapOSControler(object):
 
-  def __init__(self, working_directory, config, log):
+  def __init__(self, working_directory, config):
     self.config = config
     self.software_root = os.path.join(working_directory, 'soft')
     self.instance_root = os.path.join(working_directory, 'inst')
     self.slapos_config = os.path.join(working_directory, 'slapos.cfg')
-    self.log = log
     self.proxy_database = os.path.join(working_directory, 'proxy.db')
     self.instance_config = {}
 
@@ -80,7 +79,7 @@ class SlapOSControler(object):
     Ex :
     my_controler.supply('kvm.cfg', 'COMP-726')
     """
-    self.log('SlapOSControler : supply')
+    logger.debug('SlapOSControler : supply')
     parser = argparse.ArgumentParser()
     parser.add_argument("configuration_file")
     parser.add_argument("software_url")
@@ -92,9 +91,9 @@ class SlapOSControler(object):
       try:
         local = client.init(config)
         local['supply'](software_url, computer_guid=computer_id, state=state)
-        self.log('SlapOSControler : supply %s %s %s', software_url, computer_id, state)
+        logger.debug('SlapOSControler: supply %s %s %s', software_url, computer_id, state)
       except Exception:
-        self.log("SlapOSControler.supply", exc_info=sys.exc_info())
+        logger.exception("SlapOSControler.supply")
         raise ValueError("Unable to supply (or remove)")
     else:
       raise ValueError("Configuration file not found.")
@@ -113,7 +112,7 @@ class SlapOSControler(object):
                                'kvm.cfg', 'cluster', { "_" : "{'toto' : 'titi'}" } )
 
     """
-    self.log('SlapOSControler : request-->SlapOSMaster')
+    logger.debug('SlapOSControler : request-->SlapOSMaster')
     current_intance_config = {'software_type':software_type,
                               'software_configuration':software_configuration,
                               'computer_guid':computer_guid,
@@ -145,10 +144,10 @@ class SlapOSControler(object):
         if state == 'destroyed':
           del self.instance_config[reference]
         elif state == 'started':
-          self.log('Instance started with configuration: %s',
+          logger.debug('Instance started with configuration: %s',
                    software_configuration)
       except Exception:
-        self.log("SlapOSControler.request", exc_info=sys.exc_info())
+        logger.exception("SlapOSControler.request")
         raise ValueError("Unable to do this request")
     else:
       raise ValueError("Configuration file not found.")
@@ -163,21 +162,21 @@ class SlapOSControler(object):
     )    
   
   def destroyInstance(self, reference):
-    self.log('SlapOSControler : delete instance')
+    logger.debug('SlapOSControler : delete instance')
     try:
       self._requestSpecificState(reference, 'destroyed')
     except Exception:
       raise ValueError("Can't delete instance %r (instance not created?)" % reference)
     
   def stopInstance(self, reference):
-    self.log('SlapOSControler : stop instance')
+    logger.debug('SlapOSControler : stop instance')
     try:
       self._requestSpecificState(reference, 'stopped')
     except Exception:
       raise ValueError("Can't stop instance %r (instance not created?)" % reference)
   
   def startInstance(self, reference):
-    self.log('SlapOSControler : start instance')
+    logger.debug('SlapOSControler : start instance')
     try:
       self._requestSpecificState(reference, 'started')
     except Exception:
@@ -188,7 +187,7 @@ class SlapOSControler(object):
     Update the XML configuration of an instance
     # Request same instance with different parameters.
     """
-    self.log('SlapOSControler : updateInstanceXML will request same'
+    logger.debug('SlapOSControler : updateInstanceXML will request same'
                  ' instance with new XML configuration...')
 
     try:
@@ -203,7 +202,7 @@ class SlapOSControler(object):
       raise ValueError("Can't update instance '%s' (may not exist?)" %reference)
 
   def _resetSoftware(self):
-    self.log('SlapOSControler : GOING TO RESET ALL SOFTWARE : %r',
+    logger.info('SlapOSControler: GOING TO RESET ALL SOFTWARE : %r',
              self.software_root)
     createFolder(self.software_root, True)
 
@@ -211,7 +210,7 @@ class SlapOSControler(object):
         reset_software=False, software_path_list=None):
     self.process_manager = process_manager
     self.software_path_list = software_path_list
-    self.log('SlapOSControler, initialize, reset_software: %r', reset_software)
+    logger.debug('SlapOSControler, initialize, reset_software: %r', reset_software)
     config = self.config
     slapos_config_dict = config.copy()
     slapos_config_dict.update(software_root=self.software_root,
@@ -248,8 +247,7 @@ class SlapOSControler(object):
             computer_guid=config['computer_id'])
       computer = slap.registerComputer(config['computer_id'])
     except Exception:
-        self.log("SlapOSControler.initializeSlapOSControler",
-                 exc_info=sys.exc_info())
+        logger.exception("SlapOSControler.initializeSlapOSControler")
         raise ValueError("Unable to registerSupply")
     # Reset all previously generated software if needed
     if reset_software:
@@ -289,7 +287,7 @@ class SlapOSControler(object):
     return self.process_manager.spawn(*args, **kw)
 
   def runSoftwareRelease(self, config, environment, **kw):
-    self.log("SlapOSControler.runSoftwareRelease")
+    logger.debug("SlapOSControler.runSoftwareRelease")
     cpu_count = str(os.sysconf("SC_NPROCESSORS_ONLN"))
     os.environ['MAKEFLAGS'] = '-j' + cpu_count
     os.environ['NPY_NUM_BUILD_JOBS'] = cpu_count
@@ -309,7 +307,7 @@ class SlapOSControler(object):
 
   def runComputerPartition(self, config, environment,
                            stdout=None, stderr=None, cluster_configuration=None, **kw):
-    self.log("SlapOSControler.runComputerPartition with cluster_config: %r",
+    logger.debug("SlapOSControler.runComputerPartition with cluster_config: %r",
              cluster_configuration)
     for path in self.software_path_list:
       try:
@@ -318,7 +316,7 @@ class SlapOSControler(object):
             self.software_path_list.index(path),
           partition_parameter_kw=cluster_configuration)
       except Exception:
-        self.log("SlapOSControler.runComputerPartition", exc_info=sys.exc_info())
+        logger.exception("SlapOSControler.runComputerPartition")
         raise ValueError("Unable to registerOpenOrder")
 
     # try to run for all partitions as one partition may in theory request another one 
@@ -329,7 +327,7 @@ class SlapOSControler(object):
                  '--pidfile', os.path.join(self.instance_root, 'slapos-node.pid'),
                  '--cfg', self.slapos_config, raise_error_if_fail=False,
                  log_prefix='slapgrid_cp', get_output=False)
-      self.log('slapgrid_cp status_dict : %r', status_dict)
+      logger.debug('slapgrid_cp status_dict : %r', status_dict)
       if not status_dict['status_code']:
         break
     else:

erp5/util/testnode/SlapOSMasterCommunicator.py

@@ -10,6 +10,7 @@ import slapos.slap
 from slapos.slap import SoftwareProductCollection
 from requests.exceptions import HTTPError
 from ..taskdistribution import SAFE_RPC_EXCEPTION_LIST
+from . import logger
 
 # max time to instance changing state: 2 hour
 MAX_INSTANCE_TIME = 60*60*2
@@ -61,8 +62,7 @@ def retryOnNetworkFailure(func,
 class SlapOSMasterCommunicator(object):
   latest_state = None
 
-  def __init__(self, slap, slap_supply, slap_order, url, logger):
-    self._logger = logger
+  def __init__(self, slap, slap_supply, slap_order, url):
     self.slap = slap
     self.slap_order = slap_order
     self.slap_supply = slap_supply
@@ -72,20 +72,20 @@ class SlapOSMasterCommunicator(object):
     if url is not None and \
       url.startswith(SOFTWARE_PRODUCT_NAMESPACE):
 
-      product = SoftwareProductCollection(self._logger, self.slap)
+      product = SoftwareProductCollection(logger, self.slap)
       try:
         url = product.__getattr__(url[len(SOFTWARE_PRODUCT_NAMESPACE):])
       except AttributeError as e:
-        self._logger.warning('Error on get software release : %s ' % e.message)
+        logger.warning('Error on get software release: %s ', e.message)
 
     self.url = url  
 
   @retryOnNetworkFailure
   def _supply(self):
     if self.computer_guid is None:
-      self._logger('Nothing to supply for %s.' % (self.name))
+      logger.info('Nothing to supply for %s.', self.name)
       return None
-    self._logger('Supply %s@%s', self.url, self.computer_guid)
+    logger.info('Supply %s@%s', self.url, self.computer_guid)
     return self.slap_supply.supply(self.url, self.computer_guid)
 
   @retryOnNetworkFailure
@@ -97,7 +97,7 @@ class SlapOSMasterCommunicator(object):
         self.request_kw = json.loads(request_kw)
       else:
         self.request_kw = request_kw
-    self._logger('Request %s@%s: %s', self.url, self.name, state)
+    logger.info('Request %s@%s: %s', self.url, self.name, state)
     self.latest_state = state
     return self.slap_order.request(
             software_release=self.url,
@@ -252,7 +252,7 @@ class SlapOSMasterCommunicator(object):
   @retryOnNetworkFailure
   def _getInstanceState(self):
     latest_state = self.latest_state
-    self._logger('latest_state = %r', latest_state)
+    logger.info('latest_state = %r', latest_state)
 
     if latest_state is None:
       return INSTANCE_STATE_UNKNOWN
@@ -297,8 +297,8 @@ class SlapOSMasterCommunicator(object):
           try:
             monitor_information_dict = self.getRSSEntryFromMonitoring(monitor_v6_url)
           except Exception:
-            self._logger('Unable to download promises for: %s' % (instance["title"]))
-            self._logger(traceback.format_exc())
+            logger.exception('Unable to download promises for: %s',
+                             instance["title"])
             monitor_information_dict = {"message": "Unable to download"}
 
         message_list.append({
@@ -311,11 +311,10 @@ class SlapOSMasterCommunicator(object):
         })
 
     except slapos.slap.ServerError:
-      self._logger('Got an error requesting partition for '
-            'its state')
+      logger.error('Got an error requesting partition for its state')
       return INSTANCE_STATE_UNKNOWN
     except Exception:
-      self._logger("ERROR getting instance state")
+      logger.error("ERROR getting instance state")
       return INSTANCE_STATE_UNKNOWN
 
     started = 0
@@ -348,24 +347,24 @@ class SlapOSMasterCommunicator(object):
     """
     Wait for 'max_time' an instance specific state
     """
-    self._logger("Waiting for instance state: %s" %state)
+    logger.info("Waiting for instance state: %s", state)
     start_time = time.time()
     while (not self._getInstanceState() == state
            and (max_time > (time.time()-start_time))):
-      self._logger("Instance(s) not in %s state yet." % state)
-      self._logger("Current state: %s" % self._getInstanceState())
+      logger.info("Instance(s) not in %s state yet.", state)
+      logger.info("Current state: %s", self._getInstanceState())
       time.sleep(15)
     if (time.time()-start_time) > max_time:
       error_message = "Instance '%s' not '%s' after %s seconds" %(instance_title, state, str(time.time()-start_time))
       return {'error_message' : error_message}
-    self._logger("Instance correctly '%s' after %s seconds." %(state, str(time.time()-start_time)))
+    logger.info("Instance correctly '%s' after %s seconds.",
+                state, time.time() - start_time)
     return {'error_message' : None}
 
 class SlapOSTester(SlapOSMasterCommunicator):
 
   def __init__(self,
               name,
-              logger,
               slap,
               slap_order,
               slap_supply,
@@ -374,7 +373,7 @@ class SlapOSTester(SlapOSMasterCommunicator):
               request_kw=None
           ):
     super(SlapOSTester, self).__init__(
-      slap, slap_supply, slap_order, url, logger)
+      slap, slap_supply, slap_order, url)
 
     self.name = name
     self.computer_guid = computer_guid
@@ -413,9 +412,10 @@ class SlapOSTester(SlapOSMasterCommunicator):
   def waitInstanceStarted(self, instance_title):
     error_message = self._waitInstance(instance_title, INSTANCE_STATE_STARTED)["error_message"]
     if error_message is not None:
-      self._logger(error_message)
-      self._logger("Do you use instance state propagation in your project?")
-      self._logger("Instance '%s' will be stopped and test aborted." %instance_title)
+      logger.error(error_message)
+      logger.error("Do you use instance state propagation in your project?")
+      logger.error("Instance '%s' will be stopped and test aborted.",
+                   instance_title)
       self.requestInstanceStop()
       time.sleep(60)
       raise ValueError(error_message)
@@ -423,15 +423,15 @@ class SlapOSTester(SlapOSMasterCommunicator):
   def waitInstanceStopped(self, instance_title):
     error_message = self._waitInstance(instance_title, INSTANCE_STATE_STOPPED)["error_message"]
     if error_message is not None:
-      self._logger(error_message)
-      self._logger("Do you use instance state propagation in your project?")
+      logger.error(error_message)
+      logger.error("Do you use instance state propagation in your project?")
       raise ValueError(error_message)
 
   def waitInstanceDestroyed(self, instance_title):
     error_message = self._waitInstance(instance_title, INSTANCE_STATE_DESTROYED)["error_message"]
     if error_message is not None:
-      self._logger(error_message)
-      self._logger("Do you use instance state propagation in your project?")
+      logger.error(error_message)
+      logger.error("Do you use instance state propagation in your project?")
       raise ValueError(error_message)
 
 class SoftwareReleaseTester(SlapOSTester):
@@ -439,7 +439,6 @@ class SoftwareReleaseTester(SlapOSTester):
 
   def __init__(self,
               name,
-              logger,
               slap,
               slap_order,
               slap_supply,
@@ -450,7 +449,7 @@ class SoftwareReleaseTester(SlapOSTester):
               instance_timeout=3600,
           ):
     super(SoftwareReleaseTester, self).__init__(
-      name, logger, slap, slap_order, slap_supply, url, computer_guid, request_kw)
+      name, slap, slap_order, slap_supply, url, computer_guid, request_kw)
 
     self.state = TESTER_STATE_INITIAL
     self.transition_dict = {
@@ -536,7 +535,7 @@ class SoftwareReleaseTester(SlapOSTester):
     """
     Interrupt a running test sequence, putting it in idle state.
     """
-    self._logger('Invoking TearDown for %s@%s' % (self.url, self.name))
+    logger.info('Invoking TearDown for %s@%s', self.url, self.name)
     if self.request_kw is not None:
        self._request(INSTANCE_STATE_DESTROYED)
     if self.computer_guid is not None:
@@ -548,7 +547,7 @@ class SoftwareReleaseTester(SlapOSTester):
     Check for missed deadlines (-> test failure), conditions for moving to
     next state, and actually moving to next state (executing its payload).
     """
-    self._logger('[DEBUG] TIC')
+    logger.debug('TIC')
     deadline = self.deadline
 
     if deadline < now and deadline is not None:
@@ -562,7 +561,7 @@ class SoftwareReleaseTester(SlapOSTester):
           instance_state is None or
           instance_state == self._getInstanceState()):
 
-      self._logger('[DEBUG] Going to state %s (%r)', next_state, instance_state)
+      logger.debug('Going to state %s (%r)', next_state, instance_state)
       if next_state is None:
         return None
 

erp5/util/testnode/UnitTestRunner.py

@@ -27,6 +27,7 @@
 import os
 import glob
 import json
+from . import logger
 from .ProcessManager import SubprocessError
 from .SlapOSControler import SlapOSControler
 from .Utils import createFolder
@@ -49,21 +50,20 @@ class UnitTestRunner(object):
     """
     return SlapOSControler(
                working_directory,
-               self.testnode.config,
-               self.testnode.log)
+               self.testnode.config)
  
-  def _prepareSlapOS(self, working_directory, slapos_instance, log,
+  def _prepareSlapOS(self, working_directory, slapos_instance,
           create_partition=1, software_path_list=None, **kw):
     """
     Launch slapos to build software and partitions
     """
     slapproxy_log = os.path.join(self.testnode.config['log_directory'],
                                   'slapproxy.log')
-    log('Configured slapproxy log to %r', slapproxy_log)
+    logger.debug('Configured slapproxy log to %r', slapproxy_log)
     reset_software = slapos_instance.retry_software_count > 10
     if reset_software:
       slapos_instance.retry_software_count = 0
-    log('testnode, retry_software_count : %r',
+    logger.info('testnode, retry_software_count: %r',
              slapos_instance.retry_software_count)
 
     # XXX Create a new controler because working_directory can be
@@ -80,12 +80,12 @@ class UnitTestRunner(object):
       method_list.append("runComputerPartition")
     for method_name in method_list:
       slapos_method = getattr(slapos_controler, method_name)
-      log("Before status_dict = slapos_method(...)")
+      logger.debug("Before status_dict = slapos_method(...)")
       status_dict = slapos_method(self.testnode.config,
                                   environment=self.testnode.config['environment'],
                                   **kw)
-      log(status_dict)
-      log("After status_dict = slapos_method(...)")
+      logger.info(status_dict)
+      logger.debug("After status_dict = slapos_method(...)")
       if status_dict['status_code'] != 0:
          slapos_instance.retry = True
          slapos_instance.retry_software_count += 1
@@ -103,7 +103,7 @@ class UnitTestRunner(object):
     # instance. This is a hack which must be removed.
     config = self.testnode.config
     return self._prepareSlapOS(test_node_slapos.working_directory,
-              test_node_slapos, self.testnode.log, create_partition=0,
+              test_node_slapos, create_partition=0,
               software_path_list=config.get("software_list"),
               cluster_configuration={
                 'report-url': config.get("report-url", ""),
@@ -116,7 +116,7 @@ class UnitTestRunner(object):
     Build softwares needed by testsuites
     """
     return self._prepareSlapOS(node_test_suite.working_directory,
-              node_test_suite, self.testnode.log,
+              node_test_suite,
               software_path_list=[node_test_suite.custom_profile_path],
               cluster_configuration={'_': json.dumps(node_test_suite.cluster_configuration)})
 
@@ -124,7 +124,7 @@ class UnitTestRunner(object):
     return self._getSlapOSControler(
       node_test_suite.working_directory).instance_root
 
-  def runTestSuite(self, node_test_suite, portal_url, log=None):
+  def runTestSuite(self, node_test_suite, portal_url):
     config = self.testnode.config
     run_test_suite_path_list = glob.glob(
         self.getInstanceRoot(node_test_suite) + "/*/bin/runTestSuite")

erp5/util/testnode/Updater.py

@@ -28,7 +28,7 @@ import errno
 import os
 import re
 import shutil
-import sys
+from . import logger
 from .ProcessManager import SubprocessError
 
 SVN_UP_REV = re.compile(r'^(?:At|Updated to) revision (\d+).$')
@@ -42,10 +42,9 @@ class Updater(object):
 
   _git_cache = {}
 
-  def __init__(self, repository_path, log, revision=None, git_binary='git',
+  def __init__(self, repository_path, revision=None, git_binary='git',
       branch=None, realtime_output=True, process_manager=None, url=None,
       working_directory=None):
-    self.log = log
     self.revision = revision
     self._path_list = []
     self.branch = branch
@@ -111,16 +110,16 @@ class Updater(object):
     git_repository_path = os.path.join(self.getRepositoryPath(), '.git')
     name = os.path.basename(os.path.normpath(self.getRepositoryPath()))
     git_repository_link_path = os.path.join(self.getRepositoryPath(), '%s.git' %name)
-    self.log("checking link %s -> %s..",
+    logger.debug("checking link %s -> %s..",
              git_repository_link_path, git_repository_path)
     if ( not os.path.lexists(git_repository_link_path) and \
          not os.path.exists(git_repository_link_path) ):
       try:
         os.symlink(git_repository_path, git_repository_link_path)
-        self.log("link: %s -> %s created",
+        logger.debug("link: %s -> %s created",
           git_repository_link_path, git_repository_path)
       except OSError:
-        self.log("Cannot create link from %s -> %s",
+        logger.error("Cannot create link from %s -> %s",
           git_repository_link_path, git_repository_path)
   
   def _git_find_rev(self, ref):
@@ -148,7 +147,7 @@ class Updater(object):
     raise NotImplementedError
 
   def deleteRepository(self):
-    self.log("Wrong repository or wrong url, deleting repos %s",
+    logger.info("Wrong repository or wrong url, deleting repos %s",
              self.repository_path)
     shutil.rmtree(self.repository_path)
 
@@ -162,7 +161,7 @@ class Updater(object):
           if remote_url == self.url:
             correct_url = True
         except SubprocessError:
-          self.log("SubprocessError", exc_info=sys.exc_info())
+          logger.exception("")
         if not(correct_url):
           self.deleteRepository()
       if not os.path.exists(self.repository_path):

erp5/util/testnode/__init__.py

@@ -30,9 +30,12 @@ import logging
 import logging.handlers
 import os
 
-from .testnode import TestNode
+log_formatter = logging.Formatter('%(asctime)s %(levelname)-8s %(message)s')
+logger = logging.getLogger(__name__)
+logger.setLevel(logging.DEBUG)
 
 def main(*args):
+  from .testnode import TestNode
   parser = argparse.ArgumentParser()
   parser.add_argument("configuration_file", nargs=1, type=argparse.FileType(),
       help="Configuration file.")
@@ -43,29 +46,24 @@ def main(*args):
     parsed_argument = parser.parse_args(list(args))
   else:
     parsed_argument = parser.parse_args()
-  logger_format = '%(asctime)s %(name)-13s: %(levelname)-8s %(message)s'
-  formatter = logging.Formatter(logger_format)
-  logging.basicConfig(level=logging.INFO,
-                     format=logger_format)
-  logger = logging.getLogger('erp5testnode')
-  CONFIG = {
-    'logger': logger.info,
-    'partition_reference': 'test0',
-  }
+
   if parsed_argument.console or parsed_argument.logfile:
+    root = logging.getLogger()
+    def addHandler(handler):
+      handler.setFormatter(log_formatter)
+      root.addHandler(handler)
     if parsed_argument.console:
-      logger.addHandler(logging.StreamHandler())
-      logger.info('Activated console output.')
+      addHandler(logging.StreamHandler())
     if parsed_argument.logfile:
-      file_handler = logging.handlers.RotatingFileHandler(
+      addHandler(logging.handlers.RotatingFileHandler(
         filename=parsed_argument.logfile,
-        maxBytes=20000000, backupCount=4)
-      file_handler.setFormatter(formatter)
-      logger.addHandler(file_handler)
-      logger.info('Activated logfile %r output', parsed_argument.logfile)
-      CONFIG['log_file'] = parsed_argument.logfile
+        maxBytes=20000000, backupCount=4))
   else:
-    logger.addHandler(logging.NullHandler())
+    logger.disable(logging.CRITICAL)
+
+  CONFIG = {
+    'partition_reference': 'test0',
+  }
   config = ConfigParser.SafeConfigParser()
   # do not change case of option keys
   config.optionxform = str
@@ -107,5 +105,4 @@ def main(*args):
     CONFIG['software_list'] = filter(None,
         config.get("software_list", "path_list").split(","))
   
-  testnode = TestNode(logger.info, CONFIG)
-  testnode.run()
+  TestNode(CONFIG).run()