feat: add structured startup timeline logging

app/utils/startup_timeline.py

@@ -0,0 +1,184 @@
+import platform
+import time
+from contextlib import asynccontextmanager
+from dataclasses import dataclass
+from typing import Any, Iterable, List, Optional, Sequence, Tuple
+
+
+@dataclass
+class StepRecord:
+    title: str
+    icon: str
+    status_label: str
+    message: str
+    duration: float
+
+
+class StageHandle:
+    def __init__(
+        self,
+        timeline: "StartupTimeline",
+        title: str,
+        icon: str,
+        success_message: Optional[str],
+    ) -> None:
+        self.timeline = timeline
+        self.title = title
+        self.icon = icon
+        self.message = success_message or ""
+        self.status_icon = "✅"
+        self.status_label = "Готово"
+        self._explicit_status = False
+
+    def success(self, message: Optional[str] = None) -> None:
+        if message is not None:
+            self.message = message
+        self.status_icon = "✅"
+        self.status_label = "Готово"
+        self._explicit_status = True
+
+    def warning(self, message: str) -> None:
+        self.status_icon = "⚠️"
+        self.status_label = "Предупреждение"
+        self.message = message
+        self._explicit_status = True
+
+    def skip(self, message: str) -> None:
+        self.status_icon = "⏭️"
+        self.status_label = "Пропущено"
+        self.message = message
+        self._explicit_status = True
+
+    def failure(self, message: str) -> None:
+        self.status_icon = "❌"
+        self.status_label = "Ошибка"
+        self.message = message
+        self._explicit_status = True
+
+    def log(self, message: str, icon: str = "•") -> None:
+        self.timeline.logger.info(f"┃ {icon} {message}")
+
+
+class StartupTimeline:
+    def __init__(self, logger: Any, app_name: str) -> None:
+        self.logger = logger
+        self.app_name = app_name
+        self.steps: List[StepRecord] = []
+
+    def _record_step(
+        self, title: str, icon: str, status_label: str, message: str, duration: float
+    ) -> None:
+        self.steps.append(
+            StepRecord(
+                title=title,
+                icon=icon,
+                status_label=status_label,
+                message=message,
+                duration=duration,
+            )
+        )
+
+    def log_banner(self, metadata: Optional[Sequence[Tuple[str, Any]]] = None) -> None:
+        title_text = f"🚀 {self.app_name}"
+        subtitle_parts = [f"Python {platform.python_version()}"]
+        if metadata:
+            for key, value in metadata:
+                subtitle_parts.append(f"{key}: {value}")
+        subtitle_text = " | ".join(subtitle_parts)
+
+        width = max(len(title_text), len(subtitle_text))
+        border = "╔" + "═" * (width + 2) + "╗"
+        self.logger.info(border)
+        self.logger.info("║ " + title_text.ljust(width) + " ║")
+        self.logger.info("║ " + subtitle_text.ljust(width) + " ║")
+        self.logger.info("╚" + "═" * (width + 2) + "╝")
+
+    def log_section(self, title: str, lines: Iterable[str], icon: str = "📄") -> None:
+        items = [f"{icon} {title}"] + [f"• {line}" for line in lines]
+        width = max(len(item) for item in items)
+        top = "┌ " + "─" * width + " ┐"
+        middle = "├ " + "─" * width + " ┤"
+        bottom = "└ " + "─" * width + " ┘"
+
+        self.logger.info(top)
+        self.logger.info("│ " + items[0].ljust(width) + " │")
+        self.logger.info(middle)
+        for item in items[1:]:
+            self.logger.info("│ " + item.ljust(width) + " │")
+        self.logger.info(bottom)
+
+    def add_manual_step(
+        self,
+        title: str,
+        icon: str,
+        status_label: str,
+        message: str,
+    ) -> None:
+        self.logger.info(f"┏ {icon} {title}")
+        self.logger.info(f"┗ {icon} {title} — {status_label}: {message}")
+        self._record_step(title, icon, status_label, message, 0.0)
+
+    @asynccontextmanager
+    async def stage(
+        self,
+        title: str,
+        icon: str = "⚙️",
+        description: Optional[str] = None,
+        success_message: Optional[str] = "Готово",
+    ):
+        if description:
+            self.logger.info(f"┏ {icon} {title} — {description}")
+        else:
+            self.logger.info(f"┏ {icon} {title}")
+
+        handle = StageHandle(self, title, icon, success_message)
+        start_time = time.perf_counter()
+        try:
+            yield handle
+        except Exception as exc:
+            message = str(exc)
+            handle.failure(message)
+            self.logger.exception(f"┣ ❌ {title} — ошибка: {message}")
+            raise
+        finally:
+            duration = time.perf_counter() - start_time
+            if not handle._explicit_status:
+                handle.success(handle.message or "Готово")
+            self.logger.info(
+                f"┗ {handle.status_icon} {title} — {handle.message} [{duration:.2f}s]"
+            )
+            self._record_step(
+                title=title,
+                icon=handle.status_icon,
+                status_label=handle.status_label,
+                message=handle.message,
+                duration=duration,
+            )
+
+    def log_summary(self) -> None:
+        if not self.steps:
+            return
+
+        lines = []
+        for step in self.steps:
+            base = (
+                f"{step.icon} {step.title} — {step.status_label}"
+                f" [{step.duration:.2f}s]"
+            )
+            if step.message:
+                base += f" :: {step.message}"
+            lines.append(base)
+
+        width = max(len(line) for line in lines)
+        border_top = "┏" + "━" * (width + 2) + "┓"
+        border_mid = "┣" + "━" * (width + 2) + "┫"
+        border_bottom = "┗" + "━" * (width + 2) + "┛"
+        title = "РЕЗЮМЕ ЗАПУСКА"
+
+        self.logger.info(border_top)
+        self.logger.info("┃ " + title.center(width) + " ┃")
+        self.logger.info(border_mid)
+        for line in lines:
+            self.logger.info("┃ " + line.ljust(width) + " ┃")
+        self.logger.info(border_bottom)
+

main.py

@@ -23,6 +23,7 @@ from app.services.reporting_service import reporting_service
 from app.localization.loader import ensure_locale_templates
 from app.services.system_settings_service import bot_configuration_service
 from app.services.broadcast_service import broadcast_service
+from app.utils.startup_timeline import StartupTimeline
 
 
 class GracefulExit:
@@ -46,12 +47,22 @@ async def main():
     )
     
     logger = logging.getLogger(__name__)
-    logger.info("🚀 Запуск Bedolaga Remnawave Bot...")
+    timeline = StartupTimeline(logger, "Bedolaga Remnawave Bot")
+    timeline.log_banner(
+        [
+            ("Уровень логирования", settings.LOG_LEVEL),
+            ("Режим БД", settings.DATABASE_MODE),
+        ]
+    )
 
-    try:
-        ensure_locale_templates()
-    except Exception as error:
-        logger.warning("Failed to prepare locale templates: %s", error)
+    async with timeline.stage(
+        "Подготовка локализаций", "🗂️", success_message="Шаблоны локализаций готовы"
+    ) as stage:
+        try:
+            ensure_locale_templates()
+        except Exception as error:
+            stage.warning(f"Не удалось подготовить шаблоны локализаций: {error}")
+            logger.warning("Failed to prepare locale templates: %s", error)
 
     killer = GracefulExit()
     signal.signal(signal.SIGINT, killer.exit_gracefully)
@@ -66,70 +77,112 @@ async def main():
     polling_task = None
     web_api_server = None
     
+    summary_logged = False
+
     try:
-        logger.info("📊 Инициализация базы данных...")
-        await init_db()
+        async with timeline.stage(
+            "Инициализация базы данных", "🗄️", success_message="База данных готова"
+        ):
+            await init_db()
 
         skip_migration = os.getenv('SKIP_MIGRATION', 'false').lower() == 'true'
 
         if not skip_migration:
-            logger.info("🔧 Выполняем проверку и миграцию базы данных...")
-            try:
-                migration_success = await run_universal_migration()
-                
-                if migration_success:
-                    logger.info("✅ Миграция базы данных завершена успешно")
-                else:
-                    logger.warning("⚠️ Миграция завершилась с предупреждениями, но продолжаем запуск")
-                    
-            except Exception as migration_error:
-                logger.error(f"❌ Ошибка выполнения миграции: {migration_error}")
-                logger.warning("⚠️ Продолжаем запуск без миграции")
+            async with timeline.stage(
+                "Проверка и миграция базы данных",
+                "🧬",
+                success_message="Миграция завершена успешно",
+            ) as stage:
+                try:
+                    migration_success = await run_universal_migration()
+                    if migration_success:
+                        stage.success("Миграция завершена успешно")
+                    else:
+                        stage.warning(
+                            "Миграция завершилась с предупреждениями, запуск продолжится"
+                        )
+                        logger.warning(
+                            "⚠️ Миграция завершилась с предупреждениями, но продолжаем запуск"
+                        )
+                except Exception as migration_error:
+                    stage.warning(f"Ошибка выполнения миграции: {migration_error}")
+                    logger.error(f"❌ Ошибка выполнения миграции: {migration_error}")
+                    logger.warning("⚠️ Продолжаем запуск без миграции")
         else:
-            logger.info("ℹ️ Миграция пропущена (SKIP_MIGRATION=true)")
+            timeline.add_manual_step(
+                "Проверка и миграция базы данных",
+                "⏭️",
+                "Пропущено",
+                "SKIP_MIGRATION=true",
+            )
 
-        logger.info("⚙️ Загрузка конфигурации из БД...")
-        try:
-            await bot_configuration_service.initialize()
-            logger.info("✅ Конфигурация загружена")
-        except Exception as error:
-            logger.error(f"❌ Не удалось загрузить конфигурацию: {error}")
+        async with timeline.stage(
+            "Загрузка конфигурации из БД",
+            "⚙️",
+            success_message="Конфигурация загружена",
+        ) as stage:
+            try:
+                await bot_configuration_service.initialize()
+            except Exception as error:
+                stage.warning(f"Не удалось загрузить конфигурацию: {error}")
+                logger.error(f"❌ Не удалось загрузить конфигурацию: {error}")
 
-        logger.info("🤖 Настройка бота...")
-        bot, dp = await setup_bot()
+        bot = None
+        dp = None
+        async with timeline.stage("Настройка бота", "🤖", success_message="Бот настроен") as stage:
+            bot, dp = await setup_bot()
+            stage.log("Кеш и FSM подготовлены")
 
         monitoring_service.bot = bot
         maintenance_service.set_bot(bot)
         broadcast_service.set_bot(bot)
 
         from app.services.admin_notification_service import AdminNotificationService
-        admin_notification_service = AdminNotificationService(bot)
-        version_service.bot = bot
-        version_service.set_notification_service(admin_notification_service)
-        logger.info(f"📄 Сервис версий настроен для репозитория: {version_service.repo}")
-        logger.info(f"📦 Текущая версия: {version_service.current_version}")
 
-        logger.info("🔗 Бот подключен к сервисам мониторинга и техработ")
+        async with timeline.stage(
+            "Интеграция сервисов",
+            "🔗",
+            success_message="Сервисы подключены",
+        ) as stage:
+            admin_notification_service = AdminNotificationService(bot)
+            version_service.bot = bot
+            version_service.set_notification_service(admin_notification_service)
+            stage.log(f"Репозиторий версий: {version_service.repo}")
+            stage.log(f"Текущая версия: {version_service.current_version}")
+            stage.success("Мониторинг, уведомления и рассылки подключены")
 
-        logger.info("🗄️ Инициализация сервиса бекапов...")
-        try:
-            backup_service.bot = bot
+        async with timeline.stage(
+            "Сервис бекапов",
+            "🗄️",
+            success_message="Сервис бекапов инициализирован",
+        ) as stage:
+            try:
+                backup_service.bot = bot
+                settings_obj = await backup_service.get_backup_settings()
+                if settings_obj.auto_backup_enabled:
+                    await backup_service.start_auto_backup()
+                    stage.log(
+                        "Автобекапы включены: интервал "
+                        f"{settings_obj.backup_interval_hours}ч, запуск {settings_obj.backup_time}"
+                    )
+                else:
+                    stage.log("Автобекапы отключены настройками")
+                stage.success("Сервис бекапов инициализирован")
+            except Exception as e:
+                stage.warning(f"Ошибка инициализации сервиса бекапов: {e}")
+                logger.error(f"❌ Ошибка инициализации сервиса бекапов: {e}")
 
-            settings_obj = await backup_service.get_backup_settings()
-            if settings_obj.auto_backup_enabled:
-                await backup_service.start_auto_backup()
-                logger.info("✅ Автобекапы запущены")
-            
-            logger.info("✅ Сервис бекапов инициализирован")
-        except Exception as e:
-            logger.error(f"❌ Ошибка инициализации сервиса бекапов: {e}")
-
-        logger.info("📊 Инициализация сервиса отчетов...")
-        try:
-            reporting_service.set_bot(bot)
-            await reporting_service.start()
-        except Exception as e:
-            logger.error(f"❌ Ошибка запуска сервиса отчетов: {e}")
+        async with timeline.stage(
+            "Сервис отчетов",
+            "📊",
+            success_message="Сервис отчетов готов",
+        ) as stage:
+            try:
+                reporting_service.set_bot(bot)
+                await reporting_service.start()
+            except Exception as e:
+                stage.warning(f"Ошибка запуска сервиса отчетов: {e}")
+                logger.error(f"❌ Ошибка запуска сервиса отчетов: {e}")
 
         payment_service = PaymentService(bot)
 
@@ -139,95 +192,156 @@ async def main():
             or settings.is_mulenpay_enabled()
         )
 
-        if webhook_needed:
-            enabled_services = []
-            if settings.TRIBUTE_ENABLED:
-                enabled_services.append("Tribute")
-            if settings.is_mulenpay_enabled():
-                enabled_services.append("Mulen Pay")
-            if settings.is_cryptobot_enabled():
-                enabled_services.append("CryptoBot")
+        async with timeline.stage(
+            "Webhook сервисы",
+            "🌐",
+            success_message="Webhook сервера настроены",
+        ) as stage:
+            if webhook_needed:
+                enabled_services = []
+                if settings.TRIBUTE_ENABLED:
+                    enabled_services.append("Tribute")
+                if settings.is_mulenpay_enabled():
+                    enabled_services.append("Mulen Pay")
+                if settings.is_cryptobot_enabled():
+                    enabled_services.append("CryptoBot")
 
-            logger.info(f"🌐 Запуск webhook сервера для: {', '.join(enabled_services)}...")
-            webhook_server = WebhookServer(bot)
-            await webhook_server.start()
-        else:
-            logger.info("ℹ️ Tribute и CryptoBot отключены, webhook сервер не запускается")
+                webhook_server = WebhookServer(bot)
+                await webhook_server.start()
+                stage.log(f"Активированы: {', '.join(enabled_services)}")
+                stage.success("Webhook сервера запущены")
+            else:
+                stage.skip("Tribute, Mulen Pay и CryptoBot отключены")
 
-        if settings.is_yookassa_enabled():
-            logger.info("💳 Запуск YooKassa webhook сервера...")
-            yookassa_server_task = asyncio.create_task(
-                start_yookassa_webhook_server(payment_service)
-            )
-        else:
-            logger.info("ℹ️ YooKassa отключена, webhook сервер не запускается")
-
-        if settings.is_pal24_enabled():
-            logger.info("💳 Запуск PayPalych webhook сервера...")
-            pal24_server = await start_pal24_webhook_server(payment_service)
-        else:
-            logger.info("ℹ️ PayPalych отключен, webhook сервер не запускается")
-
-        logger.info("📊 Запуск службы мониторинга...")
-        monitoring_task = asyncio.create_task(monitoring_service.start_monitoring())
-        
-        logger.info("🔧 Проверка службы техработ...")
-        if not maintenance_service._check_task or maintenance_service._check_task.done():
-            logger.info("🔧 Запуск службы техработ...")
-            maintenance_task = asyncio.create_task(maintenance_service.start_monitoring())
-        else:
-            logger.info("🔧 Служба техработ уже запущена")
-            maintenance_task = None
-        
-        if settings.is_version_check_enabled():
-            logger.info("📄 Запуск сервиса проверки версий...")
-            version_check_task = asyncio.create_task(version_service.start_periodic_check())
-        else:
-            logger.info("ℹ️ Проверка версий отключена")
-        
-        if settings.is_web_api_enabled():
-            try:
-                from app.webapi import WebAPIServer
-
-                web_api_server = WebAPIServer()
-                await web_api_server.start()
-                logger.info(
-                    "🌐 Административное веб-API запущено: http://%s:%s",
-                    settings.WEB_API_HOST,
-                    settings.WEB_API_PORT,
+        async with timeline.stage(
+            "YooKassa webhook",
+            "💳",
+            success_message="YooKassa webhook запущен",
+        ) as stage:
+            if settings.is_yookassa_enabled():
+                yookassa_server_task = asyncio.create_task(
+                    start_yookassa_webhook_server(payment_service)
                 )
-            except Exception as error:
-                logger.error(f"❌ Не удалось запустить веб-API: {error}")
-        else:
-            logger.info("ℹ️ Веб-API отключено")
+                stage.log(
+                    f"Endpoint: {settings.WEBHOOK_URL}:{settings.YOOKASSA_WEBHOOK_PORT}{settings.YOOKASSA_WEBHOOK_PATH}"
+                )
+            else:
+                stage.skip("YooKassa отключена настройками")
 
-        logger.info("📄 Запуск polling...")
-        polling_task = asyncio.create_task(dp.start_polling(bot, skip_updates=True))
+        async with timeline.stage(
+            "PayPalych webhook",
+            "💳",
+            success_message="PayPalych webhook запущен",
+        ) as stage:
+            if settings.is_pal24_enabled():
+                pal24_server = await start_pal24_webhook_server(payment_service)
+                stage.log(
+                    f"Endpoint: {settings.WEBHOOK_URL}:{settings.PAL24_WEBHOOK_PORT}{settings.PAL24_WEBHOOK_PATH}"
+                )
+            else:
+                stage.skip("PayPalych отключен настройками")
 
-        logger.info("=" * 50)
-        logger.info("🎯 Активные webhook endpoints:")
+        async with timeline.stage(
+            "Служба мониторинга",
+            "📈",
+            success_message="Служба мониторинга запущена",
+        ) as stage:
+            monitoring_task = asyncio.create_task(monitoring_service.start_monitoring())
+            stage.log(f"Интервал опроса: {settings.MONITORING_INTERVAL}с")
+
+        async with timeline.stage(
+            "Служба техработ",
+            "🛡️",
+            success_message="Служба техработ запущена",
+        ) as stage:
+            if not maintenance_service._check_task or maintenance_service._check_task.done():
+                maintenance_task = asyncio.create_task(maintenance_service.start_monitoring())
+                stage.log(f"Интервал проверки: {settings.MAINTENANCE_CHECK_INTERVAL}с")
+            else:
+                maintenance_task = None
+                stage.skip("Служба техработ уже активна")
+
+        async with timeline.stage(
+            "Сервис проверки версий",
+            "📄",
+            success_message="Проверка версий запущена",
+        ) as stage:
+            if settings.is_version_check_enabled():
+                version_check_task = asyncio.create_task(version_service.start_periodic_check())
+                stage.log(
+                    f"Интервал проверки: {settings.VERSION_CHECK_INTERVAL_HOURS}ч"
+                )
+            else:
+                version_check_task = None
+                stage.skip("Проверка версий отключена настройками")
+
+        async with timeline.stage(
+            "Административное веб-API",
+            "🌐",
+            success_message="Веб-API запущено",
+        ) as stage:
+            if settings.is_web_api_enabled():
+                try:
+                    from app.webapi import WebAPIServer
+
+                    web_api_server = WebAPIServer()
+                    await web_api_server.start()
+                    stage.success(
+                        f"Доступно на http://{settings.WEB_API_HOST}:{settings.WEB_API_PORT}"
+                    )
+                except Exception as error:
+                    stage.warning(f"Не удалось запустить веб-API: {error}")
+                    logger.error(f"❌ Не удалось запустить веб-API: {error}")
+            else:
+                stage.skip("Веб-API отключено")
+
+        async with timeline.stage(
+            "Запуск polling",
+            "🤖",
+            success_message="Aiogram polling запущен",
+        ) as stage:
+            polling_task = asyncio.create_task(dp.start_polling(bot, skip_updates=True))
+            stage.log("skip_updates=True")
+
+        webhook_lines = []
         if webhook_needed:
             if settings.TRIBUTE_ENABLED:
-                logger.info(f"   Tribute: {settings.WEBHOOK_URL}:{settings.TRIBUTE_WEBHOOK_PORT}{settings.TRIBUTE_WEBHOOK_PATH}")
+                webhook_lines.append(
+                    f"Tribute: {settings.WEBHOOK_URL}:{settings.TRIBUTE_WEBHOOK_PORT}{settings.TRIBUTE_WEBHOOK_PATH}"
+                )
             if settings.is_mulenpay_enabled():
-                logger.info(f"   Mulen Pay: {settings.WEBHOOK_URL}:{settings.TRIBUTE_WEBHOOK_PORT}{settings.MULENPAY_WEBHOOK_PATH}")
+                webhook_lines.append(
+                    f"Mulen Pay: {settings.WEBHOOK_URL}:{settings.TRIBUTE_WEBHOOK_PORT}{settings.MULENPAY_WEBHOOK_PATH}"
+                )
             if settings.is_cryptobot_enabled():
-                logger.info(f"   CryptoBot: {settings.WEBHOOK_URL}:{settings.TRIBUTE_WEBHOOK_PORT}{settings.CRYPTOBOT_WEBHOOK_PATH}")
+                webhook_lines.append(
+                    f"CryptoBot: {settings.WEBHOOK_URL}:{settings.TRIBUTE_WEBHOOK_PORT}{settings.CRYPTOBOT_WEBHOOK_PATH}"
+                )
         if settings.is_yookassa_enabled():
-            logger.info(f"   YooKassa: {settings.WEBHOOK_URL}:{settings.YOOKASSA_WEBHOOK_PORT}{settings.YOOKASSA_WEBHOOK_PATH}")
-        if settings.is_pal24_enabled():
-            logger.info(
-                f"   PayPalych: {settings.WEBHOOK_URL}:{settings.PAL24_WEBHOOK_PORT}{settings.PAL24_WEBHOOK_PATH}"
+            webhook_lines.append(
+                f"YooKassa: {settings.WEBHOOK_URL}:{settings.YOOKASSA_WEBHOOK_PORT}{settings.YOOKASSA_WEBHOOK_PATH}"
             )
-        logger.info("📄 Активные фоновые сервисы:")
-        logger.info(f"   Мониторинг: {'Включен' if monitoring_task else 'Отключен'}")
-        logger.info(f"   Техработы: {'Включен' if maintenance_task else 'Отключен'}")
-        logger.info(f"   Проверка версий: {'Включен' if version_check_task else 'Отключен'}")
-        logger.info(
-            "   Отчеты: %s",
-            "Включен" if reporting_service.is_running() else "Отключен",
+        if settings.is_pal24_enabled():
+            webhook_lines.append(
+                f"PayPalych: {settings.WEBHOOK_URL}:{settings.PAL24_WEBHOOK_PORT}{settings.PAL24_WEBHOOK_PATH}"
+            )
+
+        timeline.log_section(
+            "Активные webhook endpoints",
+            webhook_lines if webhook_lines else ["Нет активных endpoints"],
+            icon="🎯",
         )
-        logger.info("=" * 50)
+
+        services_lines = [
+            f"Мониторинг: {'Включен' if monitoring_task else 'Отключен'}",
+            f"Техработы: {'Включен' if maintenance_task else 'Отключен'}",
+            f"Проверка версий: {'Включен' if version_check_task else 'Отключен'}",
+            f"Отчеты: {'Включен' if reporting_service.is_running() else 'Отключен'}",
+        ]
+        timeline.log_section("Активные фоновые сервисы", services_lines, icon="📄")
+
+        timeline.log_summary()
+        summary_logged = True
         
         try:
             while not killer.exit:
@@ -276,6 +390,9 @@ async def main():
         raise
         
     finally:
+        if not summary_logged:
+            timeline.log_summary()
+            summary_logged = True
         logger.info("🛑 Начинается корректное завершение работы...")
         
         if yookassa_server_task and not yookassa_server_task.done():