diff --git a/telegram/_bot.py b/telegram/_bot.py index 902443edc..79afc1a11 100644 --- a/telegram/_bot.py +++ b/telegram/_bot.py @@ -22,7 +22,6 @@ import asyncio import contextlib import copy import functools -import logging import pickle from datetime import datetime from types import TracebackType @@ -94,6 +93,7 @@ from telegram._userprofilephotos import UserProfilePhotos from telegram._utils.argumentparsing import parse_sequence_arg from telegram._utils.defaultvalue import DEFAULT_NONE, DefaultValue from telegram._utils.files import is_local_file, parse_file_input +from telegram._utils.logging import get_logger from telegram._utils.types import DVInput, FileInput, JSONDict, ODVInput, ReplyMarkup from telegram._utils.warnings import warn from telegram._utils.warnings_transition import warn_about_thumb_return_thumbnail @@ -206,6 +206,10 @@ class Bot(TelegramObject, AsyncContextManager["Bot"]): """ + # This is a class variable since we want to override the logger name in ExtBot + # without having to change all places where this is used + _LOGGER = get_logger(__name__) + __slots__ = ( "_token", "_base_url", @@ -213,7 +217,6 @@ class Bot(TelegramObject, AsyncContextManager["Bot"]): "_private_key", "_bot_user", "_request", - "_logger", "_initialized", "_local_mode", ) @@ -239,7 +242,6 @@ class Bot(TelegramObject, AsyncContextManager["Bot"]): self._local_mode: bool = local_mode self._bot_user: Optional[User] = None self._private_key: Optional[bytes] = None - self._logger = logging.getLogger(__name__) self._initialized = False self._request: Tuple[BaseRequest, BaseRequest] = ( @@ -361,14 +363,13 @@ class Bot(TelegramObject, AsyncContextManager["Bot"]): # TODO: After https://youtrack.jetbrains.com/issue/PY-50952 is fixed, we can revisit this and # consider adding Paramspec from typing_extensions to properly fix this. Currently a workaround def _log(func: Any): # type: ignore[no-untyped-def] # skipcq: PY-D0003 - logger = logging.getLogger(func.__module__) - @functools.wraps(func) - async def decorator(*args, **kwargs): # type: ignore[no-untyped-def] - logger.debug("Entering: %s", func.__name__) - result = await func(*args, **kwargs) # skipcq: PYL-E1102 - logger.debug(result) - logger.debug("Exiting: %s", func.__name__) + async def decorator(self, *args, **kwargs): # type: ignore[no-untyped-def] + # pylint: disable=protected-access + self._LOGGER.debug("Entering: %s", func.__name__) + result = await func(self, *args, **kwargs) # skipcq: PYL-E1102 + self._LOGGER.debug(result) + self._LOGGER.debug("Exiting: %s", func.__name__) return result return decorator @@ -569,7 +570,7 @@ class Bot(TelegramObject, AsyncContextManager["Bot"]): .. versionadded:: 20.0 """ if self._initialized: - self._logger.debug("This Bot is already initialized.") + self._LOGGER.debug("This Bot is already initialized.") return await asyncio.gather(self._request[0].initialize(), self._request[1].initialize()) @@ -590,7 +591,7 @@ class Bot(TelegramObject, AsyncContextManager["Bot"]): .. versionadded:: 20.0 """ if not self._initialized: - self._logger.debug("This Bot is already shut down. Returning.") + self._LOGGER.debug("This Bot is already shut down. Returning.") return await asyncio.gather(self._request[0].shutdown(), self._request[1].shutdown()) @@ -3614,9 +3615,9 @@ class Bot(TelegramObject, AsyncContextManager["Bot"]): ) if result: - self._logger.debug("Getting updates: %s", [u["update_id"] for u in result]) + self._LOGGER.debug("Getting updates: %s", [u["update_id"] for u in result]) else: - self._logger.debug("No new updates found.") + self._LOGGER.debug("No new updates found.") return Update.de_list(result, self) diff --git a/telegram/_files/inputfile.py b/telegram/_files/inputfile.py index 3a0df5546..8cc8b8ba9 100644 --- a/telegram/_files/inputfile.py +++ b/telegram/_files/inputfile.py @@ -18,7 +18,6 @@ # along with this program. If not, see [http://www.gnu.org/licenses/]. """This module contains an object that represents a Telegram InputFile.""" -import logging import mimetypes from typing import IO, Optional, Union from uuid import uuid4 @@ -27,7 +26,6 @@ from telegram._utils.files import load_file from telegram._utils.types import FieldTuple _DEFAULT_MIME_TYPE = "application/octet-stream" -logger = logging.getLogger(__name__) class InputFile: diff --git a/telegram/_utils/logging.py b/telegram/_utils/logging.py new file mode 100644 index 000000000..e6a792744 --- /dev/null +++ b/telegram/_utils/logging.py @@ -0,0 +1,49 @@ +#!/usr/bin/env python +# +# A library that provides a Python interface to the Telegram Bot API +# Copyright (C) 2015-2023 +# Leandro Toledo de Souza +# +# This program is free software: you can redistribute it and/or modify +# it under the terms of the GNU Lesser Public License as published by +# the Free Software Foundation, either version 3 of the License, or +# (at your option) any later version. +# +# This program is distributed in the hope that it will be useful, +# but WITHOUT ANY WARRANTY; without even the implied warranty of +# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +# GNU Lesser Public License for more details. +# +# You should have received a copy of the GNU Lesser Public License +# along with this program. If not, see [http://www.gnu.org/licenses/]. +"""This module contains helper functions related to logging. + +Warning: + Contents of this module are intended to be used internally by the library and *not* by the + user. Changes to this module are not considered breaking changes and may not be documented in + the changelog. +""" +import logging + + +def get_logger(file_name: str, class_name: str = None) -> logging.Logger: + """Returns a logger with an appropriate name. + Use as follows:: + + logger = get_logger(__name__) + + If for example `__name__` is `telegram.ext._updater`, the logger will be named + `telegram.ext.Updater`. If `class_name` is passed, this will result in + `telegram.ext.`. Useful e.g. for CamelCase class names. + + If the file name points to a utils module, the logger name will simply be `telegram(.ext)`. + + Returns: + :class:`logging.Logger`: The logger. + """ + parts = file_name.split("_") + if parts[1].startswith("utils") and class_name is None: + name = parts[0].rstrip(".") + else: + name = f"{parts[0]}{class_name or parts[1].capitalize()}" + return logging.getLogger(name) diff --git a/telegram/ext/_aioratelimiter.py b/telegram/ext/_aioratelimiter.py index c948075ac..b211ed8f7 100644 --- a/telegram/ext/_aioratelimiter.py +++ b/telegram/ext/_aioratelimiter.py @@ -21,7 +21,6 @@ library. """ import asyncio import contextlib -import logging import sys from typing import Any, AsyncIterator, Callable, Coroutine, Dict, List, Optional, Union @@ -32,6 +31,7 @@ try: except ImportError: AIO_LIMITER_AVAILABLE = False +from telegram._utils.logging import get_logger from telegram._utils.types import JSONDict from telegram.error import RetryAfter from telegram.ext._baseratelimiter import BaseRateLimiter @@ -48,6 +48,9 @@ else: yield None +_LOGGER = get_logger(__name__, class_name="AIORateLimiter") + + class AIORateLimiter(BaseRateLimiter[int]): """ Implementation of :class:`~telegram.ext.BaseRateLimiter` using the library @@ -118,7 +121,6 @@ class AIORateLimiter(BaseRateLimiter[int]): "_group_limiters", "_group_max_rate", "_group_time_period", - "_logger", "_max_retries", "_retry_after_event", ) @@ -152,7 +154,6 @@ class AIORateLimiter(BaseRateLimiter[int]): self._group_limiters: Dict[Union[str, int], AsyncLimiter] = {} self._max_retries: int = max_retries - self._logger = logging.getLogger(__name__) self._retry_after_event = asyncio.Event() self._retry_after_event.set() @@ -247,13 +248,13 @@ class AIORateLimiter(BaseRateLimiter[int]): ) except RetryAfter as exc: if i == max_retries: - self._logger.exception( + _LOGGER.exception( "Rate limit hit after maximum of %d retries", max_retries, exc_info=exc ) raise exc sleep = exc.retry_after + 0.1 - self._logger.info("Rate limit hit. Retrying after %f seconds", sleep) + _LOGGER.info("Rate limit hit. Retrying after %f seconds", sleep) # Make sure we don't allow other requests to be processed self._retry_after_event.clear() await asyncio.sleep(sleep) diff --git a/telegram/ext/_application.py b/telegram/ext/_application.py index 4952bd804..e311e92a0 100644 --- a/telegram/ext/_application.py +++ b/telegram/ext/_application.py @@ -21,7 +21,6 @@ import asyncio import contextlib import inspect import itertools -import logging import platform import signal from collections import defaultdict @@ -53,6 +52,7 @@ from typing import ( from telegram._update import Update from telegram._utils.defaultvalue import DEFAULT_NONE, DEFAULT_TRUE, DefaultValue +from telegram._utils.logging import get_logger from telegram._utils.types import SCT, DVType, ODVInput from telegram._utils.warnings import warn from telegram.error import TelegramError @@ -77,7 +77,7 @@ _AppType = TypeVar("_AppType", bound="Application") # pylint: disable=invalid-n _STOP_SIGNAL = object() _DEFAULT_0 = DefaultValue(0) -_logger = logging.getLogger(__name__) +_LOGGER = get_logger(__name__) class ApplicationHandlerStop(Exception): @@ -393,7 +393,7 @@ class Application(Generic[BT, CCT, UD, CD, BD, JQ], AsyncContextManager["Applica :meth:`shutdown` """ if self._initialized: - _logger.debug("This Application is already initialized.") + _LOGGER.debug("This Application is already initialized.") return await self.bot.initialize() @@ -443,7 +443,7 @@ class Application(Generic[BT, CCT, UD, CD, BD, JQ], AsyncContextManager["Applica raise RuntimeError("This Application is still running!") if not self._initialized: - _logger.debug("This Application is already shut down. Returning.") + _LOGGER.debug("This Application is already shut down. Returning.") return await self.bot.shutdown() @@ -451,10 +451,10 @@ class Application(Generic[BT, CCT, UD, CD, BD, JQ], AsyncContextManager["Applica await self.updater.shutdown() if self.persistence: - _logger.debug("Updating & flushing persistence before shutdown") + _LOGGER.debug("Updating & flushing persistence before shutdown") await self.update_persistence() await self.persistence.flush() - _logger.debug("Updated and flushed persistence") + _LOGGER.debug("Updated and flushed persistence") self._initialized = False @@ -557,18 +557,18 @@ class Application(Generic[BT, CCT, UD, CD, BD, JQ], AsyncContextManager["Applica # TODO: Add this once we drop py3.7 # name=f'Application:{self.bot.id}:persistence_updater' ) - _logger.debug("Loop for updating persistence started") + _LOGGER.debug("Loop for updating persistence started") if self._job_queue: await self._job_queue.start() # type: ignore[union-attr] - _logger.debug("JobQueue started") + _LOGGER.debug("JobQueue started") self.__update_fetcher_task = asyncio.create_task( self._update_fetcher(), # TODO: Add this once we drop py3.7 # name=f'Application:{self.bot.id}:update_fetcher' ) - _logger.info("Application started") + _LOGGER.info("Application started") except Exception as exc: self._running = False @@ -601,32 +601,32 @@ class Application(Generic[BT, CCT, UD, CD, BD, JQ], AsyncContextManager["Applica raise RuntimeError("This Application is not running!") self._running = False - _logger.info("Application is stopping. This might take a moment.") + _LOGGER.info("Application is stopping. This might take a moment.") # Stop listening for new updates and handle all pending ones await self.update_queue.put(_STOP_SIGNAL) - _logger.debug("Waiting for update_queue to join") + _LOGGER.debug("Waiting for update_queue to join") await self.update_queue.join() if self.__update_fetcher_task: await self.__update_fetcher_task - _logger.debug("Application stopped fetching of updates.") + _LOGGER.debug("Application stopped fetching of updates.") if self._job_queue: - _logger.debug("Waiting for running jobs to finish") + _LOGGER.debug("Waiting for running jobs to finish") await self._job_queue.stop(wait=True) # type: ignore[union-attr] - _logger.debug("JobQueue stopped") + _LOGGER.debug("JobQueue stopped") - _logger.debug("Waiting for `create_task` calls to be processed") + _LOGGER.debug("Waiting for `create_task` calls to be processed") await asyncio.gather(*self.__create_task_tasks, return_exceptions=True) # Make sure that this is the *last* step of stopping the application! if self.persistence and self.__update_persistence_task: - _logger.debug("Waiting for persistence loop to finish") + _LOGGER.debug("Waiting for persistence loop to finish") self.__update_persistence_event.set() await self.__update_persistence_task self.__update_persistence_event.clear() - _logger.info("Application.stop() complete") + _LOGGER.info("Application.stop() complete") def run_polling( self, @@ -1026,7 +1026,7 @@ class Application(Generic[BT, CCT, UD, CD, BD, JQ], AsyncContextManager["Applica # Avoid infinite recursion of error handlers. elif is_error_handler: - _logger.exception( + _LOGGER.exception( "An error was raised and an uncaught error was raised while " "handling the error with an error_handler.", exc_info=exception, @@ -1049,7 +1049,7 @@ class Application(Generic[BT, CCT, UD, CD, BD, JQ], AsyncContextManager["Applica update = await self.update_queue.get() if update is _STOP_SIGNAL: - _logger.debug("Dropping pending updates") + _LOGGER.debug("Dropping pending updates") while not self.update_queue.empty(): self.update_queue.task_done() @@ -1057,7 +1057,7 @@ class Application(Generic[BT, CCT, UD, CD, BD, JQ], AsyncContextManager["Applica self.update_queue.task_done() return - _logger.debug("Processing update %s", update) + _LOGGER.debug("Processing update %s", update) if self._concurrent_updates: # We don't await the below because it has to be run concurrently @@ -1117,13 +1117,13 @@ class Application(Generic[BT, CCT, UD, CD, BD, JQ], AsyncContextManager["Applica # Stop processing with any other handler. except ApplicationHandlerStop: - _logger.debug("Stopping further handlers due to ApplicationHandlerStop") + _LOGGER.debug("Stopping further handlers due to ApplicationHandlerStop") break # Dispatch any error. except Exception as exc: if await self.process_error(update=update, error=exc): - _logger.debug("Error handler stopped further handlers.") + _LOGGER.debug("Error handler stopped further handlers.") break if any_blocking: @@ -1451,7 +1451,7 @@ class Application(Generic[BT, CCT, UD, CD, BD, JQ], AsyncContextManager["Applica if not self.persistence: return - _logger.debug("Starting next run of updating the persistence.") + _LOGGER.debug("Starting next run of updating the persistence.") coroutines: Set[Coroutine] = set() @@ -1519,13 +1519,13 @@ class Application(Generic[BT, CCT, UD, CD, BD, JQ], AsyncContextManager["Applica # *all* tasks will be done. if not new_state.done(): if self.running: - _logger.debug( + _LOGGER.debug( "A ConversationHandlers state was not yet resolved. Updating the " "persistence with the current state. Will check again on next run of " "Application.update_persistence." ) else: - _logger.warning( + _LOGGER.warning( "A ConversationHandlers state was not yet resolved. Updating the " "persistence with the current state." ) @@ -1545,7 +1545,7 @@ class Application(Generic[BT, CCT, UD, CD, BD, JQ], AsyncContextManager["Applica ) results = await asyncio.gather(*coroutines, return_exceptions=True) - _logger.debug("Finished updating persistence.") + _LOGGER.debug("Finished updating persistence.") # dispatch any errors await asyncio.gather( @@ -1586,7 +1586,7 @@ class Application(Generic[BT, CCT, UD, CD, BD, JQ], AsyncContextManager["Applica :meth:`process_error`. Defaults to :obj:`True`. """ if callback in self.error_handlers: - _logger.warning("The callback is already registered as an error handler. Ignoring.") + _LOGGER.warning("The callback is already registered as an error handler. Ignoring.") return self.error_handlers[callback] = block @@ -1663,12 +1663,12 @@ class Application(Generic[BT, CCT, UD, CD, BD, JQ], AsyncContextManager["Applica except ApplicationHandlerStop: return True except Exception as exc: - _logger.exception( + _LOGGER.exception( "An error was raised and an uncaught error was raised while " "handling the error with an error_handler.", exc_info=exc, ) return False - _logger.exception("No error handlers are registered, logging exception.", exc_info=error) + _LOGGER.exception("No error handlers are registered, logging exception.", exc_info=error) return False diff --git a/telegram/ext/_conversationhandler.py b/telegram/ext/_conversationhandler.py index a7ff749ce..ce979fe58 100644 --- a/telegram/ext/_conversationhandler.py +++ b/telegram/ext/_conversationhandler.py @@ -19,7 +19,6 @@ """This module contains the ConversationHandler.""" import asyncio import datetime -import logging from dataclasses import dataclass from typing import ( TYPE_CHECKING, @@ -38,6 +37,7 @@ from typing import ( from telegram import Update from telegram._utils.defaultvalue import DEFAULT_TRUE, DefaultValue +from telegram._utils.logging import get_logger from telegram._utils.types import DVType from telegram._utils.warnings import warn from telegram.ext._application import ApplicationHandlerStop @@ -56,7 +56,7 @@ if TYPE_CHECKING: from telegram.ext import Application, Job, JobQueue _CheckUpdateType = Tuple[object, ConversationKey, BaseHandler[Update, CCT], object] -_logger = logging.getLogger(__name__) +_LOGGER = get_logger(__name__, class_name="ConversationHandler") @dataclass @@ -102,7 +102,7 @@ class PendingState: exc = self.task.exception() if exc: - _logger.exception( + _LOGGER.exception( "Task function raised exception. Falling back to old state %s", self.old_state, ) @@ -649,7 +649,7 @@ class ConversationHandler(BaseHandler[Update, CCT]): try: effective_new_state = await new_state except Exception as exc: - _logger.debug( + _LOGGER.debug( "Non-blocking handler callback raised exception. Not scheduling conversation " "timeout.", exc_info=exc, @@ -684,7 +684,7 @@ class ConversationHandler(BaseHandler[Update, CCT]): data=_ConversationTimeoutContext(conversation_key, update, application, context), ) except Exception as exc: - _logger.exception("Failed to schedule timeout.", exc_info=exc) + _LOGGER.exception("Failed to schedule timeout.", exc_info=exc) # pylint: disable=too-many-return-statements def check_update(self, update: object) -> Optional[_CheckUpdateType[CCT]]: @@ -719,7 +719,7 @@ class ConversationHandler(BaseHandler[Update, CCT]): # Resolve futures if isinstance(state, PendingState): - _logger.debug("Waiting for asyncio Task to finish ...") + _LOGGER.debug("Waiting for asyncio Task to finish ...") # check if future is finished or not if state.done(): @@ -741,7 +741,7 @@ class ConversationHandler(BaseHandler[Update, CCT]): return self.WAITING, key, handler_, check return None - _logger.debug("Selecting conversation %s with state %s", str(key), str(state)) + _LOGGER.debug("Selecting conversation %s with state %s", str(key), str(state)) handler: Optional[BaseHandler] = None @@ -905,7 +905,7 @@ class ConversationHandler(BaseHandler[Update, CCT]): job = cast("Job", context.job) ctxt = cast(_ConversationTimeoutContext, job.data) - _logger.debug( + _LOGGER.debug( "Conversation timeout was triggered for conversation %s!", ctxt.conversation_key ) diff --git a/telegram/ext/_extbot.py b/telegram/ext/_extbot.py index fb87e49a8..e8f02cb34 100644 --- a/telegram/ext/_extbot.py +++ b/telegram/ext/_extbot.py @@ -85,6 +85,7 @@ from telegram import ( ) from telegram._utils.datetime import to_timestamp from telegram._utils.defaultvalue import DEFAULT_NONE, DefaultValue +from telegram._utils.logging import get_logger from telegram._utils.types import DVInput, FileInput, JSONDict, ODVInput, ReplyMarkup from telegram._utils.warnings import warn from telegram.ext._callbackdatacache import CallbackDataCache @@ -156,6 +157,8 @@ class ExtBot(Bot, Generic[RLARGS]): __slots__ = ("_callback_data_cache", "_defaults", "_rate_limiter") + _LOGGER = get_logger(__name__, class_name="ExtBot") + # using object() would be a tiny bit safer, but a string plays better with the typing setup __RL_KEY = uuid4().hex @@ -324,7 +327,7 @@ class ExtBot(Bot, Generic[RLARGS]): "connect_timeout": connect_timeout, "pool_timeout": pool_timeout, } - self._logger.debug( + self._LOGGER.debug( "Passing request through rate limiter of type %s with rate_limit_args %s", type(self.rate_limiter), rate_limit_args, diff --git a/telegram/ext/_updater.py b/telegram/ext/_updater.py index 73ca65c3f..1318e6c7b 100644 --- a/telegram/ext/_updater.py +++ b/telegram/ext/_updater.py @@ -19,7 +19,6 @@ """This module contains the class Updater, which tries to make creating Telegram bots intuitive.""" import asyncio import contextlib -import logging import ssl from pathlib import Path from types import TracebackType @@ -36,6 +35,7 @@ from typing import ( ) from telegram._utils.defaultvalue import DEFAULT_NONE +from telegram._utils.logging import get_logger from telegram._utils.types import ODVInput from telegram.error import InvalidToken, RetryAfter, TelegramError, TimedOut @@ -51,6 +51,7 @@ if TYPE_CHECKING: _UpdaterType = TypeVar("_UpdaterType", bound="Updater") # pylint: disable=invalid-name +_LOGGER = get_logger(__name__) class Updater(AsyncContextManager["Updater"]): @@ -97,7 +98,6 @@ class Updater(AsyncContextManager["Updater"]): __slots__ = ( "bot", - "_logger", "update_queue", "_last_update_id", "_running", @@ -121,7 +121,6 @@ class Updater(AsyncContextManager["Updater"]): self._httpd: Optional[WebhookServer] = None self.__lock = asyncio.Lock() self.__polling_task: Optional[asyncio.Task] = None - self._logger = logging.getLogger(__name__) @property def running(self) -> bool: @@ -135,7 +134,7 @@ class Updater(AsyncContextManager["Updater"]): :meth:`shutdown` """ if self._initialized: - self._logger.debug("This Updater is already initialized.") + _LOGGER.debug("This Updater is already initialized.") return await self.bot.initialize() @@ -155,12 +154,12 @@ class Updater(AsyncContextManager["Updater"]): raise RuntimeError("This Updater is still running!") if not self._initialized: - self._logger.debug("This Updater is already shut down. Returning.") + _LOGGER.debug("This Updater is already shut down. Returning.") return await self.bot.shutdown() self._initialized = False - self._logger.debug("Shut down of Updater complete") + _LOGGER.debug("Shut down of Updater complete") async def __aenter__(self: _UpdaterType) -> _UpdaterType: """Simple context manager which initializes the Updater.""" @@ -279,9 +278,9 @@ class Updater(AsyncContextManager["Updater"]): error_callback=error_callback, ) - self._logger.debug("Waiting for polling to start") + _LOGGER.debug("Waiting for polling to start") await polling_ready.wait() - self._logger.debug("Polling updates from Telegram started") + _LOGGER.debug("Polling updates from Telegram started") return self.update_queue except Exception as exc: @@ -302,7 +301,7 @@ class Updater(AsyncContextManager["Updater"]): ready: asyncio.Event, error_callback: Optional[Callable[[TelegramError], None]], ) -> None: - self._logger.debug("Updater started (polling)") + _LOGGER.debug("Updater started (polling)") # the bootstrapping phase does two things: # 1) make sure there is no webhook set @@ -314,7 +313,7 @@ class Updater(AsyncContextManager["Updater"]): allowed_updates=None, ) - self._logger.debug("Bootstrap done") + _LOGGER.debug("Bootstrap done") async def polling_action_cb() -> bool: try: @@ -336,7 +335,7 @@ class Updater(AsyncContextManager["Updater"]): raise exc except Exception as exc: # Other exceptions should not. Let's log them for now. - self._logger.critical( + _LOGGER.critical( "Something went wrong processing the data received from Telegram. " "Received data was *not* processed!", exc_info=exc, @@ -345,9 +344,9 @@ class Updater(AsyncContextManager["Updater"]): if updates: if not self.running: - self._logger.critical( - "Updater stopped unexpectedly. Pulled updates will be ignored and again " - "on restart." + _LOGGER.critical( + "Updater stopped unexpectedly. Pulled updates will be ignored and pulled " + "again on restart." ) else: for update in updates: @@ -357,7 +356,7 @@ class Updater(AsyncContextManager["Updater"]): return True # Keep fetching updates & don't quit. Polls with poll_interval. def default_error_callback(exc: TelegramError) -> None: - self._logger.exception("Exception happened while polling for updates.", exc_info=exc) + _LOGGER.exception("Exception happened while polling for updates.", exc_info=exc) # Start task that runs in background, pulls # updates from Telegram and inserts them in the update queue of the @@ -496,9 +495,9 @@ class Updater(AsyncContextManager["Updater"]): secret_token=secret_token, ) - self._logger.debug("Waiting for webhook server to start") + _LOGGER.debug("Waiting for webhook server to start") await webhook_ready.wait() - self._logger.debug("Webhook server started") + _LOGGER.debug("Webhook server started") except Exception as exc: self._running = False raise exc @@ -522,7 +521,7 @@ class Updater(AsyncContextManager["Updater"]): max_connections: int = 40, secret_token: str = None, ) -> None: - self._logger.debug("Updater thread started (webhook)") + _LOGGER.debug("Updater thread started (webhook)") if not url_path.startswith("/"): url_path = f"/{url_path}" @@ -600,7 +599,7 @@ class Updater(AsyncContextManager["Updater"]): `action_cb`. """ - self._logger.debug("Start network loop retry %s", description) + _LOGGER.debug("Start network loop retry %s", description) cur_interval = interval while self.running: try: @@ -608,17 +607,17 @@ class Updater(AsyncContextManager["Updater"]): if not await action_cb(): break except RetryAfter as exc: - self._logger.info("%s", exc) + _LOGGER.info("%s", exc) cur_interval = 0.5 + exc.retry_after except TimedOut as toe: - self._logger.debug("Timed out %s: %s", description, toe) + _LOGGER.debug("Timed out %s: %s", description, toe) # If failure is due to timeout, we should retry asap. cur_interval = 0 except InvalidToken as pex: - self._logger.error("Invalid token; aborting") + _LOGGER.error("Invalid token; aborting") raise pex except TelegramError as telegram_exc: - self._logger.error("Error while %s: %s", description, telegram_exc) + _LOGGER.error("Error while %s: %s", description, telegram_exc) on_err_cb(telegram_exc) # increase waiting times on subsequent errors up to 30secs @@ -630,7 +629,7 @@ class Updater(AsyncContextManager["Updater"]): await asyncio.sleep(cur_interval) except asyncio.CancelledError: - self._logger.debug("Network loop retry %s was cancelled", description) + _LOGGER.debug("Network loop retry %s was cancelled", description) break async def _bootstrap( @@ -652,16 +651,16 @@ class Updater(AsyncContextManager["Updater"]): retries = 0 async def bootstrap_del_webhook() -> bool: - self._logger.debug("Deleting webhook") + _LOGGER.debug("Deleting webhook") if drop_pending_updates: - self._logger.debug("Dropping pending updates from Telegram server") + _LOGGER.debug("Dropping pending updates from Telegram server") await self.bot.delete_webhook(drop_pending_updates=drop_pending_updates) return False async def bootstrap_set_webhook() -> bool: - self._logger.debug("Setting webhook") + _LOGGER.debug("Setting webhook") if drop_pending_updates: - self._logger.debug("Dropping pending updates from Telegram server") + _LOGGER.debug("Dropping pending updates from Telegram server") await self.bot.set_webhook( url=webhook_url, certificate=cert, @@ -680,11 +679,11 @@ class Updater(AsyncContextManager["Updater"]): if not isinstance(exc, InvalidToken) and (max_retries < 0 or retries < max_retries): retries += 1 - self._logger.warning( + _LOGGER.warning( "Failed bootstrap phase; try=%s max_retries=%s", retries, max_retries ) else: - self._logger.error("Failed bootstrap phase after %s retries (%s)", retries, exc) + _LOGGER.error("Failed bootstrap phase after %s retries (%s)", retries, exc) raise exc # Dropping pending updates from TG can be efficiently done with the drop_pending_updates @@ -725,26 +724,26 @@ class Updater(AsyncContextManager["Updater"]): if not self.running: raise RuntimeError("This Updater is not running!") - self._logger.debug("Stopping Updater") + _LOGGER.debug("Stopping Updater") self._running = False await self._stop_httpd() await self._stop_polling() - self._logger.debug("Updater.stop() is complete") + _LOGGER.debug("Updater.stop() is complete") async def _stop_httpd(self) -> None: """Stops the Webhook server by calling ``WebhookServer.shutdown()``""" if self._httpd: - self._logger.debug("Waiting for current webhook connection to be closed.") + _LOGGER.debug("Waiting for current webhook connection to be closed.") await self._httpd.shutdown() self._httpd = None async def _stop_polling(self) -> None: """Stops the polling task by awaiting it.""" if self.__polling_task: - self._logger.debug("Waiting background polling task to finish up.") + _LOGGER.debug("Waiting background polling task to finish up.") self.__polling_task.cancel() with contextlib.suppress(asyncio.CancelledError): diff --git a/telegram/ext/_utils/stack.py b/telegram/ext/_utils/stack.py index e7d91d230..a8fb3c3dd 100644 --- a/telegram/ext/_utils/stack.py +++ b/telegram/ext/_utils/stack.py @@ -25,12 +25,13 @@ Warning: user. Changes to this module are not considered breaking changes and may not be documented in the changelog. """ -import logging from pathlib import Path from types import FrameType from typing import Optional -_logger = logging.getLogger(__name__) +from telegram._utils.logging import get_logger + +_LOGGER = get_logger(__name__) def was_called_by(frame: Optional[FrameType], caller: Path) -> bool: @@ -57,7 +58,7 @@ def was_called_by(frame: Optional[FrameType], caller: Path) -> bool: try: return _was_called_by(frame, caller) except Exception as exc: - _logger.debug( + _LOGGER.debug( "Failed to check if frame was called by `caller`. Assuming that it was not.", exc_info=exc, ) diff --git a/telegram/ext/_utils/webhookhandler.py b/telegram/ext/_utils/webhookhandler.py index 364364633..9097ffb2d 100644 --- a/telegram/ext/_utils/webhookhandler.py +++ b/telegram/ext/_utils/webhookhandler.py @@ -19,7 +19,6 @@ # pylint: disable=missing-module-docstring import asyncio import json -import logging from http import HTTPStatus from ssl import SSLContext from types import TracebackType @@ -31,11 +30,15 @@ import tornado.web from tornado.httpserver import HTTPServer from telegram import Update +from telegram._utils.logging import get_logger from telegram.ext._extbot import ExtBot if TYPE_CHECKING: from telegram import Bot +# This module is not visible to users, so we log as Updater +_LOGGER = get_logger(__name__, class_name="Updater") + class WebhookServer: """Thin wrapper around ``tornado.httpserver.HTTPServer``.""" @@ -44,7 +47,6 @@ class WebhookServer: "_http_server", "listen", "port", - "_logger", "is_running", "_server_lock", "_shutdown_lock", @@ -56,7 +58,6 @@ class WebhookServer: self._http_server = HTTPServer(webhook_app, ssl_options=ssl_ctx) self.listen = listen self.port = port - self._logger = logging.getLogger(__name__) self.is_running = False self._server_lock = asyncio.Lock() self._shutdown_lock = asyncio.Lock() @@ -69,17 +70,17 @@ class WebhookServer: if ready is not None: ready.set() - self._logger.debug("Webhook Server started.") + _LOGGER.debug("Webhook Server started.") async def shutdown(self) -> None: async with self._shutdown_lock: if not self.is_running: - self._logger.debug("Webhook Server is already shut down. Returning") + _LOGGER.debug("Webhook Server is already shut down. Returning") return self.is_running = False self._http_server.stop() await self._http_server.close_all_connections() - self._logger.debug("Webhook Server stopped") + _LOGGER.debug("Webhook Server stopped") class WebhookAppClass(tornado.web.Application): @@ -104,7 +105,7 @@ class WebhookAppClass(tornado.web.Application): class TelegramHandler(tornado.web.RequestHandler): """BaseHandler that processes incoming requests from Telegram""" - __slots__ = ("bot", "update_queue", "_logger", "secret_token") + __slots__ = ("bot", "update_queue", "secret_token") SUPPORTED_METHODS = ("POST",) # type: ignore[assignment] @@ -113,10 +114,9 @@ class TelegramHandler(tornado.web.RequestHandler): # pylint: disable=attribute-defined-outside-init self.bot = bot self.update_queue = update_queue # skipcq: PYL-W0201 - self._logger = logging.getLogger(__name__) # skipcq: PYL-W0201 self.secret_token = secret_token # skipcq: PYL-W0201 if secret_token: - self._logger.debug( + _LOGGER.debug( "The webhook server has a secret token, expecting it in incoming requests now" ) @@ -126,25 +126,25 @@ class TelegramHandler(tornado.web.RequestHandler): async def post(self) -> None: """Handle incoming POST request""" - self._logger.debug("Webhook triggered") + _LOGGER.debug("Webhook triggered") self._validate_post() json_string = self.request.body.decode() data = json.loads(json_string) self.set_status(HTTPStatus.OK) - self._logger.debug("Webhook received data: %s", json_string) + _LOGGER.debug("Webhook received data: %s", json_string) try: update = Update.de_json(data, self.bot) except Exception as exc: - self._logger.critical( + _LOGGER.critical( "Something went wrong processing the data received from Telegram. " "Received data was *not* processed!", exc_info=exc, ) if update: - self._logger.debug( + _LOGGER.debug( "Received Update with ID %d on Webhook", # For some reason pylint thinks update is a general TelegramObject update.update_id, # pylint: disable=no-member @@ -165,12 +165,12 @@ class TelegramHandler(tornado.web.RequestHandler): if self.secret_token is not None: token = self.request.headers.get("X-Telegram-Bot-Api-Secret-Token") if not token: - self._logger.debug("Request did not include the secret token") + _LOGGER.debug("Request did not include the secret token") raise tornado.web.HTTPError( HTTPStatus.FORBIDDEN, reason="Request did not include the secret token" ) if token != self.secret_token: - self._logger.debug("Request had the wrong secret token: %s", token) + _LOGGER.debug("Request had the wrong secret token: %s", token) raise tornado.web.HTTPError( HTTPStatus.FORBIDDEN, reason="Request had the wrong secret token" ) @@ -182,7 +182,7 @@ class TelegramHandler(tornado.web.RequestHandler): tb: Optional[TracebackType], ) -> None: """Override the default logging and instead use our custom logging.""" - self._logger.debug( + _LOGGER.debug( "%s - %s", self.request.remote_ip, "Exception in TelegramHandler", diff --git a/telegram/request/_httpxrequest.py b/telegram/request/_httpxrequest.py index 837162b41..6854e085f 100644 --- a/telegram/request/_httpxrequest.py +++ b/telegram/request/_httpxrequest.py @@ -17,12 +17,12 @@ # You should have received a copy of the GNU Lesser Public License # along with this program. If not, see [http://www.gnu.org/licenses/]. """This module contains methods to make POST and GET requests using the httpx library.""" -import logging from typing import Optional, Tuple import httpx from telegram._utils.defaultvalue import DefaultValue +from telegram._utils.logging import get_logger from telegram._utils.types import ODVInput from telegram.error import NetworkError, TimedOut from telegram.request._baserequest import BaseRequest @@ -33,7 +33,7 @@ from telegram.request._requestdata import RequestData # https://www.python-httpx.org/contributing/#development-proxy-setup (also saved on archive.org) # That also works with socks5. Just pass `--mode socks5` to mitmproxy -_logger = logging.getLogger(__name__) +_LOGGER = get_logger(__name__, "HTTPXRequest") class HTTPXRequest(BaseRequest): @@ -166,7 +166,7 @@ class HTTPXRequest(BaseRequest): async def shutdown(self) -> None: """See :meth:`BaseRequest.shutdown`.""" if self._client.is_closed: - _logger.debug("This HTTPXRequest is already shut down. Returning.") + _LOGGER.debug("This HTTPXRequest is already shut down. Returning.") return await self._client.aclose() diff --git a/tests/ext/_utils/test_stack.py b/tests/ext/_utils/test_stack.py index fc5d42ef5..13305b502 100644 --- a/tests/ext/_utils/test_stack.py +++ b/tests/ext/_utils/test_stack.py @@ -56,6 +56,7 @@ class TestStack: assert not was_called_by(inspect.currentframe(), None) assert len(caplog.records) == 1 + assert caplog.records[0].name == "telegram.ext" assert caplog.records[0].levelno == logging.DEBUG assert caplog.records[0].getMessage().startswith("Failed to check") assert caplog.records[0].exc_info[0] is RuntimeError diff --git a/tests/ext/test_application.py b/tests/ext/test_application.py index b68696e98..8ee4d09ec 100644 --- a/tests/ext/test_application.py +++ b/tests/ext/test_application.py @@ -803,6 +803,7 @@ class TestApplication: with caplog.at_level(logging.DEBUG): app.add_error_handler(self.error_handler_context) assert len(caplog.records) == 1 + assert caplog.records[-1].name == "telegram.ext.Application" assert caplog.records[-1].getMessage().startswith("The callback is already registered") async def test_error_handler_that_raises_errors(self, app, caplog): @@ -826,11 +827,11 @@ class TestApplication: assert self.count == 0 assert self.received is None assert len(caplog.records) > 0 - log_messages = (record.getMessage() for record in caplog.records) assert any( "uncaught error was raised while handling the error with an error_handler" - in message - for message in log_messages + in record.getMessage() + and record.name == "telegram.ext.Application" + for record in caplog.records ) await app.update_queue.put("1") @@ -988,6 +989,7 @@ class TestApplication: assert ( caplog.records[-1].getMessage().startswith("No error handlers are registered") ) + assert caplog.records[-1].name == "telegram.ext.Application" await app.stop() @pytest.mark.parametrize("handler_block", [True, False]) @@ -1090,6 +1092,7 @@ class TestApplication: await app.update_queue.put(1) await asyncio.sleep(0.05) assert len(caplog.records) == 1 + assert caplog.records[-1].name == "telegram.ext.Application" assert ( caplog.records[-1] .getMessage() diff --git a/tests/ext/test_basepersistence.py b/tests/ext/test_basepersistence.py index dde7f23fb..e61888dd1 100644 --- a/tests/ext/test_basepersistence.py +++ b/tests/ext/test_basepersistence.py @@ -405,7 +405,7 @@ class TestBasePersistence: assert bot.callback_data_cache is None assert papp.persistence.set_bot(bot) is None - def test_construction_with_bad_persistence(self, caplog, bot): + def test_construction_with_bad_persistence(self, bot): class MyPersistence: def __init__(self): self.store_data = PersistenceInput(False, False, False, False) @@ -1128,6 +1128,7 @@ class TestBasePersistence: assert len(caplog.records) == 6 assert test_flag == [True, True, True, True, True, True] for record in caplog.records: + assert record.name == "telegram.ext.Application" message = record.getMessage() assert message.startswith("An error was raised and an uncaught") @@ -1199,8 +1200,8 @@ class TestBasePersistence: assert not papp.persistence.updated_chat_ids assert not papp.persistence.updated_conversations - async def test_non_blocking_conversations(self, bot): - papp = build_papp(token=bot.token) + async def test_non_blocking_conversations(self, bot, caplog): + papp = build_papp(token=bot.token, update_interval=100) event = asyncio.Event() async def callback(_, __): @@ -1220,6 +1221,7 @@ class TestBasePersistence: papp.add_handler(conversation) async with papp: + await papp.start() assert papp.persistence.updated_conversations == {} await papp.process_update( @@ -1227,19 +1229,43 @@ class TestBasePersistence: ) assert papp.persistence.updated_conversations == {} - await papp.update_persistence() - await asyncio.sleep(0.01) - # Conversation should have been updated with the current state, i.e. None - assert papp.persistence.updated_conversations == {"conv": ({(1, 1): 1})} - assert papp.persistence.conversations == {"conv": {(1, 1): None}} + with caplog.at_level(logging.DEBUG): + await papp.update_persistence() + await asyncio.sleep(0.01) + # Conversation should have been updated with the current state, i.e. None + assert papp.persistence.updated_conversations == {"conv": ({(1, 1): 1})} + assert papp.persistence.conversations == {"conv": {(1, 1): None}} + + # Ensure that we warn the user about this! + found_record = None + for record in caplog.records: + message = record.getMessage() + if message.startswith("A ConversationHandlers state was not yet resolved"): + assert "Will check again on next run" in record.getMessage() + assert record.name == "telegram.ext.Application" + found_record = record + break + assert found_record is not None + + caplog.clear() papp.persistence.reset_tracking() event.set() await asyncio.sleep(0.01) - await papp.update_persistence() + with caplog.at_level(logging.DEBUG): + await papp.update_persistence() + + # Conversation should have been updated with the resolved state now and hence + # there should be no warning + assert not any( + record.getMessage().startswith("A ConversationHandlers state was not yet") + for record in caplog.records + ) assert papp.persistence.updated_conversations == {"conv": {(1, 1): 1}} assert papp.persistence.conversations == {"conv": {(1, 1): HandlerStates.STATE_1}} + await papp.stop() + async def test_non_blocking_conversations_raises_Exception(self, bot): papp = build_papp(token=bot.token) @@ -1371,6 +1397,8 @@ class TestBasePersistence: found_record = None for record in caplog.records: if record.getMessage().startswith("A ConversationHandlers state was not yet resolved"): + assert "will check again" not in record.getMessage() + assert record.name == "telegram.ext.Application" found_record = record break assert found_record is not None diff --git a/tests/ext/test_conversationhandler.py b/tests/ext/test_conversationhandler.py index 913a6a6a7..c6e3aadd7 100644 --- a/tests/ext/test_conversationhandler.py +++ b/tests/ext/test_conversationhandler.py @@ -1090,6 +1090,7 @@ class TestConversationHandler: assert len(caplog.records) == 1 assert caplog.records[0].message == "Failed to schedule timeout." + assert caplog.records[0].name == "telegram.ext.ConversationHandler" assert str(caplog.records[0].exc_info[1]) == "job error" await app.stop() @@ -1143,6 +1144,7 @@ class TestConversationHandler: assert handler.check_update(Update(0, message=message)) if test_type == "exception": assert len(caplog.records) == 1 + assert caplog.records[0].name == "telegram.ext.ConversationHandler" assert ( caplog.records[0].message == "Task function raised exception. Falling back to old state 1" @@ -1189,6 +1191,7 @@ class TestConversationHandler: # This also makes sure that we're still in the same state assert handler.check_update(Update(0, message=message)) assert len(caplog.records) == 1 + assert caplog.records[0].name == "telegram.ext.ConversationHandler" assert ( caplog.records[0].message == "Task function raised exception. Falling back to old state None" diff --git a/tests/ext/test_jobqueue.py b/tests/ext/test_jobqueue.py index 82ee293ba..355b32c66 100644 --- a/tests/ext/test_jobqueue.py +++ b/tests/ext/test_jobqueue.py @@ -557,6 +557,7 @@ class TestJobQueue: await job.run(app) assert len(caplog.records) == 1 rec = caplog.records[-1] + assert rec.name == "telegram.ext.Application" assert "No error handlers are registered" in rec.getMessage() async def test_custom_context(self, bot, job_queue): diff --git a/tests/ext/test_updater.py b/tests/ext/test_updater.py index 4eb779527..57b84e184 100644 --- a/tests/ext/test_updater.py +++ b/tests/ext/test_updater.py @@ -399,8 +399,11 @@ class TestUpdater: assert self.received == error else: assert len(caplog.records) > 0 - records = (record.getMessage() for record in caplog.records) - assert "Error while getting Updates: TestMessage" in records + assert any( + "Error while getting Updates: TestMessage" in record.getMessage() + and record.name == "telegram.ext.Updater" + for record in caplog.records + ) # Make sure that get_updates was called assert get_updates_event.is_set() @@ -418,8 +421,11 @@ class TestUpdater: assert self.received == error else: assert len(caplog.records) > 0 - records = (record.getMessage() for record in caplog.records) - assert "Error while getting Updates: TestMessage" in records + assert any( + "Error while getting Updates: TestMessage" in record.getMessage() + and record.name == "telegram.ext.Updater" + for record in caplog.records + ) await updater.stop() async def test_start_polling_unexpected_shutdown(self, updater, monkeypatch, caplog): @@ -451,8 +457,11 @@ class TestUpdater: await asyncio.sleep(0.1) assert caplog.records - records = (record.getMessage() for record in caplog.records) - assert any("Updater stopped unexpectedly." in record for record in records) + assert any( + "Updater stopped unexpectedly." in record.getMessage() + and record.name == "telegram.ext.Updater" + for record in caplog.records + ) # Make sure that the update_id offset wasn't increased assert self.message_count == 2 @@ -503,6 +512,7 @@ class TestUpdater: assert len(caplog.records) > 0 for record in caplog.records: assert record.getMessage().startswith("Something went wrong processing") + assert record.name == "telegram.ext.Updater" # Make sure that everything works fine again when receiving proper updates raise_exception = False @@ -914,6 +924,7 @@ class TestUpdater: assert len(caplog.records) == 1 assert caplog.records[-1].getMessage().startswith("Something went wrong processing") + assert caplog.records[-1].name == "telegram.ext.Updater" # Make sure that everything works fine again when receiving proper updates caplog.clear() diff --git a/tests/test_bot.py b/tests/test_bot.py index 5e14707e4..05ec6731e 100644 --- a/tests/test_bot.py +++ b/tests/test_bot.py @@ -377,10 +377,13 @@ class TestBotWithoutRequest: re.match(rf"\s*\@\_log\s*async def {bot_method_name}", source) ), f"{bot_method_name} is missing the @_log decorator" - async def test_log_decorator(self, bot: PytestExtBot, caplog): + @pytest.mark.parametrize( + ("cls", "logger_name"), [(Bot, "telegram.Bot"), (ExtBot, "telegram.ext.ExtBot")] + ) + async def test_log_decorator(self, bot: PytestExtBot, cls, logger_name, caplog): # Second argument makes sure that we ignore logs from e.g. httpx with caplog.at_level(logging.DEBUG, logger="telegram"): - await ExtBot(bot.token).get_me() + await cls(bot.token).get_me() # Only for stabilizing this test- if len(caplog.records) == 4: for idx, record in enumerate(caplog.records): @@ -390,6 +393,8 @@ class TestBotWithoutRequest: if record.getMessage().startswith("Task exception was never retrieved"): caplog.records.pop(idx) assert len(caplog.records) == 3 + + assert all(caplog.records[i].name == logger_name for i in [-1, 0]) assert caplog.records[0].getMessage().startswith("Entering: get_me") assert caplog.records[-1].getMessage().startswith("Exiting: get_me") @@ -963,7 +968,7 @@ class TestBotWithoutRequest: assert await bot.answer_inline_query(1234, results=inline_results, current_offset=0) - async def test_answer_inline_query_current_offset_callback(self, monkeypatch, bot, caplog): + async def test_answer_inline_query_current_offset_callback(self, monkeypatch, bot): # For now just test that our internals pass the correct data async def make_assertion(url, request_data: RequestData, *args, **kwargs): data = request_data.parameters