Merge pull request #99 from rundeck-plugins/improve-logging

RUN-2098: retry connection and increase connection logging

README.md

@@ -37,6 +37,10 @@ For further information see:
 It can be overwriting at node level using `winrm-readtimeout`
 * **operation timeout**: maximum allowed time in seconds for any single wsman HTTP operation (default 20). Note that operation timeouts while receiving output (the only wsman operation that should take any significant time, and where these timeouts are expected) will be silently retried indefinitely.
 It can be overwriting at node level using `winrm-operationtimeout`
+* **retry connection**: Retry a connection when it fails for connectivity issues (default 1).  
+  It can be overwriting at node level using `winrm-retry-connection`
+* **retry connection**: Delay between retries in seconds (default 10 seconds).
+  It can be overwriting at node level using `winrm-retry-connection-delay`
 
 For Kerberos
 * **krb5 Config File**: path of the krb5.conf (default: /etc/krb5.conf)

contents/winrm-exec.py

@@ -19,10 +19,22 @@ def filter(self, record):
 
 try:
     from urllib3.connectionpool import log
-    log.addFilter(SuppressFilter())
+    #log.addFilter(SuppressFilter())
 except:
     pass
 
+import http.client
+httpclient_logger = logging.getLogger("http.client")
+
+
+def httpclient_logging_patch(level=logging.DEBUG):
+    def httpclient_log(*args):
+        httpclient_logger.log(level, " ".join(args))
+
+    http.client.print = httpclient_log
+    http.client.HTTPConnection.debuglevel = 1
+
+
 #checking and importing dependencies
 ISPY3 = sys.version_info[0] == 3
 WINRM_INSTALLED = False
@@ -96,6 +108,10 @@ def filter(self, record):
 log.addHandler(console)
 log.setLevel(log_level)
 
+requests_log = logging.getLogger("requests.packages.urllib3")
+requests_log.setLevel(logging.DEBUG)
+requests_log.propagate = True
+
 parser = argparse.ArgumentParser(description='Run Bolt command.')
 parser.add_argument('hostname', help='the hostname')
 args = parser.parse_args()
@@ -118,6 +134,10 @@ def filter(self, record):
 forcefail = False
 exitBehaviour = "console"
 cleanescapingflg = False
+enabledHttpDebug = False
+retryconnection = 1
+retryconnectiondelay = 0
+username = None
 
 if "RD_CONFIG_AUTHTYPE" in os.environ:
     authentication = os.getenv("RD_CONFIG_AUTHTYPE")
@@ -164,6 +184,18 @@ def filter(self, record):
      else:
         cleanescapingflg = False
 
+if "RD_CONFIG_ENABLEDHTTPDEBUG" in os.environ:
+    if os.getenv("RD_CONFIG_ENABLEDHTTPDEBUG") == "true":
+        enabledHttpDebug = True
+    else:
+        enabledHttpDebug = False
+
+if "RD_CONFIG_RETRYCONNECTION" in os.environ:
+    retryconnection = int(os.getenv("RD_CONFIG_RETRYCONNECTION"))
+
+if "RD_CONFIG_RETRYCONNECTIONDELAY" in os.environ:
+    retryconnectiondelay = int(os.getenv("RD_CONFIG_RETRYCONNECTIONDELAY"))
+
 exec_command = os.getenv("RD_EXEC_COMMAND")
 log.debug("Command will be executed: " + exec_command)
 
@@ -220,17 +252,23 @@ def filter(self, record):
 log.debug("username:" + username)
 log.debug("nossl:" + str(nossl))
 log.debug("diabletls12:" + str(diabletls12))
-log.debug("krb5config:" + krb5config)
-log.debug("kinit command:" + kinit)
+log.debug("krb5config:" + str(krb5config))
+log.debug("kinit command:" + str(kinit))
 log.debug("kerberos delegation:" + str(krbdelegation))
 log.debug("shell:" + shell)
 log.debug("output_charset:" + output_charset)
 log.debug("readtimeout:" + str(readtimeout))
 log.debug("operationtimeout:" + str(operationtimeout))
 log.debug("exit Behaviour:" + exitBehaviour)
 log.debug("cleanescapingflg: " + str(cleanescapingflg))
+log.debug("enabledHttpDebug: " + str(enabledHttpDebug))
+log.debug("retryConnection: " + str(retryconnection))
+log.debug("retryConnectionDelay: " + str(retryconnectiondelay))
 log.debug("------------------------------------------")
 
+if enabledHttpDebug:
+    httpclient_logging_patch(logging.DEBUG)
+
 if not URLLIB_INSTALLED:
     log.error("request and urllib3 not installed, try: pip install requests &&  pip install urllib3")
     sys.exit(1)
@@ -287,7 +325,7 @@ def filter(self, record):
 winrm.Session._clean_error_msg = winrm_session._clean_error_msg
 winrm.Session._strip_namespace = winrm_session._strip_namespace
 
-tsk = winrm_session.RunCommand(session, shell, exec_command, output_charset)
+tsk = winrm_session.RunCommand(session, shell, exec_command, retryconnection, retryconnectiondelay, output_charset)
 t = threading.Thread(target=tsk.get_response)
 t.start()
 realstdout = sys.stdout

contents/winrm-filecopier.py

@@ -15,8 +15,10 @@
 import colored_formatter
 from colored_formatter import ColoredFormatter
 import kerberosauth
+import http.client
+import winrm_session
 
-#checking and importing dependencies
+# checking and importing dependencies
 ISPY3 = sys.version_info[0] == 3
 WINRM_INSTALLED = False
 URLLIB_INSTALLED = False
@@ -81,14 +83,7 @@
 else:
     log_level = 'ERROR'
 
-##end
-
-
-log_level = 'INFO'
-if os.environ.get('RD_JOB_LOGLEVEL') == 'DEBUG':
-    log_level = 'DEBUG'
-else:
-    log_level = 'ERROR'
+# end
 
 console = logging.StreamHandler()
 console.setFormatter(ColoredFormatter(colored_formatter.format()))
@@ -98,6 +93,17 @@
 log.addHandler(console)
 log.setLevel(log_level)
 
+httpclient_logger = logging.getLogger("http.client")
+
+
+def httpclient_logging_patch(level=logging.DEBUG):
+    def httpclient_log(*args):
+        httpclient_logger.log(level, " ".join(args))
+
+    http.client.print = httpclient_log
+    http.client.HTTPConnection.debuglevel = 1
+
+
 def _clean_error_msg(self, msg):
     """converts a Powershell CLIXML message to a more human readable string
     """
@@ -165,8 +171,10 @@ class WinRmError(RemoteCommandError):
 
 class CopyFiles(object):
 
-    def __init__(self, session):
-        self.session=session
+    def __init__(self, session, retry, retry_delay):
+        self.session = session
+        self.retry = retry
+        self.retry_delay = retry_delay
 
 
     def winrm_upload(self,
@@ -184,10 +192,12 @@ def winrm_upload(self,
 
         print("coping file %s to %s" % (local_path, full_path))
 
-        self.session.run_ps('if (!(Test-Path {0})) {{ New-Item -ItemType directory -Path {0} }}'.format(remote_path))
+        self.session.run_ps('if (!(Test-Path {0})) {{ New-Item -ItemType directory -Path {0} }}'.format(remote_path),
+                            retry=self.retry,
+                            retry_delay=self.retry_delay)
 
-        if(override):
-            self.session.run_ps('if ((Test-Path {0} -PathType Leaf)) {{ rm {0} }}'.format(full_path))
+        if override:
+            self.session.run_ps('if ((Test-Path {0} -PathType Leaf)) {{ rm {0} }}'.format(full_path), retry=self.retry, retry_delay=self.retry_delay)
 
         size = os.stat(local_path).st_size
         with open(local_path, 'rb') as f:
@@ -250,6 +260,13 @@ def winrm_upload(self,
 krbdelegation = False
 forceTicket = False
 override=False
+enabledHttpDebug = False
+readtimeout = None
+operationtimeout = None
+retryconnection = 1
+retryconnectiondelay = 0
+certpath = None
+username = None
 
 if os.environ.get('RD_CONFIG_OVERRIDE') == 'true':
     override = True
@@ -313,10 +330,29 @@ def winrm_upload(self,
     else:
         krbdelegation = False
 
-endpoint = transport+'://'+args.hostname+':'+port
+if "RD_CONFIG_READTIMEOUT" in os.environ:
+    readtimeout = os.getenv("RD_CONFIG_READTIMEOUT")
+
+if "RD_CONFIG_OPERATIONTIMEOUT" in os.environ:
+    operationtimeout = os.getenv("RD_CONFIG_OPERATIONTIMEOUT")
+
+if "RD_CONFIG_ENABLEDHTTPDEBUG" in os.environ:
+    if os.getenv("RD_CONFIG_ENABLEDHTTPDEBUG") == "true":
+        enabledHttpDebug = True
+    else:
+        enabledHttpDebug = False
+
+if "RD_CONFIG_RETRYCONNECTION" in os.environ:
+    retryconnection = int(os.getenv("RD_CONFIG_RETRYCONNECTION"))
 
-arguments = {}
-arguments["transport"] = authentication
+if "RD_CONFIG_RETRYCONNECTIONDELAY" in os.environ:
+    retryconnectiondelay = int(os.getenv("RD_CONFIG_RETRYCONNECTIONDELAY"))
+
+if enabledHttpDebug:
+    httpclient_logging_patch(logging.DEBUG)
+
+endpoint = transport+'://'+args.hostname+':'+port
+arguments = {"transport": authentication}
 
 if(nossl == True):
     arguments["server_cert_validation"] = "ignore"
@@ -327,6 +363,11 @@ def winrm_upload(self,
 
 arguments["credssp_disable_tlsv1_2"] = diabletls12
 
+if(readtimeout):
+    arguments["read_timeout_sec"] = readtimeout
+
+if(operationtimeout):
+    arguments["operation_timeout_sec"] = operationtimeout
 
 if not URLLIB_INSTALLED:
     log.error("request and urllib3 not installed, try: pip install requests &&  pip install urllib3")
@@ -361,10 +402,12 @@ def winrm_upload(self,
                         auth=(username, password),
                         **arguments)
 
+winrm.Session.run_cmd = winrm_session.run_cmd
+winrm.Session.run_ps = winrm_session.run_ps
+winrm.Session._clean_error_msg = winrm_session._clean_error_msg
+winrm.Session._strip_namespace = winrm_session._strip_namespace
 
-winrm.Session._clean_error_msg = _clean_error_msg
-
-copy = CopyFiles(session)
+copy = CopyFiles(session, retryconnection, retryconnectiondelay)
 
 destination = args.destination
 filename = ntpath.basename(args.destination)