Ticket #70: Logging instead of prints for PlanetLab

diff --git a/src/nepi/testbeds/planetlab/application.py b/src/nepi/testbeds/planetlab/application.py
index 3d72bde..7cdd723 100644 (file)
--- a/src/nepi/testbeds/planetlab/application.py
+++ b/src/nepi/testbeds/planetlab/application.py
@@ -15,6 +15,7 @@ import random
 import time
 import socket
 import threading
+import logging
 
 from nepi.util.constants import ApplicationStatus as AS
 
@@ -81,6 +82,9 @@ class Dependency(object):
         self._build_pid = None
         self._build_ppid = None
         
+        # Logging
+        self._logger = logging.getLogger('nepi.testbeds.planetlab')
+        
     
     def __str__(self):
         return "%s<%s>" % (
@@ -138,7 +142,7 @@ class Dependency(object):
         return local_path
 
     def setup(self):
-        print >>sys.stderr, "Setting up", self
+        self._logger.info("Setting up %s", self)
         self._make_home()
         self._launch_build()
         self._finish_build()
@@ -158,7 +162,7 @@ class Dependency(object):
     
     def async_setup_wait(self):
         if not self._setup:
-            print >>sys.stderr, "Waiting for", self, "to be setup"
+            self._logger.info("Waiting for %s to be setup", self)
             if self._setuper:
                 self._setuper.join()
                 if not self._setup:
@@ -212,7 +216,7 @@ class Dependency(object):
             buildscript = self._do_build_master()
             
         if buildscript is not None:
-            print >>sys.stderr, "Building", self
+            self._logger.info("Building %s", self)
             
             # upload build script
             try:
@@ -345,7 +349,7 @@ class Dependency(object):
         else:
             raise RuntimeError, "Failed to set up build slave %s: cannot get pid" % (self.home_path,)
 
-        print >>sys.stderr, "Deploying", self
+        self._logger.info("Deploying %s", self)
         
     def _do_wait_build(self):
         pid = self._build_pid
@@ -370,11 +374,8 @@ class Dependency(object):
                     break
                 else:
                     if first:
-                        print >>sys.stderr, "Waiting for", self, "to finish building",
-                        if self._master is not None:
-                            print >>sys.stderr, "(build slave)"
-                        else:
-                            print >>sys.stderr, "(build master)"
+                        self._logger.info("Waiting for %s to finish building %s", self,
+                            "(build slave)" if self._master is not None else "(build master)")
                         
                         first = False
                     time.sleep(delay*(0.5+random.random()))
@@ -407,14 +408,14 @@ class Dependency(object):
                         "(expected %r, got %r), see buildlog: %s" % (
                     self.home_path, pid, ppid, self._master_token, slave_token, buildlog)
 
-            print >>sys.stderr, "Built", self
+            self._logger.info("Built %s", self)
 
     def _do_kill_build(self):
         pid = self._build_pid
         ppid = self._build_ppid
         
         if pid and ppid:
-            print >>sys.stderr, "Killing build of", self
+            self._logger.info("Killing build of %s", self)
             rspawn.remote_kill(
                 pid, ppid,
                 host = self.node.hostname,
@@ -477,7 +478,7 @@ class Dependency(object):
 
     def _do_install(self):
         if self.install:
-            print >>sys.stderr, "Installing", self
+            self._logger.info("Installing %s", self)
             
             # Install application
             try:
@@ -606,7 +607,7 @@ class Application(Dependency):
         )
     
     def start(self):
-        print >>sys.stderr, "Starting", self
+        self._logger.info("Starting %s", self)
         
         # Create shell script with the command
         # This way, complex commands and scripts can be ran seamlessly
@@ -717,7 +718,7 @@ class Application(Dependency):
                 ident_key = self.node.ident_path,
                 server_key = self.node.server_key
                 )
-            print >>sys.stderr, "Killed", self
+            self._logger.info("Killed %s", self)
 
 
 class NepiDependency(Dependency):

diff --git a/src/nepi/testbeds/planetlab/execute.py b/src/nepi/testbeds/planetlab/execute.py
index 6714f2b..33ec208 100644 (file)
--- a/src/nepi/testbeds/planetlab/execute.py
+++ b/src/nepi/testbeds/planetlab/execute.py
@@ -22,6 +22,7 @@ import tempfile
 import subprocess
 import random
 import shutil
+import logging
 
 class TempKeyError(Exception):
     pass
@@ -42,6 +43,8 @@ class TestbedController(testbed_impl.TestbedController):
         self._just_provisioned = set()
         
         self._load_blacklist()
+        
+        self._logger = logging.getLogger('nepi.testbeds.planetlab')
 
     @property
     def home_directory(self):
@@ -118,6 +121,11 @@ class TestbedController(testbed_impl.TestbedController):
             get_attribute_value("plcHost")
         self.plcUrl = self._attributes.\
             get_attribute_value("plcUrl")
+        self.logLevel = self._attributes.\
+            get_attribute_value("plLogLevel")
+        
+        self._logger.setLevel(getattr(logging,self.logLevel))
+        
         super(TestbedController, self).do_setup()
 
     def do_post_asynclaunch(self, guid):
@@ -245,29 +253,28 @@ class TestbedController(testbed_impl.TestbedController):
                 node.slicename = self.slicename
             
                 # Show the magic
-                print >>sys.stderr, "PlanetLab Node", guid, "configured at", node.hostname
+                self._logger.info("PlanetLab Node %s configured at %s", guid, node.hostname)
             
         try:
             for guid, node in self._elements.iteritems():
                 if isinstance(node, self._node.Node):
-                    print >>sys.stderr, "Waiting for Node", guid, "configured at", node.hostname,
-                    sys.stdout.flush()
+                    self._logger.info("Waiting for Node %s configured at %s", guid, node.hostname)
                     
                     node.wait_provisioning(
                         (20*60 if node._node_id in self._just_provisioned else 60)
                     )
                     
-                    print >>sys.stderr, "READY"
+                    self._logger.info("READY Node %s at %s", guid, node.hostname)
         except self._node.UnresponsiveNodeError:
             # Uh... 
-            print >>sys.stderr, "UNRESPONSIVE"
+            self._logger.warn("UNRESPONSIVE Node %s", node.hostname)
             
             # Mark all dead nodes (which are unresponsive) on the blacklist
             # and re-raise
             for guid, node in self._elements.iteritems():
                 if isinstance(node, self._node.Node):
                     if not node.is_alive():
-                        print >>sys.stderr, "Blacklisting", node.hostname, "for unresponsiveness"
+                        self._logger.warn("Blacklisting %s for unresponsiveness", node.hostname)
                         self._blacklist.add(node._node_id)
                         node.unassign_node()
             

diff --git a/src/nepi/testbeds/planetlab/metadata.py b/src/nepi/testbeds/planetlab/metadata.py
index 16646a5..dc4f19c 100644 (file)
--- a/src/nepi/testbeds/planetlab/metadata.py
+++ b/src/nepi/testbeds/planetlab/metadata.py
@@ -1121,6 +1121,18 @@ testbed_attributes = dict({
             "flags": Attribute.ExecReadOnly | Attribute.ExecImmutable | Attribute.NoDefaultValue,
             "validation_function": validation.is_string
         }),
+        "pl_log_level": dict({      
+            "name": "plLogLevel",
+            "help": "Verbosity of logging of planetlab events.",
+            "value": "ERROR",
+            "type": Attribute.ENUM, 
+            "allowed": ["DEBUG",
+                        "INFO",
+                        "WARNING",
+                        "ERROR",
+                        "CRITICAL"],
+            "validation_function": validation.is_enum,
+        }),
     })
 
 class MetadataInfo(metadata.MetadataInfo):

diff --git a/src/nepi/testbeds/planetlab/node.py b/src/nepi/testbeds/planetlab/node.py
index 99ba2aa..7efdb97 100644 (file)
--- a/src/nepi/testbeds/planetlab/node.py
+++ b/src/nepi/testbeds/planetlab/node.py
@@ -12,6 +12,7 @@ import cStringIO
 import resourcealloc
 import socket
 import sys
+import logging
 
 from nepi.util import server
 from nepi.util import parallel
@@ -77,6 +78,9 @@ class Node(object):
         
         # Those are filled when an actual node is allocated
         self._node_id = None
+
+        # Logging
+        self._logger = logging.getLogger('nepi.testbeds.planetlab')
     
     @property
     def _nepi_testbed_environment_setup(self):
@@ -109,7 +113,7 @@ class Node(object):
         )
     
     def find_candidates(self, filter_slice_id=None):
-        print >>sys.stderr, "Finding candidates for", self.make_filter_description()
+        self._logger.info("Finding candidates for %s", self.make_filter_description())
         
         fields = ('node_id',)
         replacements = {'timeframe':self.timeframe}
@@ -197,7 +201,7 @@ class Node(object):
         
         # make sure hostnames are resolvable
         if candidates:
-            print >>sys.stderr, "  Found", len(candidates), "candidates. Checking for reachability..."
+            self._logger.info("  Found %s candidates. Checking for reachability...", len(candidates))
             
             hostnames = dict(map(operator.itemgetter('node_id','hostname'),
                 self._api.GetNodes(list(candidates), ['node_id','hostname'])
@@ -211,7 +215,7 @@ class Node(object):
             candidates = set(parallel.pfilter(resolvable, candidates,
                 maxthreads = 16))
 
-            print >>sys.stderr, "  Found", len(candidates), "reachable candidates."
+            self._logger.info("  Found %s reachable candidates.", len(candidates))
             
         return candidates
     
@@ -474,7 +478,7 @@ class Node(object):
                 raise RuntimeError, "Route %s cannot be bound to any virtual interface " \
                     "- PL can only handle rules over virtual interfaces. Candidates are: %s" % (route,devs)
         
-        print >>sys.stderr, "Setting up routes for", self.hostname
+        self._logger.info("Setting up routes for %s", self.hostname)
         
         (out,err),proc = server.popen_ssh_command(
             "( sudo -S bash -c 'cat /vsys/vroute.out >&2' & ) ; sudo -S bash -c 'cat > /vsys/vroute.in' ; sleep 0.1" % dict(

diff --git a/src/nepi/testbeds/planetlab/tunproto.py b/src/nepi/testbeds/planetlab/tunproto.py
index 2a3c954..d066a8d 100644 (file)
--- a/src/nepi/testbeds/planetlab/tunproto.py
+++ b/src/nepi/testbeds/planetlab/tunproto.py
@@ -11,6 +11,7 @@ import base64
 import time
 import re
 import sys
+import logging
 
 from nepi.util import server
 
@@ -34,6 +35,9 @@ class TunProtoBase(object):
         self._pid = None
         self._ppid = None
         self._if_name = None
+
+        # Logging
+        self._logger = logging.getLogger('nepi.testbeds.planetlab')
     
     def __str__(self):
         local = self.local()
@@ -203,7 +207,7 @@ class TunProtoBase(object):
         if not listen and check_proto != 'fd':
             args.append(str(peer_addr))
 
-        print >>sys.stderr, "Starting", self
+        self._logger.info("Starting %s", self)
         
         self._make_home()
         self._install_scripts()
@@ -255,7 +259,7 @@ class TunProtoBase(object):
         # Wait for the connection to be established
         for spin in xrange(30):
             if self.status() != rspawn.RUNNING:
-                print >>sys.stderr, "FAILED TO CONNECT! ", self
+                self._logger.warn("FAILED TO CONNECT! %s", self)
                 break
             
             (out,err),proc = server.eintr_retry(server.popen_ssh_command)(
@@ -277,7 +281,7 @@ class TunProtoBase(object):
             
             time.sleep(1.0)
         else:
-            print >>sys.stderr, "FAILED TO CONNECT! ", self
+            self._logger.warn("FAILED TO CONNECT! %s", self)
     
     @property
     def if_name(self):
@@ -325,7 +329,6 @@ class TunProtoBase(object):
                 else:
                     raise RuntimeError, "Failed to launch TUN forwarder"
         elif not self._started:
-            print >>sys.stderr, "SYNC", 
             self.launch()
 
     def checkpid(self):            
@@ -381,7 +384,7 @@ class TunProtoBase(object):
         
         status = self.status()
         if status == rspawn.RUNNING:
-            print >>sys.stderr, "Stopping", self
+            self._logger.info("Stopping %s", self)
             
             # kill by ppid+pid - SIGTERM first, then try SIGKILL
             rspawn.remote_kill(
@@ -401,7 +404,7 @@ class TunProtoBase(object):
         for i in xrange(30):
             status = self.status()
             if status != rspawn.RUNNING:
-                print >>sys.stderr, "Stopped", self
+                self._logger.info("Stopped %s", self)
                 break
             time.sleep(interval)
             interval = min(30.0, interval * 1.1)