[Cluster-devel] [PATCH] fencing: Replace printing to stderr with proper logging solution

[Marek 'marx' Grac <mgrac@redhat.com>]

This patch replaces local solutions by standard python logging module. Levels of messages
is not final, it just reflects the previous state. So, debug level is available only with
-v / verbose option.
---
 fence/agents/amt/fence_amt.py             | 33 +++++++++++++++----------
 fence/agents/cisco_ucs/fence_cisco_ucs.py |  6 ++---
 fence/agents/dummy/fence_dummy.py         |  3 ++-
 fence/agents/eps/fence_eps.py             | 15 ++++--------
 fence/agents/ipmilan/fence_ipmilan.py     | 26 ++++++++++----------
 fence/agents/lib/XenAPI.py.py             |  4 ++--
 fence/agents/lib/fencing.py.py            | 40 +++++++++++++++++--------------
 fence/agents/lib/fencing_snmp.py.py       |  4 ++--
 fence/agents/ovh/fence_ovh.py             | 16 ++++++-------
 fence/agents/rhevm/fence_rhevm.py         |  6 ++---
 fence/agents/sanbox2/fence_sanbox2.py     |  3 ++-
 fence/agents/vmware/fence_vmware.py       |  4 ++--
 12 files changed, 84 insertions(+), 76 deletions(-)

diff --git a/fence/agents/amt/fence_amt.py b/fence/agents/amt/fence_amt.py
index 81b8aec..f4dff4b 100644
--- a/fence/agents/amt/fence_amt.py
+++ b/fence/agents/amt/fence_amt.py
@@ -1,6 +1,7 @@
 #!/usr/bin/python
 
 import sys, subprocess, re, os, stat
+import logging
 from pipes import quote
 sys.path.append("@FENCEAGENTSLIBDIR@")
 from fencing import *
@@ -15,19 +16,19 @@ def get_power_status(_, options):
 
     cmd = create_command(options, "status")
 
-    if options["log"] >= LOG_MODE_VERBOSE:
-        options["debug_fh"].write("executing: " + cmd + "\n")
-
     try:
+        logging.debug("Running: %s" % cmd)
         process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE, shell=True)
     except OSError:
         fail_usage("Amttool not found or not accessible")
 
     process.wait()
 
-    output = process.communicate()
+    out = process.communicate()
     process.stdout.close()
-    options["debug_fh"].write(output)
+    process.stderr.close()
+    logging.debug("%s\n" % str(out))
+
 
     match = re.search('Powerstate:[\\s]*(..)', str(output))
     status = match.group(1) if match else None
@@ -43,30 +44,36 @@ def set_power_status(_, options):
 
     cmd = create_command(options, options["--action"])
 
-    if options["log"] >= LOG_MODE_VERBOSE:
-        options["debug_fh"].write("executing: " + cmd + "\n")
-
     try:
-        process = subprocess.Popen(cmd, stdout=options["debug_fh"], stderr=options["debug_fh"], shell=True)
+        logging.debug("Running: %s" % cmd)
+        process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE, shell=True)
     except OSError:
         fail_usage("Amttool not found or not accessible")
 
     process.wait()
 
+    out = process.communicate()
+    process.stdout.close()
+    process.stderr.close()
+    logging.debug("%s\n" % str(out))
+
     return
 
 def reboot_cycle(_, options):
     cmd = create_command(options, "cycle")
 
-    if options["log"] >= LOG_MODE_VERBOSE:
-        options["debug_fh"].write("executing: " + cmd + "\n")
-
     try:
-        process = subprocess.Popen(cmd, stdout=options["debug_fh"], stderr=options["debug_fh"], shell=True)
+        logging.debug("Running: %s" % cmd)
+        process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE, shell=True)
     except OSError:
         fail_usage("Amttool not found or not accessible")
 
     status = process.wait()
+
+    out = process.communicate()
+    process.stdout.close()
+    process.stderr.close()
+    logging.debug("%s\n" % str(out))
     
     return not bool(status)
 
diff --git a/fence/agents/cisco_ucs/fence_cisco_ucs.py b/fence/agents/cisco_ucs/fence_cisco_ucs.py
index 71782cb..dc413d8 100644
--- a/fence/agents/cisco_ucs/fence_cisco_ucs.py
+++ b/fence/agents/cisco_ucs/fence_cisco_ucs.py
@@ -2,6 +2,7 @@
 
 import sys, re
 import pycurl, StringIO
+import logging
 sys.path.append("@FENCEAGENTSLIBDIR@")
 from fencing import *
 
@@ -90,9 +91,8 @@ def send_command(opt, command, timeout):
 	c.perform()
 	result = b.getvalue()
 
-	if opt["log"] >= LOG_MODE_VERBOSE:
-		opt["debug_fh"].write(command + "\n")
-		opt["debug_fh"].write(result + "\n")
+	logging.debug("%s\n" % command)
+	logging.debug("%s\n" % results)
 
 	return result
 
diff --git a/fence/agents/dummy/fence_dummy.py b/fence/agents/dummy/fence_dummy.py
index d5bb748..95a3579 100644
--- a/fence/agents/dummy/fence_dummy.py
+++ b/fence/agents/dummy/fence_dummy.py
@@ -1,6 +1,7 @@
 #!/usr/bin/python
 
 import sys, re, pexpect, exceptions, random
+import logging
 sys.path.append("@FENCEAGENTSLIBDIR@")
 from fencing import *
 
@@ -117,7 +118,7 @@ def main():
 	if options.has_key("--random_sleep_range"):
 		val = int(options["--random_sleep_range"])
 		ran = random.randint(1, val)
-		sys.stderr.write("random sleep for %d seconds\n" % ran)
+		logging.info("Random sleep for %d seconds\n" % ran)
 		time.sleep(ran)
 
 	if options["--type"] == "fail":
diff --git a/fence/agents/eps/fence_eps.py b/fence/agents/eps/fence_eps.py
index 0e7709d..be50bd5 100644
--- a/fence/agents/eps/fence_eps.py
+++ b/fence/agents/eps/fence_eps.py
@@ -5,6 +5,7 @@
 
 import sys, re
 import httplib, base64, string, socket
+import logging
 sys.path.append("@FENCEAGENTSLIBDIR@")
 from fencing import *
 
@@ -14,11 +15,6 @@ REDHAT_COPYRIGHT=""
 BUILD_DATE=""
 #END_VERSION_GENERATION
 
-# Log actions and results from EPS device
-def eps_log(options, str):
-	if options["log"] >= LOG_MODE_VERBOSE:
-		options["debug_fh"].write(str)
-
 # Run command on EPS device.
 # @param options Device options
 # @param params HTTP GET parameters (without ?)
@@ -32,7 +28,7 @@ def eps_run_command(options, params):
 		if (params!=""):
 			request_str += "?"+params
 
-		eps_log(options, "GET "+request_str+"\n")
+		logging.debug("GET %s\n" % request_str)
 		conn.putrequest('GET', request_str)
 
 		if (options.has_key("--username")):
@@ -41,23 +37,22 @@ def eps_run_command(options, params):
 				
 			# String for Authorization header
 			auth_str = 'Basic ' + string.strip(base64.encodestring(options["--username"]+':'+options["--password"]))
-			eps_log(options, "Authorization:"+auth_str+"\n")
+			logging.debug("Authorization: %s\n" % auth_str)
 			conn.putheader('Authorization', auth_str)
 
 		conn.endheaders()
 
 		response = conn.getresponse()
 
-		eps_log(options, "%d %s\n"%(response.status, response.reason))
+		logging.debug("%d %s\n"%(response.status, response.reason))
 
 		#Response != OK -> couldn't login
 		if (response.status!=200):
 			fail(EC_LOGIN_DENIED)
 
 		result = response.read()
-		eps_log(options, result+"\n")
+		logging.debug("%s \n" % result)
 		conn.close()
-
 	except socket.timeout:
 		fail(EC_TIMED_OUT)
 	except socket.error:
diff --git a/fence/agents/ipmilan/fence_ipmilan.py b/fence/agents/ipmilan/fence_ipmilan.py
index de42524..4731be1 100644
--- a/fence/agents/ipmilan/fence_ipmilan.py
+++ b/fence/agents/ipmilan/fence_ipmilan.py
@@ -1,6 +1,7 @@
 #!/usr/bin/python
 
 import sys, shlex, stat, subprocess, re, os
+import logging
 from pipes import quote
 sys.path.append("@FENCEAGENTSLIBDIR@")
 from fencing import *
@@ -15,10 +16,8 @@ def get_power_status(_, options):
 
     cmd = create_command(options, "status")
 
-    if options["log"] >= LOG_MODE_VERBOSE:
-        options["debug_fh"].write("executing: " + cmd + "\n")
-
     try:
+        logging.info("Executing: %s\n" % cmd)
         process = subprocess.Popen(shlex.split(cmd), stdout=subprocess.PIPE, stderr=subprocess.PIPE)
     except OSError:
         fail_usage("Ipmitool not found or not accessible")
@@ -27,7 +26,8 @@ def get_power_status(_, options):
 
     out = process.communicate()
     process.stdout.close()
-    options["debug_fh"].write(str(out) + "\n")
+    process.stderr.close()
+    logging.debug("%s\n" % str(out))
 
     match = re.search('[Cc]hassis [Pp]ower is [\\s]*([a-zA-Z]{2,3})', str(out))
     status = match.group(1) if match else None
@@ -38,25 +38,26 @@ def set_power_status(_, options):
 
     cmd = create_command(options, options["--action"])
 
-    if options["log"] >= LOG_MODE_VERBOSE:
-        options["debug_fh"].write("executing: " + cmd + "\n")
-
     try:
-        process = subprocess.Popen(shlex.split(cmd), stdout=options["debug_fh"], stderr=options["debug_fh"])
+        logging.debug("Executing: %s\n" % cmd)
+        process = subprocess.Popen(shlex.split(cmd), stdout=subprocess.PIPE, stderr=subprocess.PIPE)
     except OSError:
         fail_usage("Ipmitool not found or not accessible")
 
     process.wait()
 
+    out = process.communicate()
+    process.stdout.close()
+    process.stderr.close()
+    logging.debug("%s\n" % str(out))
+
     return
 
 def reboot_cycle(_, options):
     cmd = create_command(options, "cycle")
 
-    if options["log"] >= LOG_MODE_VERBOSE:
-        options["debug_fh"].write("executing: " + cmd + "\n")
-
     try:
+        logging.debug("Executing: %s\n" % cmd)
         process = subprocess.Popen(shlex.split(cmd), stdout=subprocess.PIPE, stderr=subprocess.PIPE)
     except OSError:
         fail_usage("Ipmitool not found or not accessible")
@@ -65,7 +66,8 @@ def reboot_cycle(_, options):
 
     out = process.communicate()
     process.stdout.close()
-    options["debug_fh"].write(str(out) + "\n")
+    process.stderr.close()
+    logging.debug("%s\n" % str(out))
 
     return bool(re.search('chassis power control: cycle', str(out).lower()))
 
diff --git a/fence/agents/lib/XenAPI.py.py b/fence/agents/lib/XenAPI.py.py
index ce905fd..9928bba 100644
--- a/fence/agents/lib/XenAPI.py.py
+++ b/fence/agents/lib/XenAPI.py.py
@@ -48,6 +48,7 @@ import gettext
 import xmlrpclib
 import httplib
 import socket
+import logging
 
 translation = gettext.translation('xen-xm', fallback = True)
 
@@ -72,8 +73,7 @@ class Failure(Exception):
 			return "Message database broken: %s.\nXen-API failure: %s" % \
 				   (exn, str(self.details))
 		except Exception, exn:
-			import sys
-			print >> sys.stderr, exn
+			logging.error("%s\n" % str(exn))
 			return "Xen-API failure: %s" % str(self.details)
 
 	def _details_map(self):
diff --git a/fence/agents/lib/fencing.py.py b/fence/agents/lib/fencing.py.py
index 5dd188e..48c5540 100644
--- a/fence/agents/lib/fencing.py.py
+++ b/fence/agents/lib/fencing.py.py
@@ -2,6 +2,7 @@
 
 import sys, getopt, time, os, uuid, pycurl, stat
 import pexpect, re, atexit, syslog
+import logging
 import __main__
 
 ## do not add code here.
@@ -376,15 +377,19 @@ DEPENDENCY_OPT = {
 
 class fspawn(pexpect.spawn):
 	def __init__(self, options, command):
+		logging.info("Running command: %s" % command)
 		pexpect.spawn.__init__(self, command)
 		self.opt = options
 		
 	def log_expect(self, options, pattern, timeout):
 		result = self.expect(pattern, timeout)
-		if options["log"] >= LOG_MODE_VERBOSE:
-			options["debug_fh"].write(self.before + self.after)
+		logging.debug("Received: %s" % (self.before + self.after))
 		return result
 
+	def send(self, message):
+		logging.debug("Sent: %s" % message)
+		pexpect.spawn.send(self,message)
+
 	# send EOL according to what was detected in login process (telnet)
 	def send_eol(self, message):
 		self.send(message + self.opt["eol"])
@@ -394,7 +399,7 @@ def atexit_handler():
 		sys.stdout.close()
 		os.close(1)
 	except IOError:
-		sys.stderr.write("%s failed to close standard output\n"%(sys.argv[0]))
+		logging.error("%s failed to close standard output\n" % (sys.argv[0]))
 		syslog.syslog(syslog.LOG_ERR, "Failed to close standard output")
 		sys.exit(EC_GENERIC_ERROR)
 
@@ -414,8 +419,8 @@ def version(command, release, build_date, copyright_notice):
 
 def fail_usage(message = ""):
 	if len(message) > 0:
-		sys.stderr.write(message+"\n")
-	sys.stderr.write("Please use '-h' for usage\n")
+		logging.error("%s\n" % message)
+	logging.error("Please use '-h' for usage\n")
 	sys.exit(EC_GENERIC_ERROR)
 
 def fail(error_code):
@@ -431,7 +436,7 @@ def fail(error_code):
 		EC_PASSWORD_MISSING : "Failed: You have to set login password",
 		EC_INVALID_PRIVILEGES : "Failed: The user does not have the correct privileges to do the requested action."
 	}[error_code] + "\n"
-	sys.stderr.write(message)
+	logging.error("%s\n" % message)
 	syslog.syslog(syslog.LOG_ERR, message)
 	sys.exit(EC_GENERIC_ERROR)
 
@@ -598,7 +603,7 @@ def process_input(avail_opt):
 			value = value[:-1]
 
 			if avail_opt.count(name) == 0:
-				sys.stderr.write("Parse error: Ignoring unknown option '"+line+"'\n")
+				logging.warning("Parse error: Ignoring unknown option '%s'\n" % line)
 				syslog.syslog(syslog.LOG_WARNING, "Parse error: Ignoring unknown option '"+line)
 				continue
 
@@ -672,9 +677,7 @@ def check_input(device_opt, opt):
 	options["--action"] = options["--action"].lower()
 
 	if options.has_key("--verbose"):
-		options["log"] = LOG_MODE_VERBOSE
-	else:
-		options["log"] = LOG_MODE_QUIET
+		logging.getLogger().setLevel(logging.DEBUG)
 
 	acceptable_actions = [ "on", "off", "status", "list", "monitor" ]
 	if 1 == device_opt.count("fabric_fencing"):
@@ -725,13 +728,13 @@ def check_input(device_opt, opt):
 
 	if options.has_key("--debug-file"):
 		try:
-			options["debug_fh"] = file (options["--debug-file"], "w")
+			fh = logging.FileHandler(options["--debug-file"])
+			fh.setLevel(logging.DEBUG)
+			logging.getLogger().addHandler(fh)
 		except IOError:
+			logging.error("Unable to create file %s" % options["--debug-file"])
 			fail_usage("Failed: Unable to create file " + options["--debug-file"])
 
-	if options.has_key("debug_fh") == 0:
-		options["debug_fh"] = sys.stderr
-
 	if options.has_key("--snmp-priv-passwd-script"):
 		options["--snmp-priv-passwd"] = os.popen(options["--snmp-priv-passwd-script"]).read().rstrip()
 
@@ -916,13 +919,13 @@ def fence_action(tn, options, set_power_fn, get_power_fn, get_outlet_list = None
 				except Exception, ex:
 					# an error occured during power ON phase in reboot
 					# fence action was completed succesfully even in that case
-					sys.stderr.write(str(ex))
+					logging.error("%s\n", str(ex))
 					syslog.syslog(syslog.LOG_NOTICE, str(ex))
 					pass
 
 			if power_on == False:
 				# this should not fail as node was fenced succesfully
-				sys.stderr.write('Timed out waiting to power ON\n')
+				logging.error('Timed out waiting to power ON\n')
 				syslog.syslog(syslog.LOG_NOTICE, "Timed out waiting to power ON")
 
 			print "Success: Rebooted"
@@ -937,7 +940,7 @@ def fence_action(tn, options, set_power_fn, get_power_fn, get_outlet_list = None
 	except pexpect.TIMEOUT:
 		fail(EC_TIMED_OUT)
 	except pycurl.error, ex:
-		sys.stderr.write(ex[1] + "\n")
+		logging.error("%s\n" % str(ex))
 		syslog.syslog(syslog.LOG_ERR, ex[1])
 		fail(EC_TIMED_OUT)
 	
@@ -961,6 +964,7 @@ def fence_login(options, re_login_string = "(login\s*: )|(Login Name:  )|(userna
 	## Do the delay of the fence device before logging in
 	## Delay is important for two-node clusters fencing but we do not need to delay 'status' operations
 	if options["--action"] in ["off", "reboot"]:
+		logging.info("Delay %s second(s) before logging in to the fence device" % options["--delay"])
 		time.sleep(int(options["--delay"]))
 
 	try:
@@ -976,7 +980,7 @@ def fence_login(options, re_login_string = "(login\s*: )|(Login Name:  )|(userna
 			try:
 				conn = fspawn(options, command)
 			except pexpect.ExceptionPexpect, ex:
-				sys.stderr.write(str(ex) + "\n")
+				logging.error("%s\n" % str(ex))
 				syslog.syslog(syslog.LOG_ERR, str(ex))
 				sys.exit(EC_GENERIC_ERROR)
 		elif options.has_key("--ssh") and 0 == options.has_key("--identity-file"):
diff --git a/fence/agents/lib/fencing_snmp.py.py b/fence/agents/lib/fencing_snmp.py.py
index 0112494..a5d7ef5 100644
--- a/fence/agents/lib/fencing_snmp.py.py
+++ b/fence/agents/lib/fencing_snmp.py.py
@@ -3,6 +3,7 @@
 # For example of use please see fence_cisco_mds
 
 import re, pexpect
+import logging
 from fencing import *
 
 ## do not add code here.
@@ -22,8 +23,7 @@ class FencingSnmp:
 
 	# Log message if user set verbose option
 	def log_command(self, message):
-		if self.options["log"] >= LOG_MODE_VERBOSE:
-			self.options["debug_fh"].write(message+"\n")
+		logging.debug("%s\n" % message)
 
 	def quote_for_run(self, string):
 		return ''.join(map(lambda x:x==r"'" and "'\\''" or x, string))
diff --git a/fence/agents/ovh/fence_ovh.py b/fence/agents/ovh/fence_ovh.py
index 2ec3fa0..c6c5ded 100644
--- a/fence/agents/ovh/fence_ovh.py
+++ b/fence/agents/ovh/fence_ovh.py
@@ -10,6 +10,7 @@
 
 import sys, time
 import shutil, tempfile
+import logging
 from datetime import datetime
 from suds.client import Client
 from suds.xsd.doctor import ImportDoctor, Import
@@ -122,20 +123,17 @@ Poweroff is simulated with a reboot into rescue-pro mode."
 	# Verify that action was completed sucesfully
 	reboot_t = reboot_time(options)
 
-	if options.has_key("--verbose"):
-		options["debug_fh"].write("reboot_start_end.start: "+ reboot_t.start.strftime('%Y-%m-%d %H:%M:%S')+"\n")         
-		options["debug_fh"].write("before_netboot_reboot: " + before_netboot_reboot.strftime('%Y-%m-%d %H:%M:%S')+"\n")
-		options["debug_fh"].write("reboot_start_end.end: "  + reboot_t.end.strftime('%Y-%m-%d %H:%M:%S')+"\n")        
-		options["debug_fh"].write("after_netboot_reboot: "  + after_netboot_reboot.strftime('%Y-%m-%d %H:%M:%S')+"\n")  
+	logging.debug("reboot_start_end.start: %s\n" % reboot_t.start.strftime('%Y-%m-%d %H:%M:%S'))
+	logging.debug("before_netboot_reboot: %s\n" % before_netboot_reboot.strftime('%Y-%m-%d %H:%M:%S'))
+	logging.debug("reboot_start_end.end: %s\n" % reboot_t.end.strftime('%Y-%m-%d %H:%M:%S'))
+	logging.debug("after_netboot_reboot: %s\n" % after_netboot_reboot.strftime('%Y-%m-%d %H:%M:%S'))
                 
 	if reboot_t.start < after_netboot_reboot < reboot_t.end:
 		result = 0
-		if options.has_key("--verbose"):
-			options["debug_fh"].write("Netboot reboot went OK.\n")
+		logging.debug("Netboot reboot went OK.\n")
 	else:
 		result = 1
-		if options.has_key("--verbose"):
-			options["debug_fh"].write("ERROR: Netboot reboot wasn't OK.\n")
+		logging.debug("ERROR: Netboot reboot wasn't OK.\n")
 
 	sys.exit(result)
 
diff --git a/fence/agents/rhevm/fence_rhevm.py b/fence/agents/rhevm/fence_rhevm.py
index ff3d19f..96a4cfa 100644
--- a/fence/agents/rhevm/fence_rhevm.py
+++ b/fence/agents/rhevm/fence_rhevm.py
@@ -2,6 +2,7 @@
 
 import sys, re
 import pycurl, StringIO
+import logging
 sys.path.append("@FENCEAGENTSLIBDIR@")
 from fencing import *
 
@@ -94,9 +95,8 @@ def send_command(opt, command, method = "GET"):
 	c.perform()
 	result = b.getvalue()
 
-	if opt["log"] >= LOG_MODE_VERBOSE:
-		opt["debug_fh"].write(command + "\n")
-		opt["debug_fh"].write(result + "\n")
+	logging.debug("%s\n" % command)
+	logging.debug("%s\n" % result)
 
 	return result
 
diff --git a/fence/agents/sanbox2/fence_sanbox2.py b/fence/agents/sanbox2/fence_sanbox2.py
index 5221d49..8f6b702 100644
--- a/fence/agents/sanbox2/fence_sanbox2.py
+++ b/fence/agents/sanbox2/fence_sanbox2.py
@@ -9,6 +9,7 @@
 #####
 
 import sys, re, pexpect, exceptions
+import logging
 sys.path.append("@FENCEAGENTSLIBDIR@")
 from fencing import *
 
@@ -129,7 +130,7 @@ because the connection will block any necessary fencing actions."
 	if (re.search("\(admin\)", conn.before, re.MULTILINE) == None):
 		## Someone else is in admin section, we can't enable/disable
 		## ports so we will rather exit
-		sys.stderr.write("Failed: Unable to switch to admin section\n")
+		logging.error("Failed: Unable to switch to admin section\n")
 		sys.exit(EC_GENERIC_ERROR)
 
 	result = fence_action(conn, options, set_power_status, get_power_status, get_list_devices)
diff --git a/fence/agents/vmware/fence_vmware.py b/fence/agents/vmware/fence_vmware.py
index dc4ef0f..b27cd95 100644
--- a/fence/agents/vmware/fence_vmware.py
+++ b/fence/agents/vmware/fence_vmware.py
@@ -23,6 +23,7 @@
 #
 
 import sys, re, pexpect, exceptions
+import logging
 sys.path.append("@FENCEAGENTSLIBDIR@")
 from fencing import *
 
@@ -136,8 +137,7 @@ def vmware_prepare_command(options, add_login_params, additional_params):
 
 # Log message if user set verbose option
 def vmware_log(options, message):
-	if options["log"] >= LOG_MODE_VERBOSE:
-		options["debug_fh"].write(message+"\n")
+	logging.debug("%s\n" % message)
 
 # Run command with timeout and parameters. Internaly uses vmware_prepare_command. Returns string
 # with output from vmrun command. If something fails (command not found, exit code is not 0), fail_usage
-- 
1.9.0