Index: fedd/fedd_experiment_control.py
===================================================================
--- fedd/fedd_experiment_control.py	(revision a97394be19715ff525bec2526f455144cc797dda)
+++ fedd/fedd_experiment_control.py	(revision 11a08b0e9216a4de8d8e50f742da2911382a40e7)
@@ -29,4 +29,12 @@
 import parse_detail
 from service_error import *
+
+import logging
+
+class nullHandler(logging.Handler):
+    def emit(self, record): pass
+
+fl = logging.getLogger("fedd.experiment_control")
+fl.addHandler(nullHandler())
 
 class fedd_experiment_control_local:
@@ -91,15 +99,12 @@
 		    self.exception = s
 		    if self.trace_file:
-			print >>self.trace_file, "Thread exception: %s %s" % \
-				(s.code_string(), s.desc)
-		    
+			logging.error("Thread exception: %s %s" % \
+				(s.code_string(), s.desc))
 		except:
 		    self.exception = sys.exc_info()[1]
 		    if self.trace_file:
-			print >>self.trace_file, \
-				"Unexpected thread exception: %s" % \
-				self.exception
-			print >>self.trace_file, "Trace: %s" % \
-				traceback.format_exc()
+			logging.error(("Unexpected thread exception: %s" +\
+				"Trace %s") % (self.exception,\
+				    traceback.format_exc()))
 	    if self.pdata:
 		self.pdata.terminate()
@@ -133,4 +138,5 @@
 	self.exp_stem = "fed-stem"
 	self.debug = config.create_debug
+	self.log = logging.getLogger("fedd.experiment_control")
 	self.muxmax = 2
 	self.nthreads = 2
@@ -176,4 +182,21 @@
 		raise service_error(service_error.internal,
 			"Cannot read sshpubkey")
+
+	# Set the logging level to the value passed in.  The getattr slieght of
+	# hand finds the logging level constant corrersponding to the string.
+	# We're a little paranoid to avoid user mayhem.
+	if config.experiment_log:
+	    try:
+		level = int(getattr(logging, config.experiment_log.upper(),-1))
+
+		if  logging.DEBUG <= level <= logging.CRITICAL:
+		    self.log.setLevel(level)
+		else:
+		    self.log.error("Bad experiment_log value: %s" % \
+			    config.experiment_log)
+
+	    except ValueError:
+		self.log.error("Bad experiment_log value: %s" % \
+			config.experiment_log)
 
 	# Grab saved state
@@ -262,8 +285,8 @@
 	    pickle.dump(self.state, f)
 	except IOError, e:
-	    print >>sys.stderr, "Can't write file %s: %s" % \
-		    (self.state_filename, e)
+	    self.log.error("Can't write file %s: %s" % \
+		    (self.state_filename, e))
 	except pickle.PicklingError, e:
-	    print >>sys.stderr, "Pickling problem: %s" % e
+	    self.log.error("Pickling problem: %s" % e)
 
     # Call while holding self.state_lock
@@ -273,8 +296,8 @@
 	    self.state = pickle.load(f)
 	except IOError, e:
-	    print >>sys.stderr, "Can't open %s: %s" % \
-		    (self.state_filename, e)
+	    self.log.warning("No saved state: Can't open %s: %s" % \
+		    (self.state_filename, e))
 	except pickle.UnpicklingError, e:
-	    print >>sys.stderr, "Unpickling failed: %s" % e
+	    self.log.warning("No saved state: Unpickling failed: %s" % e)
 
     def scp_file(self, file, user, host, dest=""):
@@ -284,20 +307,9 @@
 
 	scp_cmd = [self.scp_exec, file, "%s@%s:%s" % (user, host, dest)]
-
-	trace = self.trace_file
-	if not trace:
-	    try:
-		trace = open("/dev/null", "w")
-	    except IOError:
-		raise service_error(service_error.internal,
-			"Cannot open /dev/null??");
-
+	rv = 0
+
+	self.log.debug("[scp_file]: %s" % " ".join(scp_cmd))
 	if not self.debug:
 	    rv = call(scp_cmd, stdout=trace, stderr=trace)
-	else:
-	    if self.trace_file: 
-		print >>self.trace_file, "debug [scp_file]: %s" % \
-			" ".join(scp_cmd)
-	    rv = 0
 
 	return rv == 0
@@ -306,18 +318,9 @@
 	sh_str = "%s %s@%s %s" % (self.ssh_exec, user, host, cmd)
 
-	trace = self.trace_file
-	if not trace:
-	    try:
-		trace = open("/dev/null", "w")
-	    except IOError:
-		raise service_error(service_error.internal,
-			"Cannot open /dev/null??");
-
+	self.log.debug("[ssh_cmd]: %s" % sh_str)
 	if not self.debug:
 	    sub = Popen(sh_str, shell=True, stdout=trace, stderr=trace)
 	    return sub.wait() == 0
 	else:
-	    if self.trace_file:
-		print >>self.trace_file,"debug [ssh_cmd]: %s" % sh_str 
 	    return True
 
@@ -365,18 +368,12 @@
 	cmd = [self.ssh_exec, "%s@%s" % (user, host), expinfo_exec, pid, eid]
 
-
-	if self.trace_file:
-	    print >>self.trace_file, "status request: %s" % " ".join(cmd)
-	
-	if not self.trace_file:
-	    try:
-		st_file = open("/dev/null", "w")
-	    except IOError:
-		raise service_error(service_error.internal, 
-			"Cannot open /dev/null!?")
-	else:
-	    st_file = self.trace_file
-
-	status = Popen(cmd, stdout=PIPE, stderr=st_file)
+	self.log.debug("[start_segment]: %s"% " ".join(cmd))
+	dev_null = None
+	try:
+	    dev_null = open("/dev/null", "a")
+	except IOError, e:
+	    self.log.error("[start_segment]: can't open /dev/null: %s" %e)
+
+	status = Popen(cmd, stdout=PIPE, stderr=dev_null)
 	for line in status.stdout:
 	    m = state_re.match(line)
@@ -392,7 +389,7 @@
 	    raise service_error(service_error.internal,
 		    "Cannot get status of segment %s:%s/%s" % (tb, pid, eid))
-	if self.trace_file:
-	    print >>self.trace_file, "%s: %s" % (tb, state)
-	    print >>self.trace_file, "transferring experiment to %s" % tb
+
+	self.log.debug("[start_segment]: %s: %s" % (tb, state))
+	self.log.info("[start_segment]:transferring experiment to %s" % tb)
 
 	if not self.scp_file("%s/%s/%s" % (tmpdir, tb, tclfile), user, host):
@@ -433,6 +430,5 @@
 			"%s/rpms" % tmpdir, tarfiles_dir):
 		    return False
-	    if self.trace_file:
-		print >>self.trace_file, "Modifying %s on %s" % (eid, tb)
+	    self.log.info("[start_segment]: Modifying %s on %s" % (eid, tb))
 	    if not self.ssh_cmd(user, host,
 		    "/usr/testbed/bin/modexp -r -s -w %s %s %s" % \
@@ -459,12 +455,10 @@
 			"%s/rpms" % tmpdir, tarfiles_dir):
 		    return False
-	    if self.trace_file:
-		print >>self.trace_file, "Modifying %s on %s" % (eid, tb)
+	    self.log.info("[start_segment]: Modifying %s on %s" % (eid, tb))
 	    if not self.ssh_cmd(user, host,
 		    "/usr/testbed/bin/modexp -w %s %s %s" % (pid, eid, tclfile),
 		    "modexp"):
 		return False
-	    if self.trace_file:
-		print >>self.trace_file, "Swapping %s in on %s" % (eid, tb)
+	    self.log.info("[start_segment]: Swapping %s in on %s" % (eid, tb))
 	    if not self.ssh_cmd(user, host,
 		    "/usr/testbed/bin/swapexp -w %s %s in" % (pid, eid),
@@ -486,6 +480,5 @@
 			"%s/rpms" % tmpdir, tarfiles_dir):
 		    return False
-	    if self.trace_file:
-		print >>self.trace_file, "Creating %s on %s" % (eid, tb)
+	    self.log.info("[start_segment]: Creating %s on %s" % (eid, tb))
 	    if not self.ssh_cmd(user, host,
 		    "/usr/testbed/bin/startexp -i -f -w -p %s -e %s %s" % \
@@ -502,6 +495,5 @@
 		    proj_dir):
 		return False
-	    if self.trace_file:
-		print >>self.trace_file, "Swapping %s in on %s" % (eid, tb)
+	    self.log.info("[start_segment]: Swapping %s in on %s" % (eid, tb))
 	    if not self.ssh_cmd(user, host,
 		    "/usr/testbed/bin/swapexp -w %s %s in" % (pid, eid),
@@ -510,6 +502,5 @@
 	    return True
 	else:
-	    if self.trace_file:
-		print >>self.trace_file, "unknown state %s" % state
+	    self.log.debug("[start_segment]:unknown state %s" % state)
 	    return False
 
@@ -519,6 +510,5 @@
 	pid = tbparams[tb]['project']
 
-	if self.trace_file:
-	    print >>self.trace_file, "Stopping %s on %s" % (eid, tb)
+	self.log.info("[stop_segment]: Stopping %s on %s" % (eid, tb))
 	return self.ssh_cmd(user, host,
 		"/usr/testbed/bin/swapexp -w %s %s out" % (pid, eid))
@@ -534,16 +524,15 @@
 	t = type.lower();
 	if t not in valid_types: raise ValueError
-
-	trace = self.trace_file
-	if not trace:
-	    try:
-		trace = open("/dev/null", "w")
-	    except IOError:
-		raise service_error(service_error.internal,
-			"Cannot open /dev/null??");
+	cmd = [self.ssh_keygen, '-t', t, '-N', '', '-f', dest]
+
+	try:
+	    trace = open("/dev/null", "w")
+	except IOError:
+	    raise service_error(service_error.internal,
+		    "Cannot open /dev/null??");
 
 	# May raise CalledProcessError
-	rv = call([self.ssh_keygen, '-t', t, '-N', '', '-f', dest],
-		stdout=trace, stderr=trace)
+	self.log.debug("[generate_ssh_keys]: %s" % " ".join(cmd))
+	rv = call(cmd, stdout=trace, stderr=trace)
 	if rv != 0:
 	    raise service_error(service_error.internal, 
@@ -1007,7 +996,6 @@
 		    else:
 			# XXX
-			print >>sys.stderr, \
-			    "Ignoring gateways for unknown testbed %s" \
-				    % self.current_gateways
+			self.log.error("[gateways]: Ignoring gateways for " + \
+				"unknown testbed %s" % self.current_gateways)
 			self.current_gateways = None
 		    return True
@@ -1052,7 +1040,6 @@
 				    "Error creating seer config")
 		    else:
-			if self.trace_file:
-			    print >>sys.stderr, "No control gateway for %s" %\
-				    self.current_gateways
+			debug.error("[gateways]: No control gateway for %s" %\
+				    self.current_gateways)
 		    self.current_gateways = None
 		else:
@@ -1374,15 +1361,12 @@
 		    "Swap in failed on %s" % ",".join(failed))
 	else:
-	    if self.trace_file:
-		print >>self.trace_file, "Experiment started"
+	    self.log.info("[start_segment]: Experiment %s started" % eid)
 
 	# Generate an ID for the experiment (slice) and a certificate that the
 	# allocator can use to prove they own it.  We'll ship it back through
 	# the encrypted connection.
-	(expid, expcert) = generate_fedid("test", dir=tmpdir, 
-		trace=self.trace_file)
-
-	if self.trace_file:
-	    print >>self.trace_file, "removing %s" % tmpdir
+	(expid, expcert) = generate_fedid("test", dir=tmpdir, log=self.log)
+
+	self.log.debug("[start_experiment]: removing %s" % tmpdir)
 
 	# Walk up tmpdir, deleting as we go
