The loglevel of logging is now set from the ExperimentController depending on the...

diff --git a/src/nepi/core/execute.py b/src/nepi/core/execute.py
index 0a52691..3a3cfec 100644 (file)
--- 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 d94b6f8..11f56ad 100644 (file)
--- 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 9a189ba..32644c1 100644 (file)
--- 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 47a9495..72af827 100644 (file)
--- 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 11b85a5..1fa1774 100644 (file)
--- 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))