From f454803ef7997541b61e3d8be30d139cfc5866e5 Mon Sep 17 00:00:00 2001 From: Tulir Asokan Date: Wed, 20 May 2020 22:40:20 +0300 Subject: [PATCH] Move private information to trace log level. Fixes #321 --- mautrix_telegram/abstract_user.py | 17 ++++++------ mautrix_telegram/commands/telegram/misc.py | 4 ++- mautrix_telegram/portal/base.py | 8 +++--- mautrix_telegram/portal/matrix.py | 4 +-- mautrix_telegram/portal/metadata.py | 4 +-- mautrix_telegram/portal/telegram.py | 27 +++++++++++++------ mautrix_telegram/util/color_log.py | 3 ++- .../util/parallel_file_transfer.py | 9 ++++--- 8 files changed, 45 insertions(+), 31 deletions(-) diff --git a/mautrix_telegram/abstract_user.py b/mautrix_telegram/abstract_user.py index e04582e0..7f6b2677 100644 --- a/mautrix_telegram/abstract_user.py +++ b/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( - f"Unexpected message type in User#get_message_details: {type(update)}") + self.log.warning(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, - portal.tgid_log, + self.log.trace(f"Ignoring action %s to %s by %d", update.action, 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) diff --git a/mautrix_telegram/commands/telegram/misc.py b/mautrix_telegram/commands/telegram/misc.py index 06d66ebe..b0d525e4 100644 --- a/mautrix_telegram/commands/telegram/misc.py +++ b/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 diff --git a/mautrix_telegram/portal/base.py b/mautrix_telegram/portal/base.py index d5520d71..722d77ef 100644 --- a/mautrix_telegram/portal/base.py +++ b/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}. " - "Failing...") + self.log.warning(f"Could not find entity with bot {user.tgid}. Failing...") raise self.log.warning(f"Could not find entity with user {user.tgid}. " "falling back to get_dialogs.") diff --git a/mautrix_telegram/portal/matrix.py b/mautrix_telegram/portal/matrix.py index afd25b6c..6ba7ab61 100644 --- a/mautrix_telegram/portal/matrix.py +++ b/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: diff --git a/mautrix_telegram/portal/metadata.py b/mautrix_telegram/portal/metadata.py index 1ca971f8..017a1291 100644 --- a/mautrix_telegram/portal/metadata.py +++ b/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 diff --git a/mautrix_telegram/portal/telegram.py b/mautrix_telegram/portal/telegram.py index b39ccd88..e649b4c8 100644 --- a/mautrix_telegram/portal/telegram.py +++ b/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, - relates_to: dict = None) -> Awaitable[EventID]: + def handle_telegram_location(self, source: 'AbstractUser', intent: IntentAPI, evt: Message, + 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) diff --git a/mautrix_telegram/util/color_log.py b/mautrix_telegram/util/color_log.py index 860720c2..397cf9cc 100644 --- a/mautrix_telegram/util/color_log.py +++ b/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 . -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" diff --git a/mautrix_telegram/util/parallel_file_transfer.py b/mautrix_telegram/util/parallel_file_transfer.py index 5d316e48..0bda98fd 100644 --- a/mautrix_telegram/util/parallel_file_transfer.py +++ b/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 . -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()