From 4a998bd3744adca0b1b8346558e017858a48e626 Mon Sep 17 00:00:00 2001 From: Claudio-Daniel Freire Date: Thu, 21 Jul 2011 14:21:45 +0200 Subject: [PATCH] Ticket #70: Logging instead of prints for PlanetLab --- src/nepi/testbeds/planetlab/application.py | 29 +++++++++++----------- src/nepi/testbeds/planetlab/execute.py | 19 +++++++++----- src/nepi/testbeds/planetlab/metadata.py | 12 +++++++++ src/nepi/testbeds/planetlab/node.py | 12 ++++++--- src/nepi/testbeds/planetlab/tunproto.py | 15 ++++++----- 5 files changed, 57 insertions(+), 30 deletions(-) diff --git a/src/nepi/testbeds/planetlab/application.py b/src/nepi/testbeds/planetlab/application.py index 3d72bde1..7cdd7233 100644 --- 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 6714f2be..33ec2080 100644 --- 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 16646a5a..dc4f19c1 100644 --- 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 99ba2aa5..7efdb971 100644 --- 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 2a3c9545..d066a8d2 100644 --- 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) -- 2.47.0