Improve Logging for API HTTP requests (#715)

* improve: unify logging for all HTTP requests and responses

* convert requests.HTTPError to readable errors

* skip logging if verbose is off

* truncate long json params

Author: ptpt

mapillary_tools/api_v4.py

@@ -2,6 +2,7 @@
 import os
 import ssl
 import typing as T
+from json import dumps
 
 import requests
 from requests.adapters import HTTPAdapter
@@ -46,6 +47,106 @@ def cert_verify(self, *args, **kwargs):
         conn.ca_certs = None
 
 
+@T.overload
+def _truncate(s: bytes, limit: int = 512) -> bytes: ...
+
+
+@T.overload
+def _truncate(s: str, limit: int = 512) -> str: ...
+
+
+def _truncate(s, limit=512):
+    if limit < len(s):
+        remaining = len(s) - limit
+        if isinstance(s, bytes):
+            return (
+                s[:limit]
+                + b"..."
+                + f"({remaining} more bytes truncated)".encode("utf-8")
+            )
+        else:
+            return str(s[:limit]) + f"...({remaining} more chars truncated)"
+    else:
+        return s
+
+
+def _sanitize(headers: T.Dict):
+    new_headers = {}
+
+    for k, v in headers.items():
+        if k.lower() in [
+            "authorization",
+            "cookie",
+            "x-fb-access-token",
+            "access-token",
+            "access_token",
+            "password",
+        ]:
+            new_headers[k] = "[REDACTED]"
+        else:
+            new_headers[k] = _truncate(v)
+
+    return new_headers
+
+
+def _log_debug_request(
+    method: str,
+    url: str,
+    json: T.Optional[T.Dict] = None,
+    params: T.Optional[T.Dict] = None,
+    headers: T.Optional[T.Dict] = None,
+    timeout: T.Any = None,
+):
+    if logging.getLogger().getEffectiveLevel() <= logging.DEBUG:
+        return
+
+    msg = f"HTTP {method} {url}"
+
+    if USE_SYSTEM_CERTS:
+        msg += " (w/sys_certs)"
+
+    if json:
+        t = _truncate(dumps(_sanitize(json)))
+        msg += f" JSON={t}"
+
+    if params:
+        msg += f" PARAMS={_sanitize(params)}"
+
+    if headers:
+        msg += f" HEADERS={_sanitize(headers)}"
+
+    if timeout is not None:
+        msg += f" TIMEOUT={timeout}"
+
+    LOG.debug(msg)
+
+
+def _log_debug_response(resp: requests.Response):
+    if logging.getLogger().getEffectiveLevel() <= logging.DEBUG:
+        return
+
+    data: T.Union[str, bytes]
+    try:
+        data = _truncate(dumps(_sanitize(resp.json())))
+    except Exception:
+        data = _truncate(resp.content)
+
+    LOG.debug(f"HTTP {resp.status_code} ({resp.reason}): %s", data)
+
+
+def readable_http_error(ex: requests.HTTPError) -> str:
+    req = ex.request
+    resp = ex.response
+
+    data: T.Union[str, bytes]
+    try:
+        data = _truncate(dumps(_sanitize(resp.json())))
+    except Exception:
+        data = _truncate(resp.content)
+
+    return f"{req.method} {resp.url} => {resp.status_code} ({resp.reason}): {str(data)}"
+
+
 def request_post(
     url: str,
     data: T.Optional[T.Any] = None,
@@ -54,14 +155,23 @@ def request_post(
 ) -> requests.Response:
     global USE_SYSTEM_CERTS
 
+    _log_debug_request(
+        "POST",
+        url,
+        json=json,
+        params=kwargs.get("params"),
+        headers=kwargs.get("headers"),
+        timeout=kwargs.get("timeout"),
+    )
+
     if USE_SYSTEM_CERTS:
         with requests.Session() as session:
             session.mount("https://", HTTPSystemCertsAdapter())
-            return session.post(url, data=data, json=json, **kwargs)
+            resp = session.post(url, data=data, json=json, **kwargs)
 
     else:
         try:
-            return requests.post(url, data=data, json=json, **kwargs)
+            resp = requests.post(url, data=data, json=json, **kwargs)
         except requests.exceptions.SSLError as ex:
             if "SSLCertVerificationError" not in str(ex):
                 raise ex
@@ -70,9 +180,11 @@ def request_post(
             LOG.warning(
                 "SSL error occurred, falling back to system SSL certificates: %s", ex
             )
-            with requests.Session() as session:
-                session.mount("https://", HTTPSystemCertsAdapter())
-                return session.post(url, data=data, json=json, **kwargs)
+            return request_post(url, data=data, json=json, **kwargs)
+
+    _log_debug_response(resp)
+
+    return resp
 
 
 def request_get(
@@ -82,13 +194,21 @@ def request_get(
 ) -> requests.Response:
     global USE_SYSTEM_CERTS
 
+    _log_debug_request(
+        "GET",
+        url,
+        params=kwargs.get("params"),
+        headers=kwargs.get("headers"),
+        timeout=kwargs.get("timeout"),
+    )
+
     if USE_SYSTEM_CERTS:
         with requests.Session() as session:
             session.mount("https://", HTTPSystemCertsAdapter())
-            return session.get(url, params=params, **kwargs)
+            resp = session.get(url, params=params, **kwargs)
     else:
         try:
-            return requests.get(url, params=params, **kwargs)
+            resp = requests.get(url, params=params, **kwargs)
         except requests.exceptions.SSLError as ex:
             if "SSLCertVerificationError" not in str(ex):
                 raise ex
@@ -97,15 +217,17 @@ def request_get(
             LOG.warning(
                 "SSL error occurred, falling back to system SSL certificates: %s", ex
             )
-            with requests.Session() as session:
-                session.mount("https://", HTTPSystemCertsAdapter())
-                return session.get(url, params=params, **kwargs)
+            resp = request_get(url, params=params, **kwargs)
+
+    _log_debug_response(resp)
+
+    return resp
 
 
 def get_upload_token(email: str, password: str) -> requests.Response:
     resp = request_post(
         f"{MAPILLARY_GRAPH_API_ENDPOINT}/login",
-        params={"access_token": MAPILLARY_CLIENT_TOKEN},
+        headers={"Authorization": f"OAuth {MAPILLARY_CLIENT_TOKEN}"},
         json={"email": email, "password": password, "locale": "en_US"},
         timeout=REQUESTS_TIMEOUT,
     )

mapillary_tools/commands/__main__.py

@@ -5,7 +5,9 @@
 import typing as T
 from pathlib import Path
 
-from .. import constants, exceptions, VERSION
+import requests
+
+from .. import api_v4, constants, exceptions, VERSION
 from . import (
     authenticate,
     process,
@@ -160,11 +162,14 @@ def main():
 
     try:
         args.func(argvars)
-    except exceptions.MapillaryUserError as exc:
+    except requests.HTTPError as ex:
+        LOG.error("%s: %s", ex.__class__.__name__, api_v4.readable_http_error(ex))
+
+    except exceptions.MapillaryUserError as ex:
         LOG.error(
-            "%s: %s", exc.__class__.__name__, exc, exc_info=log_level == logging.DEBUG
+            "%s: %s", ex.__class__.__name__, ex, exc_info=log_level == logging.DEBUG
         )
-        sys.exit(exc.exit_code)
+        sys.exit(ex.exit_code)
 
 
 if __name__ == "__main__":

mapillary_tools/commands/process_and_upload.py

@@ -15,5 +15,6 @@ def run(self, args: dict):
             # \x00 is a special path similiar to /dev/null
             # it tells process command do not write anything
             args["desc_path"] = "\x00"
+
         ProcessCommand().run(args)
         UploadCommand().run(args)

mapillary_tools/upload.py

@@ -47,25 +47,6 @@ def __init__(self, inner_ex) -> None:
         super().__init__(str(inner_ex))
 
 
-class UploadHTTPError(Exception):
-    pass
-
-
-def wrap_http_exception(ex: requests.HTTPError):
-    req = ex.request
-    resp = ex.response
-    if isinstance(resp, requests.Response) and isinstance(req, requests.Request):
-        lines = [
-            f"{req.method} {resp.url}",
-            f"> HTTP Status: {resp.status_code}",
-            str(resp.content),
-        ]
-    else:
-        lines = []
-
-    return UploadHTTPError("\n".join(lines))
-
-
 def _load_validate_metadatas_from_desc_path(
     desc_path: T.Optional[str], import_paths: T.Sequence[Path]
 ) -> T.List[types.Metadata]:
@@ -175,18 +156,12 @@ def fetch_user_items(
                 "Found multiple Mapillary accounts. Please specify one with --user_name"
             )
     else:
-        try:
-            user_items = authenticate.authenticate_user(user_name)
-        except requests.HTTPError as exc:
-            raise wrap_http_exception(exc) from exc
+        user_items = authenticate.authenticate_user(user_name)
 
     if organization_key is not None:
-        try:
-            resp = api_v4.fetch_organization(
-                user_items["user_upload_token"], organization_key
-            )
-        except requests.HTTPError as ex:
-            raise wrap_http_exception(ex) from ex
+        resp = api_v4.fetch_organization(
+            user_items["user_upload_token"], organization_key
+        )
         org = resp.json()
         LOG.info("Uploading to organization: %s", json.dumps(org))
         user_items = T.cast(
@@ -430,15 +405,12 @@ def _api_logging_finished(summary: T.Dict):
     action: api_v4.ActionType = "upload_finished_upload"
     LOG.debug("API Logging for action %s: %s", action, summary)
     try:
-        api_v4.log_event(
-            action,
-            summary,
-        )
+        api_v4.log_event(action, summary)
     except requests.HTTPError as exc:
         LOG.warning(
-            "Error from API Logging for action %s",
+            "HTTPError from API Logging for action %s: %s",
             action,
-            exc_info=wrap_http_exception(exc),
+            api_v4.readable_http_error(exc),
         )
     except Exception:
         LOG.warning("Error from API Logging for action %s", action, exc_info=True)
@@ -452,16 +424,12 @@ def _api_logging_failed(payload: T.Dict, exc: Exception):
     action: api_v4.ActionType = "upload_failed_upload"
     LOG.debug("API Logging for action %s: %s", action, payload)
     try:
-        api_v4.log_event(
-            action,
-            payload_with_reason,
-        )
+        api_v4.log_event(action, payload_with_reason)
     except requests.HTTPError as exc:
-        wrapped_exc = wrap_http_exception(exc)
         LOG.warning(
-            "Error from API Logging for action %s",
+            "HTTPError from API Logging for action %s: %s",
             action,
-            exc_info=wrapped_exc,
+            api_v4.readable_http_error(exc),
         )
     except Exception:
         LOG.warning("Error from API Logging for action %s", action, exc_info=True)
@@ -678,7 +646,7 @@ def upload(
                     raise exceptions.MapillaryUploadUnauthorizedError(
                         debug_info.get("message")
                     ) from inner_ex
-            raise wrap_http_exception(inner_ex) from inner_ex
+            raise inner_ex
 
         raise inner_ex