From e364a428680073f7296aa9542a6ac99b3476379c Mon Sep 17 00:00:00 2001 From: Alina Quereilhac Date: Fri, 26 Aug 2011 16:04:16 +0200 Subject: [PATCH] The loglevel of logging is now set from the ExperimentController depending on the access_configuration setup. --- src/nepi/core/execute.py | 21 +++++++++++++++++++-- src/nepi/core/testbed_impl.py | 14 ++++++++------ src/nepi/testbeds/planetlab/application.py | 2 ++ src/nepi/util/proxy.py | 8 ++++++-- src/nepi/util/server.py | 9 ++++----- 5 files changed, 39 insertions(+), 15 deletions(-) diff --git a/src/nepi/core/execute.py b/src/nepi/core/execute.py index 0a526915..3a3cfec8 100644 --- a/src/nepi/core/execute.py +++ b/src/nepi/core/execute.py @@ -241,9 +241,14 @@ class ExperimentController(object): self._failed_testbeds = set() self._started_time = None self._stopped_time = None - + self._logger = logging.getLogger('nepi.core.execute') - + level = logging.ERROR + if os.environ.get("NEPI_CONTROLLER_LOGLEVEL", + DC.ERROR_LEVEL) == DC.DEBUG_LEVEL: + level = logging.DEBUG + self._logger.setLevel(level) + if experiment_xml is None and root_dir is not None: # Recover self.load_experiment_xml() @@ -370,24 +375,30 @@ class ExperimentController(object): def steps_to_configure(self, allowed_guids): # perform setup in parallel for all test beds, # wait for all threads to finish + + self._logger.debug("ExperimentController: Starting parallel do_setup") self._parallel([testbed.do_setup for guid,testbed in self._testbeds.iteritems() if guid in allowed_guids]) # perform create-connect in parallel, wait # (internal connections only) + self._logger.debug("ExperimentController: Starting parallel do_create") self._parallel([testbed.do_create for guid,testbed in self._testbeds.iteritems() if guid in allowed_guids]) + self._logger.debug("ExperimentController: Starting parallel do_connect_init") self._parallel([testbed.do_connect_init for guid,testbed in self._testbeds.iteritems() if guid in allowed_guids]) + self._logger.debug("ExperimentController: Starting parallel do_connect_fin") self._parallel([testbed.do_connect_compl for guid,testbed in self._testbeds.iteritems() if guid in allowed_guids]) + self._logger.debug("ExperimentController: Starting parallel do_preconfigure") self._parallel([testbed.do_preconfigure for guid,testbed in self._testbeds.iteritems() if guid in allowed_guids]) @@ -395,6 +406,7 @@ class ExperimentController(object): steps_to_configure(self, to_restart) + self._logger.debug("ExperimentController: Resolving netreffed testbeds") if self._netreffed_testbeds: # initally resolve netrefs self.do_netrefs(data, fail_if_undefined=False) @@ -426,6 +438,7 @@ class ExperimentController(object): all_restart = [ self._testbeds[guid] for guid in all_restart ] # final netref step, fail if anything's left unresolved + self._logger.debug("ExperimentController: Resolving do_netrefs") self.do_netrefs(data, fail_if_undefined=False) # Only now, that netref dependencies have been solve, it is safe to @@ -434,6 +447,7 @@ class ExperimentController(object): # perform do_configure in parallel for al testbeds # (it's internal configuration for each) + self._logger.debug("ExperimentController: Starting parallel do_configure") self._parallel([testbed.do_configure for testbed in all_restart]) @@ -444,6 +458,7 @@ class ExperimentController(object): #time.sleep(60) # cross-connect (cannot be done in parallel) + self._logger.debug("ExperimentController: Starting cross-connect") for guid, testbed in self._testbeds.iteritems(): cross_data = self._get_cross_data(guid) testbed.do_cross_connect_init(cross_data) @@ -454,6 +469,7 @@ class ExperimentController(object): self._clear_caches() # Last chance to configure (parallel on all testbeds) + self._logger.debug("ExperimentController: Starting parallel do_prestart") self._parallel([testbed.do_prestart for testbed in all_restart]) @@ -469,6 +485,7 @@ class ExperimentController(object): self.persist_execute_xml() # start experiment (parallel start on all testbeds) + self._logger.debug("ExperimentController: Starting parallel do_start") self._parallel([testbed.start for testbed in all_restart]) diff --git a/src/nepi/core/testbed_impl.py b/src/nepi/core/testbed_impl.py index d94b6f84..11f56add 100644 --- a/src/nepi/core/testbed_impl.py +++ b/src/nepi/core/testbed_impl.py @@ -250,15 +250,15 @@ class TestbedController(execute.TestbedController): # perform the action on all elements, in parallel if so requested if runner: - logger.debug("Starting parallel %s", action) + logger.debug("TesbedController: Starting parallel %s", action) runner.start() for guid in guids[factory_id]: if runner: - logger.debug("Scheduling %s on %s", action, guid) + logger.debug("TestbedController: Scheduling %s on %s", action, guid) runner.put(perform_action, guid) else: - logger.debug("Performing %s on %s", action, guid) + logger.debug("TestbedController: Performing %s on %s", action, guid) perform_action(guid) # sync @@ -269,16 +269,16 @@ class TestbedController(execute.TestbedController): if poststep: for guid in guids[factory_id]: if runner: - logger.debug("Scheduling post-%s on %s", action, guid) + logger.debug("TestbedController: Scheduling post-%s on %s", action, guid) runner.put(poststep, self, guid) else: - logger.debug("Performing post-%s on %s", action, guid) + logger.debug("TestbedController: Performing post-%s on %s", action, guid) poststep(self, guid) # sync if runner: runner.join() - logger.debug("Finished parallel %s", action) + logger.debug("TestbedController: Finished parallel %s", action) @staticmethod def do_poststep_preconfigure(self, guid): @@ -329,6 +329,8 @@ class TestbedController(execute.TestbedController): cross_connector_type_name, True) if connect_code: + self._logger.debug("Cross-connect: guid: %d, connect_code: %s " % ( + guid, repr(connect_code))) elem_cross_data = cross_data[cross_testbed_guid][cross_guid] connect_code(self, guid, elem_cross_data) diff --git a/src/nepi/testbeds/planetlab/application.py b/src/nepi/testbeds/planetlab/application.py index 9a189ba4..32644c10 100644 --- a/src/nepi/testbeds/planetlab/application.py +++ b/src/nepi/testbeds/planetlab/application.py @@ -181,6 +181,8 @@ class Dependency(object): raise exctyp,exval,exctrace else: raise RuntimeError, "Failed to setup application" + else: + self._logger.info("Setup ready: %s", self) else: self.setup() diff --git a/src/nepi/util/proxy.py b/src/nepi/util/proxy.py index 47a94955..72af827e 100644 --- a/src/nepi/util/proxy.py +++ b/src/nepi/util/proxy.py @@ -141,9 +141,9 @@ def log_reply(server, reply): def to_server_log_level(log_level): return ( - server.DEBUG_LEVEL + DC.DEBUG_LEVEL if log_level == DC.DEBUG_LEVEL - else server.ERROR_LEVEL + else DC.ERROR_LEVEL ) def get_access_config_params(access_config): @@ -198,6 +198,10 @@ def create_experiment_controller(xml, access_config = None): else access_config.get_attribute_value(DC.DEPLOYMENT_MODE) launch = True if not access_config \ else not access_config.get_attribute_value(DC.RECOVER) + log_level = DC.ERROR_LEVEL if not access_config \ + else access_config.get_attribute_value(DC.LOG_LEVEL) + os.environ["NEPI_CONTROLLER_LOGLEVEL"] = log_level + if not mode or mode == DC.MODE_SINGLE_PROCESS: from nepi.core.execute import ExperimentController diff --git a/src/nepi/util/server.py b/src/nepi/util/server.py index 11b85a5c..1fa17741 100644 --- a/src/nepi/util/server.py +++ b/src/nepi/util/server.py @@ -29,8 +29,6 @@ MAX_FD = 1024 STOP_MSG = "STOP" -ERROR_LEVEL = 0 -DEBUG_LEVEL = 1 TRACE = os.environ.get("NEPI_TRACE", "false").lower() in ("true", "1", "on") if hasattr(os, "devnull"): @@ -78,7 +76,7 @@ def eintr_retry(func): return rv class Server(object): - def __init__(self, root_dir = ".", log_level = ERROR_LEVEL, environment_setup = ""): + def __init__(self, root_dir = ".", log_level = DC.ERROR_LEVEL, environment_setup = ""): self._root_dir = root_dir self._stop = False self._ctrl_sock = None @@ -205,6 +203,7 @@ class Server(object): return 1 def post_daemonize(self): + os.environ["NEPI_CONTROLLER_LOGLEVEL"] = self._log_level # QT, for some strange reason, redefines the SIGCHILD handler to write # a \0 to a fd (lets say fileno 'x'), when ever a SIGCHILD is received. # Server dameonization closes all file descriptors from fileno '3', @@ -227,7 +226,7 @@ class Server(object): try: msg = self.recv_msg(conn) except socket.timeout, e: - self.log_error() + self.log_error("SERVER recv_msg: connection timedout ") break if not msg: @@ -303,7 +302,7 @@ class Server(object): return text def log_debug(self, text): - if self._log_level == DEBUG_LEVEL: + if self._log_level == DC.DEBUG_LEVEL: date = time.strftime("%Y-%m-%d %H:%M:%S") sys.stderr.write("DEBUG: %s\n%s\n" % (date, text)) -- 2.47.0