Partially log requests sent to the API

Payloads containing sensitive content (such as passwords and
tokens) should be hidden.

snikket_web/prosodyclient.py

@@ -3,6 +3,8 @@ import contextlib
 import functools
 import hashlib
 import json
+import logging
+import secrets
 
 import aiohttp
 
@@ -102,6 +104,9 @@ class ProsodyClient:
         self._plain_session = HTTPSessionManager(self.CTX_PLAIN_SESSION)
         self._auth_session = HTTPAuthSessionManager(self.CTX_AUTH_SESSION,
                                                     self.SESSION_TOKEN)
+        self.logger = logging.getLogger(
+            ".".join([__name__, type(self).__qualname__])
+        )
         self.app = app
         if app is not None:
             self.init_app(app)
@@ -140,6 +145,7 @@ class ProsodyClient:
         request.add_field("username", jid)
         request.add_field("password", password)
 
+        self.logger.debug("sending OAuth2 request (payload omitted)")
         async with session.post(self._login_endpoint, data=request) as resp:
             auth_status = resp.status
             auth_data = (await resp.read())
@@ -151,6 +157,7 @@ class ProsodyClient:
 
             # XXX: prosody-modules#1502
             if auth_status in [400, 401] or "error" in auth_info:
+                self.logger.debug("oauth2 error: %r", auth_info)
                 # OAuth2 spec says that’s what can happen when some stuff is
                 # wrong.
                 # we have to interpret the JSON further
@@ -159,6 +166,7 @@ class ProsodyClient:
 
             if auth_status == 200:
                 token_type = auth_info["token_type"]
+                self.logger.debug("oauth2 success: token_type=%r", token_type)
                 if token_type != "bearer":
                     raise NotImplementedError(
                         "unsupported token type: {!r}".format(
@@ -216,18 +224,32 @@ class ProsodyClient:
             return wrapped
         return decorator
 
-    async def _xml_iq_call(self, session, payload, *, headers=None):
+    async def _xml_iq_call(self, session, payload, *, headers=None,
+                           sensitive=False):
         headers = headers or {}
         headers.update({
             "Content-Type": "application/xmpp+xml",
             "Accept": "application/xmpp+xml",
         })
+        if not payload.get("id"):
+            payload.set("id", secrets.token_hex(8))
+
+        serialised = ET.tostring(payload)
+        id_ = payload.get("id")
+        self.logger.debug(
+            "sending IQ (id=%s): %r",
+            id_, "(sensitive)" if sensitive else serialised,
+        )
         async with session.post(self._rest_endpoint,
                                 headers=headers,
-                                data=payload) as resp:
+                                data=serialised) as resp:
             if resp.status != 200:
                 abort(resp.status)
             reply_payload = await resp.read()
+            self.logger.debug(
+                "received IQ (in-reply-to id=%s): %r",
+                id_, "(sensitive)" if sensitive else reply_payload,
+            )
             return ET.fromstring(reply_payload)
 
     async def get_user_info(self):
@@ -354,7 +376,8 @@ class ProsodyClient:
                 ),
                 headers={
                     "Authorization": "Bearer {}".format(token),
-                }
+                },
+                sensitive=True,
             )
             # TODO: error handling
             # TODO: obtain a new token using the new password to allow the

snikket_web/xmpputil.py

@@ -97,7 +97,7 @@ def make_password_change_request(jid, password):
     q = ET.SubElement(req, "query", xmlns="jabber:iq:register")
     ET.SubElement(q, "username").text = username
     ET.SubElement(q, "password").text = password
-    return ET.tostring(req)
+    return req
 
 
 def make_pubsub_item_put_request(to, node, id_=None):
@@ -116,7 +116,7 @@ def make_nickname_set_request(to, nickname):
         NODE_USER_NICKNAME,
     )
     ET.SubElement(item, "nick", xmlns=NS_USER_NICKNAME).text = nickname
-    return ET.tostring(req)
+    return req
 
 
 def make_pubsub_item_request(to, node, id_=None):
@@ -128,7 +128,7 @@ def make_pubsub_item_request(to, node, id_=None):
     else:
         items.set("max_items", "1")
 
-    return ET.tostring(req)
+    return req
 
 
 def make_nickname_get_request(to):
@@ -151,7 +151,7 @@ def make_avatar_data_set_request(to, data, id_):
     )
     ET.SubElement(item, "data", xmlns=NS_USER_AVATAR_DATA).text = \
         base64.b64encode(data).decode("ascii")
-    return ET.tostring(req)
+    return req
 
 
 def make_avatar_metadata_set_request(to, mimetype: str, id_: str, size: int,
@@ -177,7 +177,7 @@ def make_avatar_metadata_set_request(to, mimetype: str, id_: str, size: int,
         attr["height"] = str(height)
 
     ET.SubElement(metadata_wrap, "info", xmlns=NS_USER_AVATAR_METADATA, **attr)
-    return ET.tostring(req)
+    return req
 
 
 def _require_child(t: ET.Element, tag: str) -> ET.Element: