Configure Python logging level when debug flag is specified; add debug logs to bake command (#749)

Co-authored-by: Ye Chen <[email protected]>

Author: lgarber-akamai

Makefile

@@ -12,6 +12,8 @@ VERSION_FILE := ./linodecli/version.py
 VERSION_MODULE_DOCSTRING ?= \"\"\"\nThe version of the Linode CLI.\n\"\"\"\n\n
 LINODE_CLI_VERSION ?= "0.0.0.dev"
 
+BAKE_FLAGS := --debug
+
 .PHONY: install
 install: check-prerequisites requirements build
 	pip3 install --force dist/*.whl
@@ -21,7 +23,7 @@ bake: clean
 ifeq ($(SKIP_BAKE), 1)
 	@echo Skipping bake stage
 else
-	python3 -m linodecli bake ${SPEC} --skip-config
+	python3 -m linodecli bake ${SPEC} --skip-config $(BAKE_FLAGS)
 	cp data-3 linodecli/
 endif
 

linodecli/__init__.py

@@ -4,6 +4,7 @@
 """
 
 import argparse
+import logging
 import os
 import sys
 from importlib.metadata import version
@@ -38,6 +39,11 @@
 
 TEST_MODE = os.getenv("LINODE_CLI_TEST_MODE") == "1"
 
+# Configure the `logging` package log level depending on the --debug flag.
+logging.basicConfig(
+    level=logging.DEBUG if "--debug" in argv else logging.WARNING,
+)
+
 # if any of these arguments are given, we don't need to prompt for configuration
 skip_config = (
     any(

linodecli/api_request.py

@@ -7,6 +7,7 @@
 import os
 import sys
 import time
+from logging import getLogger
 from typing import TYPE_CHECKING, Any, Dict, Iterable, List, Optional
 
 import requests
@@ -26,6 +27,8 @@
 if TYPE_CHECKING:
     from linodecli.cli import CLI
 
+logger = getLogger(__name__)
+
 
 def get_all_pages(
     ctx: "CLI", operation: OpenAPIOperation, args: List[str]
@@ -103,13 +106,18 @@ def do_request(
 
     # Print response debug info is requested
     if ctx.debug_request:
-        _print_request_debug_info(method, url, headers, body)
+        # Multiline log entries aren't ideal, we should consider
+        # using single-line structured logging in the future.
+        logger.debug(
+            "\n%s",
+            "\n".join(_format_request_for_log(method, url, headers, body)),
+        )
 
     result = method(url, headers=headers, data=body, verify=API_CA_PATH)
 
     # Print response debug info is requested
     if ctx.debug_request:
-        _print_response_debug_info(result)
+        logger.debug("\n%s", "\n".join(_format_response_for_log(result)))
 
     # Retry the request if necessary
     while _check_retry(result) and not ctx.no_retry and ctx.retry_count < 3:
@@ -362,48 +370,61 @@ def _build_request_body(
     return json.dumps(_traverse_request_body(expanded_json))
 
 
-def _print_request_debug_info(
-    method: Any, url: str, headers: Dict[str, Any], body: Optional[str]
-) -> None:
+def _format_request_for_log(
+    method: Any,
+    url: str,
+    headers: Dict[str, str],
+    body: str,
+) -> List[str]:
     """
-    Prints debug info for an HTTP request.
+    Builds a debug output for the given request.
 
-    :param method: An object with a `__name__` attribute representing
-        the HTTP method (e.g., "get", "post").
-    :param url: The full request URL.
-    :param headers: A dictionary of request headers.
-    :param body: The request body as a string, or None if no body exists.
+    :param method: The HTTP method of the request.
+    :param url: The URL of the request.
+    :param headers: The headers of the request.
+    :param body: The body of the request.
+
+    :returns: The lines of the generated debug output.
     """
-    print(f"> {method.__name__.upper()} {url}", file=sys.stderr)
+    result = [f"> {method.__name__.upper()} {url}"]
+
     for k, v in headers.items():
         # If this is the Authorization header, sanitize the token
         if k.lower() == "authorization":
             v = "Bearer " + "*" * 64
-        print(f"> {k}: {v}", file=sys.stderr)
-    print("> Body:", file=sys.stderr)
-    print(">  ", body or "", file=sys.stderr)
-    print("> ", file=sys.stderr)
+
+        result.append(f"> {k}: {v}")
+
+    result.extend(["> Body:", f">   {body or ''}", "> "])
+
+    return result
 
 
-def _print_response_debug_info(response: Any) -> None:
+def _format_response_for_log(
+    response: requests.Response,
+):
     """
-    Prints debug info for a response from requests.
+    Builds a debug output for the given response.
 
-    :param response: The response object returned by a `requests` call.
+    :param response: The HTTP response to format.
+
+    :returns: The lines of the generated debug output.
     """
+
     # these come back as ints, convert to HTTP version
     http_version = response.raw.version / 10
     body = response.content.decode("utf-8", errors="replace")
 
-    print(
-        f"< HTTP/{http_version:.1f} {response.status_code} {response.reason}",
-        file=sys.stderr,
-    )
+    result = [
+        f"< HTTP/{http_version:.1f} {response.status_code} {response.reason}"
+    ]
+
     for k, v in response.headers.items():
-        print(f"< {k}: {v}", file=sys.stderr)
-    print("< Body:", file=sys.stderr)
-    print("<  ", body or "", file=sys.stderr)
-    print("< ", file=sys.stderr)
+        result.append(f"< {k}: {v}")
+
+    result.extend(["< Body:", f"<   {body or ''}", "< "])
+
+    return result
 
 
 def _attempt_warn_old_version(ctx: "CLI", result: Any) -> None:

linodecli/baked/operation.py

@@ -5,6 +5,7 @@
 import argparse
 import glob
 import json
+import logging
 import platform
 import re
 import sys
@@ -400,9 +401,10 @@ def __init__(
         self.docs_url = self._resolve_operation_docs_url(operation)
 
         if self.docs_url is None:
-            print(
-                f"INFO: Could not resolve docs URL for {operation}",
-                file=sys.stderr,
+            logging.warning(
+                "%s %s Could not resolve docs URL for operation",
+                self.method.upper(),
+                self.url_path,
             )
 
         code_samples_ext = operation.extensions.get("code-samples")
@@ -426,6 +428,13 @@ def arg_routes(self) -> Dict[str, List[OpenAPIRequestArg]]:
         """
         return self.request.attr_routes if self.request else []
 
+    @property
+    def attrs(self):
+        """
+        Return a list of attributes from the request schema
+        """
+        return self.response_model.attrs if self.response_model else []
+
     @staticmethod
     def _flatten_url_path(tag: str) -> str:
         """

linodecli/cli.py

@@ -8,6 +8,7 @@
 import pickle
 import sys
 from json import JSONDecodeError
+from logging import getLogger
 from sys import version_info
 from typing import IO, Any, ContextManager, Dict
 
@@ -23,6 +24,8 @@
 
 METHODS = ("get", "post", "put", "delete")
 
+logger = getLogger(__name__)
+
 
 class CLI:  # pylint: disable=too-many-instance-attributes
     """
@@ -54,6 +57,7 @@ def bake(self, spec_location: str):
         """
 
         try:
+            logger.debug("Loading and parsing OpenAPI spec: %s", spec_location)
             spec = self._load_openapi_spec(spec_location)
         except Exception as e:
             print(f"Failed to load spec: {e}")
@@ -72,21 +76,60 @@ def bake(self, spec_location: str):
             command = path.extensions.get(ext["command"], "default")
             for m in METHODS:
                 operation = getattr(path, m)
-                if operation is None or ext["skip"] in operation.extensions:
+
+                if operation is None:
+                    continue
+
+                operation_log_fmt = f"{m.upper()} {path.path[-1]}"
+
+                logger.debug(
+                    "%s: Attempting to generate command for operation",
+                    operation_log_fmt,
+                )
+
+                if ext["skip"] in operation.extensions:
+                    logger.debug(
+                        "%s: Skipping operation due to x-linode-cli-skip extension",
+                        operation_log_fmt,
+                    )
                     continue
+
                 action = operation.extensions.get(
                     ext["action"], operation.operationId
                 )
                 if not action:
+                    logger.warning(
+                        "%s: Skipping operation due to unresolvable action",
+                        operation_log_fmt,
+                    )
                     continue
+
                 if isinstance(action, list):
                     action = action[0]
+
                 if command not in self.ops:
                     self.ops[command] = {}
-                self.ops[command][action] = OpenAPIOperation(
+
+                operation = OpenAPIOperation(
                     command, operation, m, path.parameters
                 )
 
+                logger.debug(
+                    "%s %s: Successfully built command for operation: "
+                    "command='%s %s'; summary='%s'; paginated=%s; num_args=%s; num_attrs=%s",
+                    operation.method.upper(),
+                    operation.url_path,
+                    operation.command,
+                    operation.action,
+                    operation.summary.rstrip("."),
+                    operation.response_model
+                    and operation.response_model.is_paginated,
+                    len(operation.args),
+                    len(operation.attrs),
+                )
+
+                self.ops[command][action] = operation
+
         # hide the base_url from the spec away
         self.ops["_base_url"] = self.spec.servers[0].url
         self.ops["_spec_version"] = self.spec.info.version

linodecli/helpers.py

@@ -106,7 +106,10 @@ def register_debug_arg(parser: ArgumentParser):
     ArgumentParser that may be shared across the CLI and plugins.
     """
     parser.add_argument(
-        "--debug", action="store_true", help="Enable verbose HTTP debug output."
+        "--debug",
+        action="store_true",
+        help="Enable verbose debug logging, including displaying HTTP debug output and "
+        "configuring the Python logging package level to DEBUG.",
     )