From 22e5630b8570afe26bcbf8104b7b7a6f600fc382 Mon Sep 17 00:00:00 2001 From: mhorky Date: Mon, 11 Dec 2023 14:25:10 +0100 Subject: [PATCH] Improve debug logging to make it faster to understand This change clearly labels each section that's printed to make it easier to identify the interesting parts. This also adds SUBMAN_DEBUG_PRINT_TRACEBACKS flag to print the traceback directly to stdout. GREEN: title RED: method + url (request), status code (response) BLUE: headers YELLOW: body WHITE: call stack --- src/cloud_what/_base_provider.py | 52 +++++---- src/rhsm/connection.py | 187 +++++++++++++++++-------------- src/rhsm/utils.py | 15 ++- 3 files changed, 148 insertions(+), 106 deletions(-) diff --git a/src/cloud_what/_base_provider.py b/src/cloud_what/_base_provider.py index e869130c9a..6b0379d49a 100644 --- a/src/cloud_what/_base_provider.py +++ b/src/cloud_what/_base_provider.py @@ -17,6 +17,7 @@ should not be imported outside this package. """ +import enum import requests import logging import json @@ -28,6 +29,19 @@ log = logging.getLogger(__name__) +class COLOR(enum.Enum): + RED = "\033[91m" + YELLOW = "\033[93m" + GREEN = "\033[92m" + MAGENTA = "\033[95m" + BLUE = "\033[94m" + RESET = "\033[0m" + + +def colorize(text: str, color: COLOR) -> str: + return color.value + text + COLOR.RESET.value + + class BaseCloudProvider: """ Base class of cloud provider. This class is used for cloud detecting @@ -345,19 +359,17 @@ def _debug_print_http_request(request: requests.PreparedRequest) -> None: :param request: prepared HTTP request :return: None """ - yellow_col = "\033[93m" - blue_col = "\033[94m" - red_col = "\033[91m" - end_col = "\033[0m" - msg = blue_col + "Making request: " + end_col - msg += red_col + request.method + " " + request.url + end_col + print(colorize("Request:", COLOR.GREEN)) + print(colorize(f"{request.method} {request.url}", COLOR.RED)) + if os.environ.get("SUBMAN_DEBUG_PRINT_REQUEST_HEADER", ""): - headers = ", ".join("{}: {}".format(k, v) for k, v in request.headers.items()) - msg += blue_col + " {{{headers}}}".format(headers=headers) + end_col + print(colorize("Request headers:", COLOR.GREEN)) + print(colorize(f"{request.headers}", COLOR.BLUE)) + if os.environ.get("SUBMAN_DEBUG_PRINT_REQUEST_BODY", "") and request.body is not None: - msg += yellow_col + f" {request.body}" + end_col - print() - print(msg) + print(colorize("Request body:", COLOR.GREEN)) + print(colorize(f"{request.body}", COLOR.YELLOW)) + print() @staticmethod @@ -369,15 +381,15 @@ def _cb_debug_print_http_response(response: requests.Response, *args, **kwargs) :param **kwargs: Not used :return: Instance of response """ - print( - "\n{code} {{{headers}}}\n{body}\n".format( - code=response.status_code, - headers=", ".join( - "{key}: {value}".format(key=k, value=v) for k, v in response.headers.items() - ), - body=response.text, - ) - ) + print(colorize("Response:", COLOR.GREEN)) + print(colorize(f"{response.status_code}", COLOR.RED)) + + print(colorize("Response headers:", COLOR.GREEN)) + print(colorize(f"{response.headers}", COLOR.BLUE)) + + print(colorize("Response content:", COLOR.GREEN)) + print(colorize(f"{response.text}", COLOR.YELLOW)) + return response def _get_data_from_server(self, data_type: str, url: str, headers: dict = None) -> Union[str, None]: diff --git a/src/rhsm/connection.py b/src/rhsm/connection.py index 59d147a68e..82cf04ea2a 100644 --- a/src/rhsm/connection.py +++ b/src/rhsm/connection.py @@ -847,94 +847,105 @@ def _print_debug_info_about_request( :return: None """ - if os.environ.get("SUBMAN_DEBUG_PRINT_REQUEST", ""): - magenta_col = "\033[95m" - blue_col = "\033[94m" - yellow_col = "\033[93m" - green_col = "\033[92m" - red_col = "\033[91m" - end_col = "\033[0m" - - msg = "" - - if self.auth_type == ConnectionType.KEYCLOAK_AUTH: - auth = "keycloak auth" - elif self.auth_type == ConnectionType.BASIC_AUTH: - auth = "basic auth" - elif self.auth_type == ConnectionType.CONSUMER_CERT_AUTH: - auth = "consumer auth" - elif self.auth_type == ConnectionType.NO_AUTH: - auth = "no auth" - else: - auth = "undefined auth" + if os.environ.get("SUBMAN_DEBUG_PRINT_REQUEST", "") == "": + return - # Print information about TCP/IP layer - if ( - os.environ.get("SUBMAN_DEBUG_TCP_IP", "") - and self.__conn is not None - and self.__conn.sock is not None - ): - msg += blue_col + f"{self.__conn.sock}\n" + end_col - - # When proxy server is used, then print some additional information about proxy connection - if self.proxy_hostname and self.proxy_port: - # Note: using only https:// is not a mistake. We use only https for proxy connection. - msg += blue_col + "Using proxy: " + magenta_col + "https://" - # Print username and eventually password - if self.proxy_user: - if self.proxy_user and self.proxy_password: - msg += f"{self.proxy_user}:{self.proxy_password}@" - elif self.proxy_user and not self.proxy_password: - msg += f"{self.proxy_user}@" - # Print hostname and port - msg += f"{normalized_host(self.proxy_hostname)}:{safe_int(self.proxy_port)}" - msg += end_col - # Print HTTP headers used for proxy connection - tunel_headers = None - if self.__conn is not None and hasattr(self.__conn, "_tunnel_headers"): - tunel_headers = getattr(self.__conn, "_tunnel_headers") - if tunel_headers is not None: - msg += blue_col + f" {tunel_headers}" + end_col - msg += "\n" - - if self.insecure is True: - msg += blue_col + f"Making insecure ({auth}) request:" + end_col - else: - msg += blue_col + f"Making ({auth}) request:" + end_col - msg += ( - red_col - + " https://" - + f"{normalized_host(self.host)}:{safe_int(self.ssl_port)}{handler} {request_type}" - + end_col + print() + + # Print information about TCP/IP layer + if ( + os.environ.get("SUBMAN_DEBUG_TCP_IP", "") + and self.__conn is not None + and self.__conn.sock is not None + ): + print(utils.colorize("TCP socket:", utils.COLOR.GREEN)) + print(utils.colorize(f"{self.__conn.sock}", utils.COLOR.BLUE)) + + # When proxy server is used, then print some additional information about proxy connection + if self.proxy_hostname and self.proxy_port: + print(utils.colorize("Proxy:", utils.COLOR.GREEN)) + # Note: using only https:// is not a mistake. We use only https for proxy connection. + proxy_msg: str = "https://" + # Print username and eventually password + if self.proxy_user: + if self.proxy_user and self.proxy_password: + proxy_msg += f"{self.proxy_user}:{self.proxy_password}@" + elif self.proxy_user and not self.proxy_password: + proxy_msg += f"{self.proxy_user}@" + # Print hostname and port + proxy_msg += f"{normalized_host(self.proxy_hostname)}:{safe_int(self.proxy_port)}" + print(utils.colorize(proxy_msg, utils.COLOR.MAGENTA)) + + # Print HTTP headers used for proxy connection + tunnel_msg = "" + tunnel_headers = None + if self.__conn is not None and hasattr(self.__conn, "_tunnel_headers"): + tunnel_headers = getattr(self.__conn, "_tunnel_headers") + if tunnel_headers is not None: + tunnel_msg = f"{tunnel_headers}" + if tunnel_msg: + print(utils.colorize(tunnel_msg, utils.COLOR.BLUE)) + + auth = "" + if self.insecure: + auth = "insecure " + if self.auth_type == ConnectionType.KEYCLOAK_AUTH: + auth += "keycloak auth" + elif self.auth_type == ConnectionType.BASIC_AUTH: + auth += "basic auth" + elif self.auth_type == ConnectionType.CONSUMER_CERT_AUTH: + auth += "consumer auth" + elif self.auth_type == ConnectionType.NO_AUTH: + auth += "no auth" + else: + auth += "undefined auth" + + print(utils.colorize("Request:", utils.COLOR.GREEN)) + print( + utils.colorize( + f"{request_type} " + + "https://" + + f"{normalized_host(self.host)}:{safe_int(self.ssl_port)}{handler}", + utils.COLOR.RED, ) + + " using " + + utils.colorize(f"{auth}", utils.COLOR.BLUE) + ) - if os.environ.get("SUBMAN_DEBUG_PRINT_REQUEST_HEADER", ""): - msg += blue_col + " %s" % final_headers + end_col - if os.environ.get("SUBMAN_DEBUG_PRINT_REQUEST_BODY", "") and body is not None: - msg += yellow_col + " %s" % body + end_col - print() - print(msg) - print() - if os.environ.get("SUBMAN_DEBUG_SAVE_TRACEBACKS", ""): - debug_dir = Path("/tmp/rhsm/") - debug_dir.mkdir(exist_ok=True) + if os.environ.get("SUBMAN_DEBUG_PRINT_REQUEST_HEADER", ""): + print(utils.colorize("Request headers:", utils.COLOR.GREEN)) + print(utils.colorize(f"{final_headers}", utils.COLOR.BLUE)) + + if os.environ.get("SUBMAN_DEBUG_PRINT_REQUEST_BODY", "") and body is not None: + print(utils.colorize("Request body:", utils.COLOR.GREEN)) + print(utils.colorize(f"{body}", utils.COLOR.YELLOW)) + + if os.environ.get("SUBMAN_DEBUG_PRINT_TRACEBACKS", ""): + print(utils.colorize("Current call stack:", utils.COLOR.GREEN)) + traceback.print_stack(file=sys.stdout) - timestamp: str = datetime.datetime.now().strftime("%Y-%m-%d_%H-%M-%S") + if os.environ.get("SUBMAN_DEBUG_SAVE_TRACEBACKS", ""): + debug_dir = Path("/tmp/rhsm/") + debug_dir.mkdir(exist_ok=True) - # make sure we don't overwrite previous logs - i = 0 - while True: - filename = Path(f"{timestamp}_{i}.log") - debug_log = debug_dir / filename - if not debug_log.exists(): - break - i += 1 + timestamp: str = datetime.datetime.now().strftime("%Y-%m-%d_%H-%M-%S") - with debug_log.open("w", encoding="utf-8") as handle: - traceback.print_stack(file=handle) + # make sure we don't overwrite previous logs + i = 0 + while True: + filename = Path(f"{timestamp}_{i}.log") + debug_log = debug_dir / filename + if not debug_log.exists(): + break + i += 1 - print(green_col + f"Traceback saved to {str(debug_log)}." + end_col) - print() + with debug_log.open("w", encoding="utf-8") as handle: + traceback.print_stack(file=handle) + + print(utils.colorize("Call stack file:", utils.COLOR.GREEN)) + print(f"{str(debug_log)}") + + print() @staticmethod def _print_debug_info_about_response(result: dict) -> None: @@ -946,10 +957,16 @@ def _print_debug_info_about_response(result: dict) -> None: """ if os.environ.get("SUBMAN_DEBUG_PRINT_RESPONSE", ""): - gray_col = "\033[90m" - end_col = "\033[0m" - print(gray_col + "%s %s" % (result["status"], result["headers"])) - print(result["content"] + end_col) + print(utils.colorize("Response:", utils.COLOR.GREEN)) + print(utils.colorize(f"{result['status']}", utils.COLOR.RED)) + + print(utils.colorize("Response headers:", utils.COLOR.GREEN)) + print(utils.colorize(f"{result['headers']}", utils.COLOR.BLUE)) + + if result["content"]: + print(utils.colorize("Response body:", utils.COLOR.GREEN)) + print(utils.colorize(f"{result['content']}", utils.COLOR.YELLOW)) + print() def _set_accept_language_in_header(self) -> None: diff --git a/src/rhsm/utils.py b/src/rhsm/utils.py index 2302c75c61..7e901d9549 100644 --- a/src/rhsm/utils.py +++ b/src/rhsm/utils.py @@ -11,7 +11,7 @@ # granted to use or replicate Red Hat trademarks that are incorporated # in this software or its documentation. # - +import enum import functools import os import re @@ -35,6 +35,19 @@ """ +class COLOR(enum.Enum): + RED = "\033[91m" + YELLOW = "\033[93m" + GREEN = "\033[92m" + MAGENTA = "\033[95m" + BLUE = "\033[94m" + RESET = "\033[0m" + + +def colorize(text: str, color: COLOR) -> str: + return color.value + text + COLOR.RESET.value + + def remove_scheme(uri: str) -> str: """Remove the scheme component from a URI.""" return re.sub("^[A-Za-z][A-Za-z0-9+-.]*://", "", uri)