Move private information to trace log level. Fixes #321

mautrix_telegram/abstract_user.py

@@ -35,6 +35,7 @@ from telethon.tl.types import (
 from mautrix.types import UserID, PresenceState
 from mautrix.errors import MatrixError
 from mautrix.appservice import AppService
+from mautrix.util.logging import TraceLogger
 from alchemysession import AlchemySessionContainer
 
 from . import portal as po, puppet as pu, __version__
@@ -68,7 +69,7 @@ except ImportError:
 class AbstractUser(ABC):
     session_container: AlchemySessionContainer = None
     loop: asyncio.AbstractEventLoop = None
-    log: logging.Logger
+    log: TraceLogger
     az: AppService
     relaybot: Optional['Bot']
     ignore_incoming_bot_events: bool = True
@@ -258,7 +259,7 @@ class AbstractUser(ABC):
         elif isinstance(update, UpdateReadHistoryOutbox):
             await self.update_read_receipt(update)
         else:
-            self.log.debug("Unhandled update: %s", update)
+            self.log.trace("Unhandled update: %s", update)
 
     async def update_pinned_messages(self, update: Union[UpdateChannelPinnedMessage,
                                                          UpdateChatPinnedMessage]) -> None:
@@ -333,7 +334,7 @@ class AbstractUser(ABC):
             if await puppet.update_avatar(self, update.photo):
                 puppet.save()
         else:
-            self.log.warning("Unexpected other user info update: %s", update)
+            self.log.warning(f"Unexpected other user info update: {type(update)}")
 
     async def update_status(self, update: UpdateUserStatus) -> None:
         puppet = pu.Puppet.get(TelegramID(update.user_id))
@@ -342,7 +343,7 @@ class AbstractUser(ABC):
         elif isinstance(update.status, UserStatusOffline):
             await puppet.default_mxid_intent.set_presence(PresenceState.OFFLINE)
         else:
-            self.log.warning("Unexpected user status update: %s", update)
+            self.log.warning(f"Unexpected user status update: type({update})")
         return
 
     def get_message_details(self, update: UpdateMessage) -> Tuple[UpdateMessageContent,
@@ -366,8 +367,7 @@ class AbstractUser(ABC):
                 portal = po.Portal.get_by_entity(update.to_id, receiver_id=self.tgid)
             sender = pu.Puppet.get(update.from_id) if update.from_id else None
         else:
-            self.log.warning(
+            self.log.warning(f"Unexpected message type in User#get_message_details: {type(update)}")
-                f"Unexpected message type in User#get_message_details: {type(update)}")
             return update, None, None
         return update, sender, portal
 
@@ -428,11 +428,10 @@ class AbstractUser(ABC):
 
         if isinstance(update, MessageService):
             if isinstance(update.action, MessageActionChannelMigrateFrom):
-                self.log.debug(f"Ignoring action %s to %s by %d", update.action,
+                self.log.trace(f"Ignoring action %s to %s by %d", update.action, portal.tgid_log,
-                               portal.tgid_log,
                                sender.id)
                 return
-            self.log.debug("Handling action %s to %s by %d", update.action, portal.tgid_log,
+            self.log.trace("Handling action %s to %s by %d", update.action, portal.tgid_log,
                            sender.id)
             return await portal.handle_telegram_action(self, sender, update)
 

mautrix_telegram/commands/telegram/misc.py

@@ -165,7 +165,9 @@ async def join(evt: CommandEvent) -> Optional[EventID]:
             try:
                 await portal.create_matrix_room(evt.sender, chat, [evt.sender.mxid])
             except ChatIdInvalidError as e:
-                logging.getLogger("mau.commands").info(updates.stringify())
+                logging.getLogger("mau.commands").trace("ChatIdInvalidError while creating portal "
+                                                        "from !tg join command: %s",
+                                                        updates.stringify())
                 raise e
             return await evt.reply(f"Created room for {portal.title}")
     return None

mautrix_telegram/portal/base.py

@@ -32,6 +32,7 @@ from mautrix.errors import MatrixRequestError, IntentError
 from mautrix.appservice import AppService, IntentAPI
 from mautrix.types import RoomID, RoomAlias, UserID, EventType, PowerLevelStateEventContent
 from mautrix.util.simple_template import SimpleTemplate
+from mautrix.util.logging import TraceLogger
 
 from ..types import TelegramID
 from ..context import Context
@@ -55,7 +56,7 @@ config: Optional['Config'] = None
 
 
 class BasePortal(ABC):
-    base_log: logging.Logger = logging.getLogger("mau.portal")
+    base_log: TraceLogger = logging.getLogger("mau.portal")
     az: AppService = None
     bot: 'Bot' = None
     loop: asyncio.AbstractEventLoop = None
@@ -92,7 +93,7 @@ class BasePortal(ABC):
     deleted: bool
     backfilling: bool
     backfill_leave: Optional[Set[IntentAPI]]
-    log: logging.Logger
+    log: TraceLogger
 
     alias: Optional[RoomAlias]
 
@@ -243,8 +244,7 @@ class BasePortal(ABC):
             return await user.client.get_entity(self.peer)
         except ValueError:
             if user.is_bot:
-                self.log.warning(f"Could not find entity with bot {user.tgid}. "
+                self.log.warning(f"Could not find entity with bot {user.tgid}. Failing...")
-                                 "Failing...")
                 raise
             self.log.warning(f"Could not find entity with user {user.tgid}. "
                              "falling back to get_dialogs.")

mautrix_telegram/portal/matrix.py

@@ -342,7 +342,7 @@ class PortalMatrix(BasePortal, MautrixBasePortal, ABC):
 
     def _add_telegram_message_to_db(self, event_id: EventID, space: TelegramID,
                                     edit_index: int, response: TypeMessage) -> None:
-        self.log.debug("Handled Matrix message: %s", response)
+        self.log.trace("Handled Matrix message: %s", response)
         self.dedup.check(response, (event_id, space), force_hash=edit_index != 0)
         if edit_index < 0:
             prev_edit = DBMessage.get_one_by_tgid(TelegramID(response.id), space, -1)
@@ -403,7 +403,7 @@ class PortalMatrix(BasePortal, MautrixBasePortal, ABC):
             await self._handle_matrix_file(sender_id, event_id, space, client, content, reply_to,
                                            caption_content)
         else:
-            self.log.debug(f"Unhandled Matrix event: {content}")
+            self.log.trace("Unhandled Matrix event: %s", content)
 
     async def handle_matrix_pin(self, sender: 'u.User',
                                 pinned_message: Optional[EventID]) -> None:

mautrix_telegram/portal/metadata.py

@@ -267,7 +267,7 @@ class PortalMetadata(BasePortal, ABC):
 
         if not entity:
             entity = await self.get_entity(user)
-            self.log.debug(f"Fetched data: {entity}")
+            self.log.trace("Fetched data: %s", entity)
 
         self.log.debug("Creating room")
 
@@ -600,7 +600,7 @@ class PortalMetadata(BasePortal, ABC):
         try:
             if not entity:
                 entity = await self.get_entity(user)
-                self.log.debug(f"Fetched data: {entity}")
+                self.log.trace("Fetched data: %s", entity)
 
             if self.peer_type == "channel":
                 changed = self.megagroup != entity.megagroup or changed

mautrix_telegram/portal/telegram.py

@@ -80,7 +80,7 @@ class PortalTelegram(BasePortal, ABC):
         return await intent.send_message_event(self.mxid, event_type, content, **kwargs)
 
     async def handle_telegram_photo(self, source: 'AbstractUser', intent: IntentAPI, evt: Message,
-                                    relates_to: Dict = None) -> Optional[EventID]:
+                                    relates_to: RelatesTo = None) -> Optional[EventID]:
         loc, largest_size = self._get_largest_photo_size(evt.media.photo)
         file = await util.transfer_file_to_matrix(source.client, intent, loc,
                                                   encrypt=self.encrypted)
@@ -227,8 +227,8 @@ class PortalTelegram(BasePortal, ABC):
             content.url = file.mxc
         return await self._send_message(intent, content, event_type=event_type, timestamp=evt.date)
 
-    def handle_telegram_location(self, _: 'AbstractUser', intent: IntentAPI, evt: Message,
+    def handle_telegram_location(self, source: 'AbstractUser', intent: IntentAPI, evt: Message,
-                                 relates_to: dict = None) -> Awaitable[EventID]:
+                                 relates_to: RelatesTo = None) -> Awaitable[EventID]:
         long = evt.media.geo.long
         lat = evt.media.geo.lat
         long_char = "E" if long > 0 else "W"
@@ -257,7 +257,7 @@ class PortalTelegram(BasePortal, ABC):
         return await self._send_message(intent, content, timestamp=evt.date)
 
     async def handle_telegram_unsupported(self, source: 'AbstractUser', intent: IntentAPI,
-                                          evt: Message, relates_to: dict = None) -> EventID:
+                                          evt: Message, relates_to: RelatesTo = None) -> EventID:
         override_text = ("This message is not supported on your version of Mautrix-Telegram. "
                          "Please check https://github.com/tulir/mautrix-telegram or ask your "
                          "bridge administrator about possible updates.")
@@ -312,7 +312,7 @@ class PortalTelegram(BasePortal, ABC):
 
     @staticmethod
     def _int_to_bytes(i: int) -> bytes:
-        hex_value = "{0:010x}".format(i)
+        hex_value = "{0:010x}".format(i).encode("utf-8")
         return codecs.decode(hex_value, "hex_codec")
 
     def _encode_msgid(self, source: 'AbstractUser', evt: Message) -> str:
@@ -355,6 +355,7 @@ class PortalTelegram(BasePortal, ABC):
     async def handle_telegram_edit(self, source: 'AbstractUser', sender: p.Puppet, evt: Message
                                    ) -> None:
         if not self.mxid:
+            self.log.trace("Ignoring edit to %d as chat has no Matrix room", evt.id)
             return
         elif hasattr(evt, "media") and isinstance(evt.media, MessageMediaGame):
             self.log.debug("Ignoring game message edit event")
@@ -402,17 +403,21 @@ class PortalTelegram(BasePortal, ABC):
         DBMessage.update_by_mxid(temporary_identifier, self.mxid, mxid=event_id)
 
     async def backfill(self, source: 'AbstractUser') -> None:
+        self.log.debug("Backfilling history through %s", source.mxid)
         last = DBMessage.find_last(self.mxid, (source.tgid if self.peer_type != "channel"
                                                else self.tgid))
         min_id = last.tgid if last else 0
         self.backfilling = True
         self.backfill_leave = set()
         if self.peer_type == "user":
+            self.log.debug("Adding %s's default puppet to room for backfilling", source.mxid)
             sender = p.Puppet.get(source.tgid)
             await self.main_intent.invite_user(self.mxid, sender.default_mxid)
             await sender.default_mxid_intent.join_room_by_id(self.mxid)
             self.backfill_leave.add(sender.default_mxid_intent)
         max_file_size = min(config["bridge.max_document_size"], 1500) * 1024 * 1024
+        self.log.trace("Opening takeout client for %d, message ID %d->", source.tgid, min_id)
+        count = 0
         async with source.client.takeout(files=True, megagroups=self.megagroup,
                                          chats=self.peer_type == "chat",
                                          users=self.peer_type == "user",
@@ -426,14 +431,18 @@ class PortalTelegram(BasePortal, ABC):
                 # if isinstance(message, MessageService):
                 #    await self.handle_telegram_action(source, sender, message)
                 await self.handle_telegram_message(source, sender, message)
+                count += 1
         for intent in self.backfill_leave:
+            self.log.trace("Leaving room with %s post-backfill", intent.mxid)
             await intent.leave_room(self.mxid)
         self.backfilling = False
         self.backfill_leave = None
+        self.log.info("Backfilled %d messages through %s", count, source.mxid)
 
     async def handle_telegram_message(self, source: 'AbstractUser', sender: p.Puppet,
                                       evt: Message) -> None:
         if not self.mxid:
+            self.log.trace("Got telegram message %d, but no room exists, creating...", evt.id)
             await self.create_matrix_room(source, invites=[source.mxid], update_if_exists=False)
 
         if (self.peer_type == "user" and sender.tgid == self.tg_receiver
@@ -467,6 +476,8 @@ class PortalTelegram(BasePortal, ABC):
                                "bridge.deduplication.cache_queue_length in the config.")
                 return
 
+        self.log.trace("Handling Telegram message %s", evt)
+
         if sender and not sender.displayname:
             self.log.debug(f"Telegram user {sender.tgid} sent a message, but doesn't have a "
                            "displayname, updating info...")
@@ -500,7 +511,7 @@ class PortalTelegram(BasePortal, ABC):
             }[type(media)](source, intent, evt,
                            relates_to=formatter.telegram_reply_to_matrix(evt, source))
         else:
-            self.log.debug("Unhandled Telegram message: %s", evt)
+            self.log.debug("Unhandled Telegram message %d", evt.id)
             return
 
         if not event_id:
@@ -517,7 +528,7 @@ class PortalTelegram(BasePortal, ABC):
             await intent.redact(self.mxid, event_id)
             return
 
-        self.log.debug("Handled Telegram message: %s", evt)
+        self.log.debug("Handled telegram message %d -> %s", evt.id, event_id)
         try:
             DBMessage(tgid=TelegramID(evt.id), mx_room=self.mxid, mxid=event_id,
                       tg_space=tg_space, edit_index=0).insert()
@@ -572,7 +583,7 @@ class PortalTelegram(BasePortal, ABC):
             # TODO handle game score
             pass
         else:
-            self.log.debug("Unhandled Telegram action in %s: %s", self.title, action)
+            self.log.trace("Unhandled Telegram action in %s: %s", self.title, action)
 
     async def set_telegram_admin(self, user_id: TelegramID) -> None:
         puppet = p.Puppet.get(user_id)

mautrix_telegram/util/color_log.py

@@ -13,7 +13,8 @@
 #
 # You should have received a copy of the GNU Affero General Public License
 # along with this program.  If not, see <https://www.gnu.org/licenses/>.
-from mautrix.util.color_log import ColorFormatter as BaseColorFormatter, PREFIX, MXID_COLOR, RESET
+from mautrix.util.logging.color import (ColorFormatter as BaseColorFormatter,
+                                        PREFIX, MXID_COLOR, RESET)
 
 TELETHON_COLOR = PREFIX + "35;1m"  # magenta
 TELETHON_MODULE_COLOR = PREFIX + "35m"

mautrix_telegram/util/parallel_file_transfer.py

@@ -13,7 +13,7 @@
 #
 # You should have received a copy of the GNU Affero General Public License
 # along with this program.  If not, see <https://www.gnu.org/licenses/>.
-from typing import Optional, List, AsyncGenerator, Union, Awaitable, DefaultDict, Tuple
+from typing import Optional, List, AsyncGenerator, Union, Awaitable, DefaultDict, Tuple, cast
 from collections import defaultdict
 import hashlib
 import asyncio
@@ -35,6 +35,7 @@ from telethon import utils, helpers
 
 from mautrix.appservice import IntentAPI
 from mautrix.types import ContentURI, EncryptedFile
+from mautrix.util.logging import TraceLogger
 
 from ..tgclient import MautrixTelegramClient
 from ..db import TelegramFile as DBTelegramFile
@@ -44,7 +45,7 @@ try:
 except ImportError:
     async_encrypt_attachment = None
 
-log: logging.Logger = logging.getLogger("mau.util")
+log: TraceLogger = cast(TraceLogger, logging.getLogger("mau.util"))
 
 TypeLocation = Union[Document, InputDocumentFileLocation, InputPeerPhotoFileLocation,
                      InputFileLocation, InputPhotoFileLocation]
@@ -102,7 +103,7 @@ class UploadSender:
 
     async def _next(self, data: bytes) -> None:
         self.request.bytes = data
-        log.debug(f"Sending file part {self.request.file_part}/{self.part_count}"
+        log.trace(f"Sending file part {self.request.file_part}/{self.part_count}"
                   f" with {len(data)} bytes")
         await self.sender.send(self.request)
         self.request.file_part += self.stride
@@ -236,7 +237,7 @@ class ParallelTransferrer:
                     break
                 yield data
                 part += 1
-                log.debug(f"Part {part} downloaded")
+                log.trace(f"Part {part} downloaded")
 
         log.debug("Parallel download finished, cleaning up connections")
         await self._cleanup()