refactor(logging): add additional debug stmts

Author: Brooke-white

redshift_connector/__init__.py

@@ -38,7 +38,11 @@
     PGVarchar,
 )
 from redshift_connector.redshift_property import RedshiftProperty
-from redshift_connector.utils import DriverInfo
+from redshift_connector.utils import (
+    DriverInfo,
+    make_divider_block,
+    mask_secure_info_in_props,
+)
 from redshift_connector.utils.type_utils import (
     BIGINT,
     BIGINTEGER,
@@ -88,6 +92,7 @@
 from .version import __version__
 
 logging.getLogger(__name__).addHandler(logging.NullHandler())
+_logger: logging.Logger = logging.getLogger(__name__)
 
 # Copyright (c) 2007-2009, Mathieu Fenniak
 # Copyright (c) The Contributors
@@ -296,6 +301,12 @@ def connect(
         role_arn=role_arn,
     )
 
+    _logger.debug(make_divider_block())
+    _logger.debug("Initializing Connection object")
+    _logger.debug(make_divider_block())
+    _logger.debug(mask_secure_info_in_props(info).__str__())
+    _logger.debug(make_divider_block())
+
     return Connection(
         user=info.user_name,
         host=info.host,

redshift_connector/auth/aws_credentials_provider.py

@@ -57,7 +57,7 @@ def get_credentials(
             try:
                 self.refresh()
             except Exception as e:
-                _logger.error("refresh failed: {}".format(str(e)))
+                _logger.error("Refreshing IdP credentials failed: {}".format(str(e)))
                 raise InterfaceError(e)
 
         credentials: typing.Union[AWSDirectCredentialsHolder, AWSProfileCredentialsHolder] = self.cache[key]

redshift_connector/core.py

@@ -71,6 +71,7 @@
     ii_pack,
     iii_pack,
     int_array_recv,
+    make_divider_block,
     numeric_in,
     numeric_in_binary,
 )
@@ -493,6 +494,11 @@ def __init__(
         if credentials_provider:
             init_params["plugin_name"] = credentials_provider
 
+        _logger.debug(make_divider_block())
+        _logger.debug("Establishing a connection")
+        _logger.debug(init_params)
+        _logger.debug(make_divider_block())
+
         for k, v in tuple(init_params.items()):
             if isinstance(v, str):
                 init_params[k] = v.encode("utf8")
@@ -559,6 +565,9 @@ def __init__(
                     self._usock.sendall(ii_pack(8, 80877103))
                     resp: bytes = self._usock.recv(1)
                     if resp != b"S":
+                        _logger.debug(
+                            "Server response code when attempting to establish ssl connection: {!r}".format(resp)
+                        )
                         raise InterfaceError("Server refuses SSL")
 
                     if sslmode == "verify-ca":
@@ -642,6 +651,7 @@ def __init__(
 
         code = None
         self.error: typing.Optional[Exception] = None
+        _logger.debug("Sending start-up message")
         # When driver send the start-up message to database, DB will respond multi messages to driver
         # whose format is same with the message that driver send to DB.
         while code not in (READY_FOR_QUERY, ERROR_RESPONSE):
@@ -661,6 +671,7 @@ def __init__(
             self._client_protocol_version > ClientProtocolVersion.BASE_SERVER
             and not (b"server_protocol_version", str(self._client_protocol_version).encode()) in self.parameter_statuses
         ):
+            _logger.debug("Server_protocol_version not received from server")
             self._client_protocol_version = ClientProtocolVersion.BASE_SERVER
             self._enable_protocol_based_conversion_funcs()
 
@@ -1027,6 +1038,7 @@ def handle_ROW_DESCRIPTION(self: "Connection", data, cursor: Cursor) -> None:
             raise InterfaceError("Prepared Statement is missing row description")
 
         count: int = h_unpack(data)[0]
+        _logger.debug("field count={}".format(count))
         idx = 2
         for i in range(count):
             column_label = data[idx : data.find(NULL_BYTE, idx)]
@@ -1056,6 +1068,8 @@ def handle_ROW_DESCRIPTION(self: "Connection", data, cursor: Cursor) -> None:
             cursor.ps["row_desc"].append(field)
             field["pg8000_fc"], field["func"] = self.pg_types[field["type_oid"]]
 
+        _logger.debug(cursor.ps["row_desc"])
+
     def execute(self: "Connection", cursor: Cursor, operation: str, vals) -> None:
         """
         Executes a database operation. Parameters may be provided as a sequence, or as a mapping, depending upon the value of `redshift_connector.paramstyle`.

redshift_connector/cursor.py

@@ -1,4 +1,5 @@
 import functools
+import logging
 import re
 import typing
 from collections import deque
@@ -23,6 +24,8 @@
     except:
         pass
 
+_logger: logging.Logger = logging.getLogger(__name__)
+
 
 class Cursor:
     """A cursor object is returned by the :meth:`~Connection.cursor` method of
@@ -98,6 +101,8 @@ def __init__(self: "Cursor", connection: "Connection", paramstyle=None) -> None:
         else:
             self.paramstyle = paramstyle
 
+        _logger.debug("Cursor.paramstyle={}".format(self.paramstyle))
+
     def __enter__(self: "Cursor") -> "Cursor":
         return self
 

redshift_connector/iam_helper.py

@@ -16,6 +16,7 @@
 from redshift_connector.error import InterfaceError
 from redshift_connector.plugin import SamlCredentialsProvider
 from redshift_connector.redshift_property import RedshiftProperty
+from redshift_connector.utils import make_divider_block
 
 _logger: logging.Logger = logging.getLogger(__name__)
 
@@ -153,6 +154,7 @@ def set_iam_properties(
                     )
                 else:
                     info.credentials_provider = credentials_provider
+                    _logger.debug("IDP Credential Provider {}".format(info.credentials_provider))
             elif profile is not None:
                 if any((access_key_id, secret_access_key, session_token)):
                     raise InterfaceError(
@@ -161,6 +163,7 @@ def set_iam_properties(
                     )
                 else:
                     info.profile = profile
+                    _logger.debug("AWS Profile {}".format(info.profile))
             elif access_key_id is not None:
                 info.access_key_id = access_key_id
 
@@ -170,6 +173,7 @@ def set_iam_properties(
                 # SQL Workbench.
                 elif password != "":
                     info.secret_access_key = password
+                    _logger.debug("Value of password will be used for secret_access_key")
                 else:
                     raise InterfaceError(
                         "Invalid connection property setting. "
@@ -178,6 +182,11 @@ def set_iam_properties(
 
                 if session_token is not None:
                     info.session_token = session_token
+                _logger.debug(
+                    "AWS Credentials access_key_id: {} secret_access_key: {} session_token: {}".format(
+                        bool(info.access_key_id), bool(info.secret_access_key), bool(info.session_token)
+                    )
+                )
             elif secret_access_key is not None:
                 raise InterfaceError(
                     "Invalid connection property setting. access_key_id is required when secret_access_key is "
@@ -290,6 +299,7 @@ def set_iam_credentials(info: RedshiftProperty) -> None:
                     )
                     raise InterfaceError("Invalid credentials provider " + info.credentials_provider)
         else:  # indicates AWS Credentials will be used
+            _logger.debug("AWS Credentials provider will be used for authentication")
             provider = AWSCredentialsProvider()
             provider.add_parameter(info)
 

redshift_connector/plugin/adfs_credentials_provider.py

@@ -35,14 +35,16 @@ def form_based_authentication(self: "AdfsCredentialsProvider") -> str:
         url: str = "https://{host}:{port}/adfs/ls/IdpInitiatedSignOn.aspx?loginToRp=urn:amazon:webservices".format(
             host=self.idp_host, port=str(self.idpPort)
         )
+        _logger.debug("Uri: {}".format(url))
+
         try:
             response: "requests.Response" = requests.get(url, verify=self.do_verify_ssl_cert())
             response.raise_for_status()
         except requests.exceptions.HTTPError as e:
             if "response" in vars():
-                _logger.debug("form_based_authentication https response: {}".format(response.text))  # type: ignore
+                _logger.debug("Form_based_authentication https response: {}".format(response.content))  # type: ignore
             else:
-                _logger.debug("form_based_authentication could not receive https response due to an error")
+                _logger.debug("Form_based_authentication could not receive https response due to an error")
             _logger.error("Request for SAML assertion when refreshing credentials was unsuccessful. {}".format(str(e)))
             raise InterfaceError(e)
         except requests.exceptions.Timeout as e:
@@ -58,6 +60,8 @@ def form_based_authentication(self: "AdfsCredentialsProvider") -> str:
             _logger.error("A unknown error occurred when requesting SAML assertion to refresh credentials")
             raise InterfaceError(e)
 
+        _logger.debug(response.text)
+
         try:
             soup = bs4.BeautifulSoup(response.text, features="lxml")
         except Exception as e:
@@ -69,6 +73,9 @@ def form_based_authentication(self: "AdfsCredentialsProvider") -> str:
         for inputtag in soup.find_all(re.compile("(INPUT|input)")):
             name: str = inputtag.get("name", "")
             value: str = inputtag.get("value", "")
+
+            _logger.debug("Name={}".format(name))
+
             if "username" in name.lower():
                 payload[name] = self.user_name
             elif "authmethod" in name.lower():
@@ -82,6 +89,8 @@ def form_based_authentication(self: "AdfsCredentialsProvider") -> str:
         if action and action.startswith("/"):
             url = "https://{host}:{port}{action}".format(host=self.idp_host, port=str(self.idpPort), action=action)
 
+        _logger.debug("Action uri: {}".format(url))
+
         try:
             response = requests.post(url, data=payload, verify=self.do_verify_ssl_cert())
             response.raise_for_status()

redshift_connector/plugin/azure_credentials_provider.py

@@ -61,6 +61,8 @@ def azure_oauth_based_authentication(self: "AzureCredentialsProvider") -> str:
 
         # endpoint to connect with Microsoft Azure to get SAML Assertion token
         url: str = "https://login.microsoftonline.com/{tenant}/oauth2/token".format(tenant=self.idp_tenant)
+        _logger.debug("Uri: {}".format(url))
+
         # headers to pass with POST request
         headers: typing.Dict[str, str] = azure_headers
         # required parameters to pass in POST body
@@ -82,10 +84,10 @@ def azure_oauth_based_authentication(self: "AzureCredentialsProvider") -> str:
         except requests.exceptions.HTTPError as e:
             if "response" in vars():
                 _logger.debug(
-                    "azure_oauth_based_authentication https response: {}".format(response.text)  # type: ignore
+                    "azure_oauth_based_authentication https response: {}".format(response.content)  # type: ignore
                 )
             else:
-                _logger.debug("azure_oauth_based_authentication could not receive https response due to an error")
+                _logger.debug("Azure_oauth_based_authentication could not receive https response due to an error")
             _logger.error("Request for authentication from Azure was unsuccessful. {}".format(str(e)))
             raise InterfaceError(e)
         except requests.exceptions.Timeout as e:
@@ -100,6 +102,8 @@ def azure_oauth_based_authentication(self: "AzureCredentialsProvider") -> str:
             _logger.error("A unknown error occurred when requesting authentication from Azure.")
             raise InterfaceError(e)
 
+        _logger.debug(response.text)
+
         # parse the JSON response to grab access_token field which contains Base64 encoded SAML
         # Assertion and decode it
         saml_assertion: str = ""

redshift_connector/plugin/browser_azure_credentials_provider.py

@@ -52,6 +52,11 @@ def add_parameter(self: "BrowserAzureCredentialsProvider", info: RedshiftPropert
 
         self.idp_response_timeout = info.idp_response_timeout
 
+        _logger.debug("Idp_tenant={}".format(self.idp_tenant))
+        _logger.debug("Client_id={}".format(self.client_id))
+        _logger.debug("Idp_response_timeout={}".format(self.idp_response_timeout))
+        _logger.debug("Listen_port={}".format(self.listen_port))
+
     # Required method to grab the SAML Response. Used in base class to refresh temporary credentials.
     def get_saml_assertion(self: "BrowserAzureCredentialsProvider") -> str:
 
@@ -65,6 +70,7 @@ def get_saml_assertion(self: "BrowserAzureCredentialsProvider") -> str:
 
         listen_socket: socket.socket = self.get_listen_socket()
         self.redirectUri = "http://localhost:{port}/redshift/".format(port=self.listen_port)
+        _logger.debug("Listening for connection on port {}".format(self.listen_port))
 
         try:
             token: str = self.fetch_authorization_token(listen_socket)
@@ -73,7 +79,7 @@ def get_saml_assertion(self: "BrowserAzureCredentialsProvider") -> str:
             raise e
         finally:
             listen_socket.close()
-
+        _logger.debug("Got SAML assertion")
         return self.wrap_and_encode_assertion(saml_assertion)
 
     #  First authentication phase:
@@ -93,10 +99,10 @@ def fetch_authorization_token(self: "BrowserAzureCredentialsProvider", listen_so
 
             return str(return_value)
         except socket.error as e:
-            _logger.error("socket error: %s", e)
+            _logger.error("Socket error: %s", e)
             raise e
         except Exception as e:
-            _logger.error("other Exception: %s", e)
+            _logger.error("Other Exception: %s", e)
             raise e
 
     # Initiates the request to the IDP and gets the response body
@@ -119,14 +125,17 @@ def fetch_saml_response(self: "BrowserAzureCredentialsProvider", token):
             "client_secret": self.client_secret,
             "redirect_uri": self.redirectUri,
         }
+
+        _logger.debug("Uri: {}".format(url))
+
         try:
             response = requests.post(url, data=payload, headers=headers, verify=self.do_verify_ssl_cert())
             response.raise_for_status()
         except requests.exceptions.HTTPError as e:
             if "response" in vars():
-                _logger.debug("fetch_saml_response https response: {}".format(response.text))  # type: ignore
+                _logger.debug("Fetch_saml_response https response: {}".format(response.content))  # type: ignore
             else:
-                _logger.debug("fetch_saml_response could not receive https response due to an error")
+                _logger.debug("Fetch_saml_response could not receive https response due to an error")
             _logger.error("Request for authentication from Microsoft was unsuccessful. {}".format(str(e)))
             raise InterfaceError(e)
         except requests.exceptions.Timeout as e:
@@ -141,6 +150,8 @@ def fetch_saml_response(self: "BrowserAzureCredentialsProvider", token):
             _logger.error("A unknown error occurred when requesting authentication from Azure")
             raise InterfaceError(e)
 
+        _logger.debug(response.text)
+
         try:
             saml_assertion: str = response.json()["access_token"]
         except TypeError as e:

redshift_connector/plugin/browser_saml_credentials_provider.py

@@ -34,6 +34,10 @@ def add_parameter(self: "BrowserSamlCredentialsProvider", info: RedshiftProperty
         self.idp_response_timeout = info.idp_response_timeout
         self.listen_port = info.listen_port
 
+        _logger.debug("Listen_port={}".format(self.listen_port))
+        _logger.debug("Login_url={}".format(self.login_url))
+        _logger.debug("Idp_response_timeout={}".format(self.idp_response_timeout))
+
     # Required method to grab the SAML Response. Used in base class to refresh temporary credentials.
     def get_saml_assertion(self: "BrowserSamlCredentialsProvider") -> str:
 
@@ -54,17 +58,18 @@ def get_saml_assertion(self: "BrowserSamlCredentialsProvider") -> str:
     def authenticate(self: "BrowserSamlCredentialsProvider") -> str:
         try:
             with concurrent.futures.ThreadPoolExecutor() as executor:
+                _logger.debug("Listening for connection on port {}".format(self.listen_port))
                 future = executor.submit(self.run_server, self.listen_port, self.idp_response_timeout)
                 self.open_browser()
                 return_value: str = future.result()
 
             samlresponse = urllib.parse.unquote(return_value)
             return str(samlresponse)
         except socket.error as e:
-            _logger.error("socket error: %s", e)
+            _logger.error("Socket error: %s", e)
             raise e
         except Exception as e:
-            _logger.error("other Exception: %s", e)
+            _logger.error("Other Exception: %s", e)
             raise e
 
     def run_server(self: "BrowserSamlCredentialsProvider", listen_port: int, idp_response_timeout: int) -> str:
@@ -85,6 +90,7 @@ def run_server(self: "BrowserSamlCredentialsProvider", listen_port: int, idp_res
                     result: typing.Optional[typing.Match] = re.search(
                         pattern="SAMLResponse[:=]+[\\n\\r]*", string=decoded_part, flags=re.MULTILINE
                     )
+                    _logger.debug("Data received contained SAMLResponse: {}".format(bool(result is not None)))
 
                     if result is not None:
                         saml_resp_block: str = decoded_part[result.regs[0][1] :]
@@ -98,6 +104,8 @@ def open_browser(self: "BrowserSamlCredentialsProvider") -> None:
         import webbrowser
 
         url: typing.Optional[str] = self.login_url
+        _logger.debug("SSO URI: {}".format(url))
+
         if url is None:
             raise InterfaceError("the login_url could not be empty")
         webbrowser.open(url)

redshift_connector/plugin/jwt_credentials_provider.py

@@ -63,7 +63,7 @@ def get_credentials(self: "SamlCredentialsProvider") -> CredentialsHolder:
             try:
                 self.refresh()
             except Exception as e:
-                _logger.error("refresh failed: {}".format(str(e)))
+                _logger.error("Refreshing IdP credentials failed: {}".format(str(e)))
                 raise InterfaceError(e)
 
         if key not in self.cache or self.cache[key] is None:
@@ -118,7 +118,7 @@ def refresh(self: "JwtCredentialsProvider") -> None:
             _logger.error("RegionDisabledException: %s", e)
             raise e
         except Exception as e:
-            _logger.error("other Exception: %s", e)
+            _logger.error("Other Exception: %s", e)
             raise e
 
     def check_required_parameters(self: "JwtCredentialsProvider") -> None: