refactor: switch to loguru, add correlation ID

Author: y-young

.dockerignore

@@ -8,6 +8,7 @@
 **/.toolstarget
 **/.vs
 **/.vscode
+**/.venv
 **/*.*proj.user
 **/*.dbmdl
 **/*.jfm

nazurin/__init__.py

@@ -1,8 +1,11 @@
 from nazurin import config
+from nazurin.utils.logging import configure_logging
 
 from .bot import NazurinBot
 from .dispatcher import NazurinDispatcher
 
+configure_logging()
+
 bot = NazurinBot(token=config.TOKEN, proxy=config.PROXY)
 dp = NazurinDispatcher(bot)
 

nazurin/__main__.py

@@ -3,7 +3,6 @@
 import os
 import shutil
 import traceback
-from html import escape
 
 from aiogram.dispatcher.filters import IDFilter
 from aiogram.types import ChatActions, Message, Update
@@ -14,6 +13,7 @@
 from nazurin.utils import logger
 from nazurin.utils.decorators import Cache, chat_action
 from nazurin.utils.exceptions import NazurinError
+from nazurin.utils.helpers import format_error
 
 @dp.message_handler(commands=['start', 'help'])
 @chat_action(ChatActions.TYPING)
@@ -67,12 +67,9 @@ async def on_error(update: Update, exception: Exception):
         traceback.print_exc()
         await update.message.reply('Error: Timeout, please try again.')
     except Exception as error:  # pylint: disable=broad-except
-        logger.error('Update %s caused %s: %s', update, type(error), error)
-        traceback.print_exc()
+        logger.exception('Update {} caused {}: {}', update, type(error), error)
         if not isinstance(error, TelegramAPIError):
-            error_type = type(error).__name__
-            error_msg = escape(str(error), quote=False)
-            await update.message.reply(f'Error: ({error_type}) {error_msg}')
+            await update.message.reply(f'Error: {format_error(error)}')
 
     return True
 

nazurin/bot.py

@@ -106,7 +106,7 @@ async def update_collection(self,
         result = self.sites.match(urls)
         if not result:
             raise NazurinError('No source matched')
-        logger.info('Collection update: site=%s, match=%s', result['site'],
+        logger.info('Collection update: site={}, match={}', result['site'],
                     result['match'].groups())
 
         illust = await self.sites.handle_update(result)

nazurin/config.py

@@ -1,12 +1,7 @@
-import logging
 from os import path
 
 from environs import Env
 
-logging.basicConfig(
-    format='%(asctime)s - %(name)s.%(module)s - %(levelname)s - %(message)s',
-    level=logging.INFO)
-
 env = Env()
 # read config from .env file if exists
 env.read_env()
@@ -49,3 +44,4 @@
 # Local directory to store database and temporary files
 DATA_DIR = 'data'
 TEMP_DIR = path.join(DATA_DIR, 'temp')
+ACCESS_LOG_FORMAT = '%a "%r" %s %b "%{Referer}i" "%{User-Agent}i"'

nazurin/dispatcher.py

@@ -2,21 +2,22 @@
 from typing import List
 
 from aiogram import Dispatcher, executor
-from aiogram.types import AllowedUpdates, ContentType, Message
+from aiogram.types import AllowedUpdates, ContentType, Message, Update
 from aiogram.utils.executor import Executor
 
 from nazurin import config
 from nazurin.utils import logger
 from nazurin.utils.filters import URLFilter
 
 from .bot import NazurinBot
-from .middleware import AuthMiddleware
+from .middleware import AuthMiddleware, LoggingMiddleware
 from .server import NazurinServer
 
 class NazurinDispatcher(Dispatcher):
     def __init__(self, bot: NazurinBot):
         super().__init__(bot)
         self.middleware.setup(AuthMiddleware())
+        self.middleware.setup(LoggingMiddleware())
         self.filters_factory.bind(URLFilter,
                                   event_handlers=[self.message_handlers])
         self.server = NazurinServer(bot)
@@ -35,8 +36,13 @@ def register_message_handler(self, callback, *args, **kwargs):
                                                 *args, **kwargs)
 
     async def on_startup(self, *_args):
-        await self.bot.set_webhook(config.WEBHOOK_URL + config.TOKEN,
-                                   allowed_updates=AllowedUpdates.MESSAGE)
+        if config.ENV == 'production':
+            await self.bot.set_webhook(config.WEBHOOK_URL + config.TOKEN,
+                                       allowed_updates=AllowedUpdates.MESSAGE)
+
+    async def process_update(self, update: Update):
+        with logger.contextualize(request=f"update:{update.update_id}"):
+            return await super().process_update(update)
 
     def start(self):
         self.init()
@@ -50,7 +56,8 @@ def start(self):
             # resulting in RuntimeError: Task attached to different loop
             self.executor.run_app(host=config.HOST,
                                   port=config.PORT,
-                                  loop=asyncio.get_event_loop())
+                                  loop=asyncio.get_event_loop(),
+                                  access_log_format=config.ACCESS_LOG_FORMAT)
         else:
             # self.server.start()
             executor.start_polling(self, skip_updates=True)

nazurin/middleware.py

@@ -3,9 +3,10 @@
 from aiogram.types import Message
 
 from nazurin import config
+from nazurin.utils import logger
 
 class AuthMiddleware(BaseMiddleware):
-    async def on_process_message(self, message: Message, _data: dict):
+    async def on_pre_process_message(self, message: Message, _data: dict):
         if config.IS_PUBLIC:
             return
         allowed_chats = config.ALLOW_ID + config.ALLOW_GROUP + [
@@ -16,3 +17,7 @@ async def on_process_message(self, message: Message, _data: dict):
             or message.from_user.username in config.ALLOW_USERNAME:
             return
         raise CancelHandler()
+
+class LoggingMiddleware(BaseMiddleware):
+    async def on_process_message(self, message: Message, _data: dict):
+        logger.info('Message {}: {}', message.message_id, message.text)

nazurin/models/image.py

@@ -34,14 +34,17 @@ async def chosen_url(self) -> str:
                     not self.height) or self.width + self.height > 10000:
                 self._chosen_url = self.thumbnail
                 logger.info(
-                    'Use thumbnail (Unkown image size or width + height > 10000 [%s, %s]): %s',
-                    self.width, self.height, self._chosen_url)
+                    'Use thumbnail (Unkown image size or width + height > 10000 '
+                    '[{width}, {height}]): {url}',
+                    width=self.width,
+                    height=self.height,
+                    url=self._chosen_url)
             else:
                 size = await self.size()
                 if (not size) or size > 5 * 1024 * 1024:
                     self._chosen_url = self.thumbnail
                     logger.info(
-                        'Use thumbnail (Unknown size or size > 5MB [%s]): %s',
+                        'Use thumbnail (Unknown size or size > 5MB [{}]): {}',
                         size, self._chosen_url)
         return self._chosen_url
 
@@ -54,7 +57,7 @@ async def size(self, **kwargs) -> int:
                 headers = response.headers
                 if 'Content-Length' in headers:
                     self._size = int(headers['Content-Length'])
-                    logger.info('Got image size: %s', self._size)
+                    logger.info('Got image size: {}', self._size)
                 else:
                     logger.info('Failed to get image size')
                 return self._size

nazurin/server.py

@@ -1,11 +1,15 @@
 import asyncio
 import traceback
+from json import JSONDecodeError
 
 import aiohttp_cors
 import aiojobs
 from aiohttp import web
 
 from nazurin import config
+from nazurin.utils import logger
+from nazurin.utils.exceptions import NazurinError
+from nazurin.utils.helpers import format_error
 
 class NazurinServer(web.Application):
     def __init__(self, bot):
@@ -21,26 +25,40 @@ def __init__(self, bot):
             })
         self.on_startup.append(self.init_jobs)
         self.on_shutdown.append(self.shutdown_jobs)
+        self.request_id = 1
 
     def start(self):
-        web.run_app(self)
+        web.run_app(self, access_log_format=config.ACCESS_LOG_FORMAT)
 
     async def do_update(self, url):
         try:
+            logger.info("API request: {}", url)
             await self.bot.update_collection([url])
             await self.bot.send_message(config.ADMIN_ID,
                                         f'Successfully collected {url}')
-        # pylint: disable=broad-except
+        except NazurinError as error:
+            await self.bot.send_message(
+                config.ADMIN_ID,
+                f'Error processing {url}: {format_error(error)}')
+        # pylint: disable-next=broad-exception-caught
         except Exception as error:
             traceback.print_exc()
             if isinstance(error, asyncio.TimeoutError):
                 error = 'Timeout, please try again.'
             await self.bot.send_message(
-                config.ADMIN_ID, f'Error processing {url}: {str(error)}')
+                config.ADMIN_ID,
+                f'Error processing {url}: {format_error(error)}')
 
     async def update_handler(self, request):
-        data = await request.json()
-        await request.app['jobs'].spawn(self.do_update(data.get('url')))
+        try:
+            data = await request.json()
+        except JSONDecodeError:
+            return web.HTTPBadRequest()
+        if 'url' not in data:
+            return web.HTTPBadRequest()
+        with logger.contextualize(request=f"request:{self.request_id}"):
+            await request.app['jobs'].spawn(self.do_update(data.get('url')))
+        self.request_id += 1
         return web.json_response({'error': 0})
 
     async def init_jobs(self, app):

nazurin/sites/__init__.py

@@ -34,7 +34,7 @@ def load(self):
                 handle = getattr(module, 'handle')
                 self.sources.append((PRIORITY, patterns, handle, module_name))
             self.sources.sort(key=lambda s: s[0], reverse=True)
-        logger.info("Loaded %s sites", len(self.sites))
+        logger.info("Loaded {} sites", len(self.sites))
 
     def api(self, site):
         return self.sites[site]

nazurin/sites/deviant_art/api.py

@@ -214,5 +214,5 @@ async def require_csrf_token(self, refresh: bool = False) -> None:
                 # CSRF token must be used along with the cookies returned,
                 # otherwise will be considered invalid
                 DeviantArt.cookies = response.cookies
-                logger.info("Fetched CSRF token: %s, cookies: %s",
+                logger.info("Fetched CSRF token: {}, cookies: {}",
                             DeviantArt.csrf_token, DeviantArt.cookies)

nazurin/sites/moebooru/api.py

@@ -50,8 +50,8 @@ async def get_post(self, post_id: int):
             info = json.loads(info)
             post = info['posts'][0]
             tags = info['tags']
-        except json.decoder.JSONDecodeError as err:
-            logger.error(err)
+        except json.decoder.JSONDecodeError:
+            logger.exception("Failed to decode JSON")
         return post, tags
 
     async def view(self, post_id: int) -> Illust:

nazurin/sites/pixiv/api.py

@@ -129,7 +129,7 @@ async def bookmark(self,
             logger.error(response)
             raise NazurinError(response.error.user_message
                                or response.error.message)
-        logger.info('Bookmarked artwork %s, privacy = %s', artwork_id,
+        logger.info('Bookmarked artwork {}, privacy = {}', artwork_id,
                     privacy.value)
         return True
 
@@ -171,14 +171,14 @@ def convert(config: File, output: File):
             # thus we convert to YUV420P colorspace for better compatibility.
             cmd = f'ffmpeg -i "{config.path}" -vcodec libx264 -pix_fmt yuv420p '\
                   f'-vf "pad=ceil(iw/2)*2:ceil(ih/2)*2" -y "{output.path}"'
-            logger.info('Calling FFmpeg with command: %s', cmd)
+            logger.info('Calling FFmpeg with command: {}', cmd)
             args = shlex.split(cmd)
             try:
                 output = subprocess.check_output(args,
                                                  stderr=subprocess.STDOUT,
                                                  shell=False)
             except subprocess.CalledProcessError as error:
-                logger.error('FFmpeg failed with code %s, output:\n %s',
+                logger.error('FFmpeg failed with code {}, output:\n {}',
                              error.returncode, error.output.decode())
                 raise NazurinError(
                     'Failed to convert ugoira to mp4.') from None
@@ -303,7 +303,7 @@ async def auth(self, retry=True):
                 if retry:
                     random_ua = f"PixivAndroidApp/6.{random.randrange(0, 60)}.0"
                     logger.info(
-                        "Blocked by CloudFlare, retry with random UA: %s",
+                        "Blocked by CloudFlare, retry with random UA: {}",
                         random_ua)
                     Pixiv.api.additional_headers = {"User-Agent": random_ua}
                     return await self.auth(retry=False)

nazurin/storage/__init__.py

@@ -16,7 +16,7 @@ def load(self):
             driver = importlib.import_module('nazurin.storage.' +
                                              driver_name.lower())
             self.disks.append(getattr(driver, driver_name)())
-        logger.info("Loaded %s storage(s), using: %s", len(self.disks),
+        logger.info("Loaded {} storage(s), using: {}", len(self.disks),
                     STORAGE)
 
     async def store(self, illust: Illust):

nazurin/storage/googledrive.py

@@ -68,7 +68,7 @@ async def store(self, files: List[File]):
         tasks = [
             self.create_folders(destination) for destination in destinations
         ]
-        logger.info("Creating folders: %s", destinations)
+        logger.info("Creating folders: {}", destinations)
         folder_ids = await asyncio.gather(*tasks)
         folders = {}
         for destination, folder_id in zip(destinations, folder_ids):

nazurin/storage/mega.py

@@ -82,7 +82,7 @@ async def store(self, files: List[File]):
         tasks = [
             self.ensure_existence(destination) for destination in destinations
         ]
-        logger.info("Creating folders: %s", destinations)
+        logger.info("Creating folders: {}", destinations)
         folder_ids = await asyncio.gather(*tasks)
         folders = {}
         for destination, folder_id in zip(destinations, folder_ids):

nazurin/storage/onedrive.py

@@ -58,7 +58,7 @@ async def store(self, files: List[File]):
         tasks = [
             self.ensure_existence(destination) for destination in destinations
         ]
-        logger.info("Creating folders: %s", destinations)
+        logger.info("Creating folders: {}", destinations)
         await asyncio.gather(*tasks)
 
         tasks = [self.upload(file) for file in files]
@@ -183,7 +183,7 @@ async def _request(self, method, url, headers=None, **kwargs):
         async with Request(headers=_headers) as session:
             async with session.request(method, url, **kwargs) as response:
                 if not response.ok:
-                    logger.info(await response.text())
+                    logger.error(await response.text())
                 response.raise_for_status()
                 if 'application/json' in response.headers['Content-Type']:
                     return await response.json()
@@ -194,15 +194,15 @@ async def stream_upload(self, file: File, url: str):
         async def upload_chunk(url: str, chunk: bytes):
             async with session.put(url, data=chunk) as response:
                 if not response.ok:
-                    logger.info(await response.text())
+                    logger.error(await response.text())
                 response.raise_for_status()
 
         # Must be a multiple of 320 KB
         CHUNK_SIZE = 16 * 320 * 1024  # 5MB
         headers = self.with_credentials()
         range_start = 0
         total_size = await file.size()
-        logger.info("Uploading file, total size: %s...", total_size)
+        logger.info("Uploading file, total size: {}...", total_size)
 
         async with Request(headers=headers) as session:
             async for chunk in read_by_chunks(file.path, CHUNK_SIZE):
@@ -214,7 +214,7 @@ async def upload_chunk(url: str, chunk: bytes):
                 })
                 await upload_chunk(url, chunk)
                 range_start += content_length
-                logger.info("Uploaded %s", range_start)
+                logger.info("Uploaded {}", range_start)
         logger.info("Upload completed")
 
     def with_credentials(self, headers: dict = None) -> dict:

nazurin/utils/__init__.py

@@ -1,7 +1,4 @@
-import logging
-
+from .logging import logger
 from .network import Request
 
-logger = logging.getLogger('nazurin')
-
 __all__ = ['logger', 'Request']