From da0e8a2e3e7c1de40d24ea0da65f7328dfd59829 Mon Sep 17 00:00:00 2001 From: Egor Date: Sat, 4 Oct 2025 06:51:19 +0300 Subject: [PATCH] feat: add structured startup timeline logging --- app/utils/startup_timeline.py | 184 ++++++++++++++++ main.py | 397 ++++++++++++++++++++++------------ 2 files changed, 441 insertions(+), 140 deletions(-) create mode 100644 app/utils/startup_timeline.py diff --git a/app/utils/startup_timeline.py b/app/utils/startup_timeline.py new file mode 100644 index 00000000..3d37215a --- /dev/null +++ b/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) + diff --git a/main.py b/main.py index 7fb8acf2..51d6bfa2 100644 --- a/main.py +++ b/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...") - - try: - ensure_locale_templates() - except Exception as error: - logger.warning("Failed to prepare locale templates: %s", error) + timeline = StartupTimeline(logger, "Bedolaga Remnawave Bot") + timeline.log_banner( + [ + ("Уровень логирования", settings.LOG_LEVEL), + ("Режим БД", settings.DATABASE_MODE), + ] + ) + + 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,168 +77,271 @@ async def main(): polling_task = None web_api_server = None - try: - logger.info("📊 Инициализация базы данных...") - 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("⚠️ Продолжаем запуск без миграции") - else: - logger.info("ℹ️ Миграция пропущена (SKIP_MIGRATION=true)") - - logger.info("⚙️ Загрузка конфигурации из БД...") - try: - await bot_configuration_service.initialize() - logger.info("✅ Конфигурация загружена") - except Exception as error: - logger.error(f"❌ Не удалось загрузить конфигурацию: {error}") + summary_logged = False - logger.info("🤖 Настройка бота...") - bot, dp = await setup_bot() + try: + async with timeline.stage( + "Инициализация базы данных", "🗄️", success_message="База данных готова" + ): + await init_db() + + skip_migration = os.getenv('SKIP_MIGRATION', 'false').lower() == 'true' + + if not skip_migration: + 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: + timeline.add_manual_step( + "Проверка и миграция базы данных", + "⏭️", + "Пропущено", + "SKIP_MIGRATION=true", + ) + + 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}") + + 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("🔗 Бот подключен к сервисам мониторинга и техработ") - logger.info("🗄️ Инициализация сервиса бекапов...") - 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() - logger.info("✅ Автобекапы запущены") - - logger.info("✅ Сервис бекапов инициализирован") - except Exception as e: - logger.error(f"❌ Ошибка инициализации сервиса бекапов: {e}") + 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: - 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: + 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}") + + 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) - + webhook_needed = ( settings.TRIBUTE_ENABLED or settings.is_cryptobot_enabled() 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") - - logger.info(f"🌐 Запуск webhook сервера для: {', '.join(enabled_services)}...") - webhook_server = WebhookServer(bot) - await webhook_server.start() - else: - logger.info("ℹ️ Tribute и CryptoBot отключены, webhook сервер не запускается") - - 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 сервер не запускается") + 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("📊 Запуск службы мониторинга...") - 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 + webhook_server = WebhookServer(bot) + await webhook_server.start() + stage.log(f"Активированы: {', '.join(enabled_services)}") + stage.success("Webhook сервера запущены") + else: + stage.skip("Tribute, Mulen Pay и CryptoBot отключены") - 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)) - - logger.info("=" * 50) - logger.info("🎯 Активные webhook endpoints:") + 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 отключен настройками") + + 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():