Index: fedd/federation/access.py
===================================================================
--- fedd/federation/access.py	(revision 2bb8b35f2ed6f40e844649d404f4d691cae9af18)
+++ fedd/federation/access.py	(revision 8cab4c2ac9081127246fc22ca388f2d95738148a)
@@ -784,4 +784,5 @@
         """
 
+	self.log.info("RequestAccess called by %s" % fid)
         # The dance to get into the request body
         if req.has_key('RequestAccessRequestBody'):
@@ -829,4 +830,5 @@
 	checked and if valid, the state and cached certificate are destroyed.
 	"""
+	self.log.info("ReleaseAccess called by %s" % fid)
         # The dance to get into the request body
         if req.has_key('ReleaseAccessRequestBody'):
@@ -871,4 +873,5 @@
 	    self.log.debug("[ReleaseAccess] Removing %s" % cf)
 	    os.remove(cf)
+	    self.log.info("ReleaseAccess succeeded for %s" % fid)
 	    return { 'allocID': req['allocID'], 'proof': proof.to_dict() } 
 	else:
Index: fedd/federation/emulab_access.py
===================================================================
--- fedd/federation/emulab_access.py	(revision 2bb8b35f2ed6f40e844649d404f4d691cae9af18)
+++ fedd/federation/emulab_access.py	(revision 8cab4c2ac9081127246fc22ca388f2d95738148a)
@@ -241,4 +241,5 @@
 	    return rv
 
+	self.log.info("RequestAccess called by %s" % fid)
         # The dance to get into the request body
         if req.has_key('RequestAccessRequestBody'):
@@ -291,6 +292,9 @@
 	    f.close()
 	except EnvironmentError, e:
+	    self.log.info("RequestAccess failed for by %s: internal error" \
+		    % fid)
 	    raise service_error(service_error.internal, 
 		    "Can't open %s/%s : %s" % (self.certdir, aid, e))
+	self.log.debug('RequestAccess Returning allocation ID: %s' % allocID)
 	resp = self.build_access_response({ 'fedid': allocID } ,
 		pname, services, proof)
@@ -298,4 +302,5 @@
 
     def ReleaseAccess(self, req, fid):
+	self.log.info("ReleaseAccess called by %s" % fid)
         # The dance to get into the request body
         if req.has_key('ReleaseAccessRequestBody'):
@@ -335,4 +340,5 @@
 	    self.log.debug("Removing %s" % cf)
 	    os.remove(cf)
+	    self.log.info("ReleaseAccess succeeded for %s" % fid)
 	    return { 'allocID': req['allocID'], 'proof': proof.to_dict() } 
 	else:
@@ -811,4 +817,5 @@
 	rv = None   # Return value from segment creation
 
+	self.log.info("StartSegment called by %s" % fid)
 	try:
 	    req = req['StartSegmentRequestBody']
@@ -826,4 +833,5 @@
 		with_proof=True)
 	if not access_ok:
+	    self.log.info("StartSegment for %s failed: access denied" % fid)
 	    raise service_error(service_error.access, "Access denied")
 	else:
@@ -852,4 +860,5 @@
 	    os.mkdir(softdir)
         except EnvironmentError:
+	    self.log.info("StartSegment for %s failed: internal error" % fid)
             raise service_error(service_error.internal, "Cannot create tmp dir")
 
@@ -884,7 +893,10 @@
 	    rv = starter(self, ename, proj, user, expfile, tmpdir, gid=gid)
 	except service_error, e:
+	    self.log.info("StartSegment for %s failed: %s"  % (fid, e))
 	    err = e
 	except:
 	    t, v, st = sys.exc_info()
+	    self.log.info("StartSegment for %s failed: unexpected error:  %s" \
+		    % (fid, v, traceback.extract_tb(st)))
 	    err = service_error(service_error.internal, "%s: %s" % \
 		    (v, traceback.extract_tb(st)))
@@ -895,4 +907,5 @@
 
 	if rv:
+	    self.log.info("StartSegment for %s succeeded" % fid)
 	    return self.finalize_experiment(starter, topo, aid, req['allocID'],
 		    proof)
@@ -904,4 +917,5 @@
 
     def TerminateSegment(self, req, fid):
+	self.log.info("TerminateSegment called by %s" % fid)
 	try:
 	    req = req['TerminateSegmentRequestBody']
@@ -934,4 +948,6 @@
 
 	if not proj:
+	    self.log.info("TerminateSegment failed for %s: cannot find project"\
+		    % fid)
 	    raise service_error(service_error.internal, 
 		    "Can't find project for %s" % aid)
@@ -941,7 +957,12 @@
 
 	if not user:
+	    self.log.info("TerminateSegment failed for %s: cannot find user"\
+		    % fid)
 	    raise service_error(service_error.internal, 
 		    "Can't find creation user for %s" % aid)
 	if not ename:
+	    self.log.info(
+		    "TerminateSegment failed for %s: cannot find experiment"\
+		    % fid)
 	    raise service_error(service_error.internal, 
 		    "Can't find experiment name for %s" % aid)
@@ -950,7 +971,10 @@
 		cert=xmlrpc_cert)
 	stopper(self, user, proj, ename, gid, nonce)
+	self.log.info("TerminateSegment succeeded for %s %s %s" % \
+		(fid, proj, ename))
 	return { 'allocID': req['allocID'], 'proof': proof.to_dict() }
 
     def InfoSegment(self, req, fid):
+	self.log.info("InfoSegment called by %s" % fid)
 	try:
 	    req = req['InfoSegmentRequestBody']
@@ -983,4 +1007,5 @@
 
 	if not proj:
+	    self.log.info("InfoSegment failed for %s: cannot find project"% fid)
 	    raise service_error(service_error.internal, 
 		    "Can't find project for %s" % aid)
@@ -990,7 +1015,9 @@
 
 	if not user:
+	    self.log.info("InfoSegment failed for %s: cannot find user"% fid)
 	    raise service_error(service_error.internal, 
 		    "Can't find creation user for %s" % aid)
 	if not ename:
+	    self.log.info("InfoSegment failed for %s: cannot find exp"% fid)
 	    raise service_error(service_error.internal, 
 		    "Can't find experiment name for %s" % aid)
@@ -999,4 +1026,6 @@
 		cert=xmlrpc_cert)
 	info(self, user, proj, ename)
+	self.log.info("InfoSegment gathered info for %s %s %s %s" % \
+		(fid, user, proj, ename))
 	self.decorate_topology(info, topo)
 	self.state_lock.acquire()
@@ -1005,4 +1034,6 @@
 	    self.write_state()
 	self.state_lock.release()
+	self.log.info("InfoSegment updated info for %s %s %s %s" % \
+		(fid, user, proj, ename))
 
 	rv = { 
@@ -1010,4 +1041,6 @@
 		'proof': proof.to_dict(),
 		}
+	self.log.info("InfoSegment succeeded info for %s %s %s %s" % \
+		(fid, user, proj, ename))
 	if topo:
 	    rv['segmentdescription'] = { 'topdldescription' : topo.to_dict() }
@@ -1024,4 +1057,5 @@
 		return None
 
+	self.log.info("OperationSegment called by %s" % fid)
 	try:
 	    req = req['OperationSegmentRequestBody']
@@ -1035,4 +1069,5 @@
 		with_proof=True)
 	if not access_ok:
+	    self.log.info("OperationSegment failed for %s: access denied" % fid)
 	    raise service_error(service_error.access, "Access denied")
 
@@ -1042,6 +1077,8 @@
 
 	if op is None :
+	    self.log.info("OperationSegment failed for %s: no operation" % fid)
 	    raise service_error(service_error.req, "missing operation")
 	elif targets is None:
+	    self.log.info("OperationSegment failed for %s: no targets" % fid)
 	    raise service_error(service_error.req, "no targets")
 
@@ -1072,6 +1109,8 @@
 		cert=xmlrpc_cert)
 	ops(self, op, ptargets, params, topo)
+	self.log.info("OperationSegment operated for %s" % fid)
 	
 	status.extend(ops.status)
+	self.log.info("OperationSegment succeed for %s" % fid)
 
 	return { 
Index: fedd/federation/experiment_control.py
===================================================================
--- fedd/federation/experiment_control.py	(revision 2bb8b35f2ed6f40e844649d404f4d691cae9af18)
+++ fedd/federation/experiment_control.py	(revision 8cab4c2ac9081127246fc22ca388f2d95738148a)
@@ -1661,6 +1661,11 @@
 	    self.auth.save()
 
-	access_ok, proof = self.auth.check_attribute(fid, 'new', 
-		with_proof=True)
+	try:
+	    access_ok, proof = self.auth.check_attribute(fid, 'new', 
+		    with_proof=True)
+	except service_error, e:
+	    self.log.info("New experiment call for %s: access denied" % fid)
+	    raise e
+
 
         if not access_ok:
@@ -1998,5 +2003,9 @@
             raise service_error(service_error.req, "No request?")
 
-        proof = self.check_experiment_access(fid, key)
+	try:
+	    proof = self.check_experiment_access(fid, key)
+	except service_error, e:
+	    self.log.info("vtopo call failed for %s: access denied" %  fid)
+	    raise e
 
         self.state_lock.acquire()
@@ -2053,5 +2062,9 @@
             raise service_error(service_error.req, "No request?")
 
-        proof = self.check_experiment_access(fid, key)
+	try:
+	    proof = self.check_experiment_access(fid, key)
+	except service_error, e:
+	    self.log.info("vis call failed for %s: access denied" %  fid)
+	    raise e
 
         self.state_lock.acquire()
@@ -2155,6 +2168,12 @@
 	    self.auth.save()
 
-	# Make sure that the caller can talk to us
-        proof = self.check_experiment_access(fid, key)
+	try:
+	    # Make sure that the caller can talk to us
+	    proof = self.check_experiment_access(fid, key)
+	except service_error, e:
+	    self.log.info("Create experiment call failed for %s: access denied"\
+		    % fid)
+	    raise e
+
 
 	# Install the testbed map entries supplied with the request into a copy
@@ -2398,5 +2417,9 @@
             raise service_error(service_error.req, "No request?")
 
-        proof = self.check_experiment_access(fid, key)
+	try:
+	    proof = self.check_experiment_access(fid, key)
+	except service_error, e:
+	    self.log.info("Info call failed for %s: access denied" %  fid)
+
 
 	self.update_info(key, fresh)
@@ -2498,4 +2521,5 @@
 	    else: return None
 
+	self.log.info("Operation call started for %s" %  fid)
         req = req.get('OperationRequestBody', None)
         if not req:
@@ -2522,5 +2546,10 @@
             raise service_error(service_error.req, "No request?")
 
-        proof = self.check_experiment_access(fid, key)
+	try:
+	    proof = self.check_experiment_access(fid, key)
+	except service_error, e:
+	    self.log.info("Operation call failed for %s: access denied" %  fid)
+	    raise e
+
 	self.state_lock.acquire()
 	if key in self.state:
@@ -2534,4 +2563,5 @@
 
 	if top is None:
+	    self.log.info("Operation call failed for %s: not active" %  fid)
 	    raise service_error(service_error.partial, "No topology yet", 
 		    proof=proof)
@@ -2558,4 +2588,5 @@
 		results)
 
+	self.log.info("Operation call succeeded for %s" %  fid)
 	return { 
 		'experiment': exp, 
@@ -2720,5 +2751,11 @@
 
 	key = self.get_experiment_key(req, 'experiment')
-        proof = self.check_experiment_access(fid, key)
+	try:
+	    proof = self.check_experiment_access(fid, key)
+	except service_error, e:
+	    self.log.info(
+		    "Terminate experiment call failed for %s: access denied" \
+			    % fid)
+	    raise e
         exp = req.get('experiment', False)
         force = req.get('force', False)
