Use trace level for event content and other sensitive info

Author: tulir

mautrix/api/http.py

@@ -123,7 +123,6 @@ def __init__(self, base_url: str, token: str, *, client_session: ClientSession =
         self.log: Optional[logging.Logger] = log or logging.getLogger("mautrix.api")
         self.loop = loop or asyncio.get_event_loop()
         self.session: ClientSession = client_session or ClientSession(loop=self.loop)
-        self.log_sync = False
         if txn_id is not None:
             self.txn_id: int = txn_id
 
@@ -155,18 +154,17 @@ def _log_request(self, method: Method, path: PathBuilder, content: Union[str, by
                      orig_content, query_params: Dict[str, str]) -> None:
         if not self.log:
             return
-        if not self.log_sync and path == Path.sync:
-            return
         log_content = content if not isinstance(content, bytes) else f"<{len(content)} bytes>"
         as_user = query_params.get("user_id", None)
-        self.log.debug(f"{method} {path} {log_content}".strip(" "),
-                       extra={"matrix_http_request": {
-                           "method": str(method),
-                           "path": str(path),
-                           "content": (orig_content if isinstance(orig_content, (dict, list))
-                                       else log_content),
-                           "user": as_user,
-                       }})
+        level = 1 if path == Path.sync else 5
+        self.log.log(level, f"{method} {path} {log_content}".strip(" "),
+                     extra={"matrix_http_request": {
+                         "method": str(method),
+                         "path": str(path),
+                         "content": (orig_content if isinstance(orig_content, (dict, list))
+                                     else log_content),
+                         "user": as_user,
+                     }})
 
     async def request(self, method: Method, path: PathBuilder,
                       content: Optional[Union[JSON, bytes, str]] = None,

mautrix/bridge/matrix.py

@@ -15,6 +15,7 @@
                            EncryptedEvent)
 from mautrix.errors import IntentError, MatrixError, MForbidden
 from mautrix.appservice import AppService
+from mautrix.util.logging import TraceLogger
 
 from .commands import CommandProcessor
 
@@ -32,7 +33,7 @@
 
 
 class BaseMatrixHandler(ABC):
-    log: logging.Logger = logging.getLogger("mau.mx")
+    log: TraceLogger = logging.getLogger("mau.mx")
     az: AppService
     commands: CommandProcessor
     config: 'BaseBridgeConfig'
@@ -249,10 +250,11 @@ async def handle_message(self, room_id: RoomID, user_id: UserID, message: Messag
                              event_id: EventID) -> None:
         sender = await self.get_user(user_id)
         if not sender or not await self.allow_message(sender):
-            self.log.debug(f"Ignoring message \"{message}\" from {user_id} to {room_id}:"
+            self.log.debug(f"Ignoring message {event_id} from {user_id} to {room_id}:"
                            " User is not whitelisted.")
             return
-        self.log.debug(f"Received Matrix event \"{message}\" from {sender.mxid} in {room_id}")
+        self.log.debug(f"Received Matrix event {event_id} from {sender.mxid} in {room_id}")
+        self.log.trace("Event %s content: %s", event_id, message)
 
         if isinstance(message, TextMessageEventContent):
             message.trim_reply_fallback()
@@ -296,7 +298,7 @@ async def try_handle_sync_event(self, evt: Event) -> None:
             if isinstance(evt, (ReceiptEvent, PresenceEvent, TypingEvent)):
                 await self.handle_ephemeral_event(evt)
             else:
-                self.log.debug("Unknown event type received from sync:", evt)
+                self.log.trace("Unknown event type received from sync: %s", evt)
         except Exception:
             self.log.exception("Error handling manually received Matrix event")
 
@@ -324,7 +326,7 @@ async def int_handle_event(self, evt: Event) -> None:
             await self.e2ee.handle_room_membership(evt)
         if self.filter_matrix_event(evt):
             return
-        self.log.debug("Received event: %s", evt)
+        self.log.trace("Received event: %s", evt)
         start_time = time.time()
 
         if evt.type == EventType.ROOM_MEMBER:

mautrix/util/logging/__init__.py

@@ -1,2 +1,2 @@
 from .color import ColorFormatter
-from .trace import TRACE
+from .trace import TRACE, TraceLogger

mautrix/util/logging/trace.py

@@ -9,12 +9,18 @@
 TRACE = logging.TRACE = 5
 logging.addLevelName(TRACE, "TRACE")
 
+SILLY = logging.SILLY = 1
+logging.addLevelName(SILLY, "SILLY")
+
 OldLogger: Type[logging.Logger] = cast(Type[logging.Logger], logging.getLoggerClass())
 
 
 class TraceLogger(OldLogger):
     def trace(self, msg, *args, **kwargs) -> None:
         self.log(TRACE, msg, *args, **kwargs)
 
+    def silly(self, msg, *args, **kwargs) -> None:
+        self.log(SILLY, msg, *args, **kwargs)
+
 
 logging.setLoggerClass(TraceLogger)