Configure logging level using --debug flag; add logging to bake command

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,7 +7,8 @@
 import os
 import sys
 import time
-from typing import Any, Iterable, List, Optional
+from logging import getLogger
+from typing import Any, Dict, Iterable, List, Optional
 
 import requests
 from packaging import version
@@ -23,6 +24,8 @@
 )
 from .helpers import handle_url_overrides
 
+logger = getLogger(__name__)
+
 
 def get_all_pages(ctx, operation: OpenAPIOperation, args: List[str]):
     """
@@ -87,13 +90,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"
+            + "\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" + "\n".join(_format_response_for_log(result)))
 
     while _check_retry(result) and not ctx.no_retry and ctx.retry_count < 3:
         time.sleep(_get_retry_after(result.headers))
@@ -282,38 +290,61 @@ def _build_request_body(ctx, operation, parsed_args) -> Optional[str]:
     return json.dumps(_traverse_request_body(expanded_json))
 
 
-def _print_request_debug_info(method, url, headers, body):
+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: 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 ''}", f"> "])
+
+    return result
 
 
-def _print_response_debug_info(response):
+def _format_response_for_log(
+    response: requests.Response,
+):
     """
-    Prints debug info for a response from requests
+    Builds a debug output for the given request.
+
+    :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, result):

linodecli/baked/operation.py

@@ -5,6 +5,7 @@
 import argparse
 import glob
 import json
+import logging
 import platform
 import re
 import sys
@@ -17,6 +18,7 @@
 import openapi3.paths
 from openapi3.paths import Operation, Parameter
 
+from linodecli import logging
 from linodecli.baked.parsing import simplify_description
 from linodecli.baked.request import (
     OpenAPIFilteringRequest,
@@ -400,9 +402,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 +429,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

@@ -23,6 +23,10 @@
 
 METHODS = ("get", "post", "put", "delete")
 
+from logging import getLogger
+
+logger = getLogger(__name__)
+
 
 class CLI:  # pylint: disable=too-many-instance-attributes
     """
@@ -54,6 +58,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 +77,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.",
     )
 
 

tests/unit/test_api_request.py

@@ -21,8 +21,6 @@ class TestAPIRequest:
     """
 
     def test_response_debug_info(self):
-        stderr_buf = io.StringIO()
-
         mock_response = SimpleNamespace(
             raw=SimpleNamespace(version=11.1),
             status_code=200,
@@ -31,34 +29,32 @@ def test_response_debug_info(self):
             content=b"cool body",
         )
 
-        with contextlib.redirect_stderr(stderr_buf):
-            api_request._print_response_debug_info(mock_response)
+        result = api_request._format_response_for_log(mock_response)
 
-        output = stderr_buf.getvalue()
-        assert "< HTTP/1.1 200 OK" in output
-        assert "< cool: test" in output
-        assert "< Body:" in output
-        assert "<   cool body" in output
-        assert "< " in output
+        assert result == [
+            "< HTTP/1.1 200 OK",
+            "< cool: test",
+            "< Body:",
+            "<   cool body",
+            "< ",
+        ]
 
     def test_request_debug_info(self):
-        stderr_buf = io.StringIO()
-
-        with contextlib.redirect_stderr(stderr_buf):
-            api_request._print_request_debug_info(
-                SimpleNamespace(__name__="get"),
-                "https://definitely.linode.com/",
-                {"cool": "test", "Authorization": "sensitiveinfo"},
-                "cool body",
-            )
+        result = api_request._format_request_for_log(
+            SimpleNamespace(__name__="get"),
+            "https://definitely.linode.com/",
+            {"cool": "test", "Authorization": "sensitiveinfo"},
+            "cool body",
+        )
 
-        output = stderr_buf.getvalue()
-        assert "> GET https://definitely.linode.com/" in output
-        assert "> cool: test" in output
-        assert f"> Authorization: Bearer {'*' * 64}" in output
-        assert "> Body:" in output
-        assert ">   cool body" in output
-        assert "> " in output
+        assert result == [
+            "> GET https://definitely.linode.com/",
+            "> cool: test",
+            f"> Authorization: Bearer {'*' * 64}",
+            "> Body:",
+            ">   cool body",
+            "> ",
+        ]
 
     def test_build_request_body(self, mock_cli, create_operation):
         create_operation.allowed_defaults = ["region", "image"]