From db79cc9eb0d7dc7a4a1ae9190f7a23c6c9e6e317 Mon Sep 17 00:00:00 2001 From: c0mrade Date: Sun, 19 Apr 2026 11:50:40 +0300 Subject: [PATCH] =?UTF-8?q?fix:=20=D1=83=D1=81=D1=82=D1=80=D0=B0=D0=BD?= =?UTF-8?q?=D0=B8=D1=82=D1=8C=20MissingGreenlet=20=D0=B2=20=D0=B0=D0=B2?= =?UTF-8?q?=D1=82=D0=BE=D0=BF=D0=BB=D0=B0=D1=82=D0=B5=D0=B6=D0=B0=D1=85=20?= =?UTF-8?q?=D0=B8=20=D0=BF=D0=BE=D1=87=D0=B8=D0=BD=D0=B8=D1=82=D1=8C=20tra?= =?UTF-8?q?ceback=20=D0=B2=20=D0=BB=D0=BE=D0=B3=D0=B0=D1=85?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - subtract_user_balance: пишем promo_offer_log в отдельной сессии вместо rollback после commit, который экспайрил объекты основной сессии и ломал последующие обращения к subscription/user attrs - monitoring_service._process_autopayments: перезагружаем subscription с eager-load user/tariff после списания, оборачиваем каждую итерацию в try/except + rollback, чтобы одна ошибка не валила весь батч - logging_config: новый processor _auto_capture_exc_info автоматически подтягивает traceback из sys.exc_info() или error-kwarg → полный traceback в файле, консоли и Telegram без exc_info=True на каждом вызове - logging_handler: дублирующая логика захвата exc_info в TelegramNotifierProcessor как резерв --- app/database/crud/user.py | 68 ++++-- app/logging_config.py | 43 ++++ app/logging_handler.py | 17 +- app/services/monitoring_service.py | 356 ++++++++++++++++------------- 4 files changed, 305 insertions(+), 179 deletions(-) diff --git a/app/database/crud/user.py b/app/database/crud/user.py index e0a241e0..958b6752 100644 --- a/app/database/crud/user.py +++ b/app/database/crud/user.py @@ -710,30 +710,52 @@ async def subtract_user_balance( await db.refresh(user) if consume_promo_offer and log_context: - try: - await log_promo_offer_action( - db, - user_id=user.id, - offer_id=log_context.get('offer_id'), - action='consumed', - source=log_context.get('source'), - percent=log_context.get('percent'), - effect_type=log_context.get('effect_type'), - details=log_context.get('details'), - commit=commit, - ) - except Exception as log_error: # pragma: no cover - defensive logging - logger.warning( - 'Failed to record promo offer consumption log for user', user_id=user.id, log_error=log_error - ) - if commit: - try: - await db.rollback() - except Exception as rollback_error: # pragma: no cover - defensive logging - logger.warning( - 'Failed to rollback session after promo offer consumption log failure', - rollback_error=rollback_error, + # Пишем лог в ОТДЕЛЬНОЙ сессии, чтобы его commit/rollback не касался + # основной сессии caller'а. Иначе rollback в случае фейла логирования + # экспайрит объекты сессии и следующее обращение к subscription/user + # attrs у caller'а падает с MissingGreenlet. + if commit: + try: + from app.database.database import AsyncSessionLocal + + async with AsyncSessionLocal() as log_db: + await log_promo_offer_action( + log_db, + user_id=user.id, + offer_id=log_context.get('offer_id'), + action='consumed', + source=log_context.get('source'), + percent=log_context.get('percent'), + effect_type=log_context.get('effect_type'), + details=log_context.get('details'), + commit=True, ) + except Exception as log_error: # pragma: no cover - defensive logging + logger.warning( + 'Failed to record promo offer consumption log for user', + user_id=user.id, + log_error=log_error, + ) + else: + # Caller управляет транзакцией — пишем в его сессию без commit. + try: + await log_promo_offer_action( + db, + user_id=user.id, + offer_id=log_context.get('offer_id'), + action='consumed', + source=log_context.get('source'), + percent=log_context.get('percent'), + effect_type=log_context.get('effect_type'), + details=log_context.get('details'), + commit=False, + ) + except Exception as log_error: # pragma: no cover - defensive logging + logger.warning( + 'Failed to record promo offer consumption log for user', + user_id=user.id, + log_error=log_error, + ) logger.info('✅ Средства списаны: →', old_balance=old_balance, balance_kopeks=user.balance_kopeks) return True diff --git a/app/logging_config.py b/app/logging_config.py index 3f189749..6ec4bb8b 100644 --- a/app/logging_config.py +++ b/app/logging_config.py @@ -15,6 +15,7 @@ Usage:: from __future__ import annotations import logging +import sys from typing import Any import structlog @@ -56,6 +57,43 @@ def _prefix_logger_name(logger: Any, method_name: str, event_dict: dict[str, Any return event_dict +def _auto_capture_exc_info(logger: Any, method_name: str, event_dict: dict[str, Any]) -> dict[str, Any]: + """Auto-populate event_dict['exc_info'] so tracebacks render in files/console. + + Without this, callers must pass ``exc_info=True`` at every ``logger.error`` + site. Instead, we try: + 1. exc_info=True → replace with sys.exc_info() (standard structlog behaviour) + 2. no exc_info but we're inside an active except block → use sys.exc_info() + 3. error/exc/exception/e/err kwarg is a BaseException with __traceback__ → + synthesize an exc_info tuple from it + + Result: ``logger.error('msg', error=e)`` inside any ``except`` block now + renders the full traceback to files, console, and Telegram automatically. + """ + exc_info = event_dict.get('exc_info') + if exc_info is True: + current = sys.exc_info() + if current[1] is not None: + event_dict['exc_info'] = current + return event_dict + + if exc_info: + return event_dict + + current = sys.exc_info() + if current[1] is not None: + event_dict['exc_info'] = current + return event_dict + + for key in ('error', 'exc', 'exception', 'e', 'err'): + candidate = event_dict.get(key) + if isinstance(candidate, BaseException) and candidate.__traceback__ is not None: + event_dict['exc_info'] = (type(candidate), candidate, candidate.__traceback__) + return event_dict + + return event_dict + + def setup_logging() -> tuple[logging.Formatter, logging.Formatter, Any]: """Configure structlog and return formatters + notifier. @@ -82,6 +120,11 @@ def setup_logging() -> tuple[logging.Formatter, logging.Formatter, Any]: structlog.stdlib.PositionalArgumentsFormatter(), timestamper, structlog.processors.StackInfoRenderer(), + # Auto-capture traceback from sys.exc_info()/error-kwarg BEFORE any + # consumer looks at event_dict. Runs for ALL log levels so files, + # console, and Telegram all see the same traceback without requiring + # every caller to pass exc_info=True. + _auto_capture_exc_info, # TelegramNotifierProcessor MUST run while exc_info is still a raw # tuple so it can extract the traceback for Telegram notifications. # ConsoleRenderer handles exc_info formatting downstream (with Rich diff --git a/app/logging_handler.py b/app/logging_handler.py index 2cf95624..1d285bea 100644 --- a/app/logging_handler.py +++ b/app/logging_handler.py @@ -129,13 +129,28 @@ class TelegramNotifierProcessor: if any(logger_name.startswith(prefix) for prefix in IGNORED_LOGGER_PREFIXES): return event_dict - # 4. Resolve exc_info=True to actual tuple while still in except block. + # 4. Resolve exc_info into actual tuple while still in except block. # logger.exception() sets exc_info=True (bool); we need the tuple for # traceback extraction. sys.exc_info() works because the processor runs # synchronously inside the except clause. + # + # If exc_info is not passed at all, auto-capture traceback from: + # (a) sys.exc_info() — works when logger.error is called inside except + # (b) error/exc/exception kwargs if they carry __traceback__ + # This avoids having to pass exc_info=True at every logger.error site. exc_info = event_dict.get('exc_info') if exc_info is True: event_dict['exc_info'] = sys.exc_info() + elif not exc_info: + current = sys.exc_info() + if current[1] is not None: + event_dict['exc_info'] = current + else: + for key in ('error', 'exc', 'exception', 'e', 'err'): + candidate = event_dict.get(key) + if isinstance(candidate, BaseException) and candidate.__traceback__ is not None: + event_dict['exc_info'] = (type(candidate), candidate, candidate.__traceback__) + break # 5. Bot not initialized yet — skip bot = self._bot diff --git a/app/services/monitoring_service.py b/app/services/monitoring_service.py index 63e1e749..6535982b 100644 --- a/app/services/monitoring_service.py +++ b/app/services/monitoring_service.py @@ -1203,159 +1203,202 @@ class MonitoringService: failed_count = 0 for subscription in autopay_subscriptions: - from app.database.crud.subscription import is_recently_updated_by_webhook - - if is_recently_updated_by_webhook(subscription): - logger.debug( - 'Пропуск автоплатежа подписки : обновлена вебхуком недавно', subscription_id=subscription.id - ) - continue - - user = subscription.user - if not user: - continue - - user_identifier = user.telegram_id or f'email:{user.id}' - - # Определяем период продления: из тарифа (минимальный) или 30 дней по умолчанию - tariff = getattr(subscription, 'tariff', None) - if tariff: - autopay_period = tariff.get_shortest_period() or 30 - else: - autopay_period = 30 - try: - from app.database.crud.user import lock_user_for_pricing - from app.services.pricing_engine import pricing_engine + from app.database.crud.subscription import is_recently_updated_by_webhook - user = await lock_user_for_pricing(db, user.id) + if is_recently_updated_by_webhook(subscription): + logger.debug( + 'Пропуск автоплатежа подписки : обновлена вебхуком недавно', subscription_id=subscription.id + ) + continue - pricing = await pricing_engine.calculate_renewal_price( - db, - subscription, - autopay_period, - user=user, - ) - renewal_cost = pricing.final_total - except Exception as e: - logger.error( - 'Ошибка расчёта стоимости автопродления, пропускаем', - subscription_id=subscription.id, - user_id=user.id, - error=str(e), - ) - failed_count += 1 - continue + user = subscription.user + if not user: + continue - if renewal_cost <= 0: - logger.warning( - 'Нулевая стоимость автопродления, пропускаем', - subscription_id=subscription.id, - user_id=user.id, - renewal_cost=renewal_cost, - ) - failed_count += 1 - continue + user_identifier = user.telegram_id or f'email:{user.id}' - # calculate_renewal_price уже включает promo_group + promo_offer скидки. - # Не применяем promo_offer повторно — только consume-им при успешной оплате. - charge_amount = renewal_cost - promo_discount_percent = get_user_active_promo_discount_percent(user) + # Определяем период продления: из тарифа (минимальный) или 30 дней по умолчанию + tariff = getattr(subscription, 'tariff', None) + if tariff: + autopay_period = tariff.get_shortest_period() or 30 + else: + autopay_period = 30 - autopay_key = f'autopay_{user.id}_{subscription.id}' - if autopay_key in self._notified_users: - continue + try: + from app.database.crud.user import lock_user_for_pricing + from app.services.pricing_engine import pricing_engine - if user.balance_kopeks >= charge_amount: - success = await subtract_user_balance( - db, - user, - charge_amount, - 'Автопродление подписки', - consume_promo_offer=promo_discount_percent > 0, - mark_as_paid_subscription=True, - ) + user = await lock_user_for_pricing(db, user.id) - if success: - # extend_subscription сам обработает EXPIRED→ACTIVE переход - # (проверяет status + end_date для определения was_expired) - if subscription.status == SubscriptionStatus.EXPIRED.value: - logger.info( - '🔄 Autopay: продление EXPIRED подписки (восстановление)', - subscription_id=subscription.id, - user_id=user.id, - ) - old_end_date = subscription.end_date - await extend_subscription(db, subscription, autopay_period) - await self.subscription_service.update_remnawave_user( + pricing = await pricing_engine.calculate_renewal_price( db, subscription, - reset_traffic=settings.RESET_TRAFFIC_ON_PAYMENT, - reset_reason='автопродление подписки', + autopay_period, + user=user, + ) + renewal_cost = pricing.final_total + except Exception as e: + logger.error( + 'Ошибка расчёта стоимости автопродления, пропускаем', + subscription_id=subscription.id, + user_id=user.id, + error=str(e), + ) + failed_count += 1 + continue + + if renewal_cost <= 0: + logger.warning( + 'Нулевая стоимость автопродления, пропускаем', + subscription_id=subscription.id, + user_id=user.id, + renewal_cost=renewal_cost, + ) + failed_count += 1 + continue + + # calculate_renewal_price уже включает promo_group + promo_offer скидки. + # Не применяем promo_offer повторно — только consume-им при успешной оплате. + charge_amount = renewal_cost + promo_discount_percent = get_user_active_promo_discount_percent(user) + + autopay_key = f'autopay_{user.id}_{subscription.id}' + if autopay_key in self._notified_users: + continue + + if user.balance_kopeks >= charge_amount: + success = await subtract_user_balance( + db, + user, + charge_amount, + 'Автопродление подписки', + consume_promo_offer=promo_discount_percent > 0, + mark_as_paid_subscription=True, ) - # Создаём транзакцию, чтобы автопродление было видно в статистике и карточке пользователя - try: - from app.database.crud.transaction import create_transaction - from app.database.models import PaymentMethod, TransactionType - - transaction = await create_transaction( - db=db, - user_id=user.id, - type=TransactionType.SUBSCRIPTION_PAYMENT, - amount_kopeks=charge_amount, - description=f'Автопродление подписки на {autopay_period} дней', - payment_method=PaymentMethod.BALANCE, - ) - except Exception as exc: - logger.warning('Не удалось создать транзакцию автопродления', user_id=user.id, exc=exc) - transaction = None - - # Отправляем уведомление администраторам - try: - from app.services.subscription_renewal_service import with_admin_notification_service - - if transaction: - await with_admin_notification_service( - lambda svc: svc.send_subscription_extension_notification( - db, - user, - subscription, - transaction, - autopay_period, - old_end_date, - new_end_date=subscription.end_date, - balance_after=user.balance_kopeks, - ) + if success: + # subtract_user_balance мог оставить сессию в expired state + # (напр. rollback внутри log_promo_offer_action при consume_promo_offer). + # Перезагружаем subscription с eager-загрузкой user/tariff, чтобы + # избежать MissingGreenlet на последующих обращениях к subscription.* + refetch_result = await db.execute( + select(Subscription) + .options( + selectinload(Subscription.user), + selectinload(Subscription.tariff), ) - except Exception as exc: + .where(Subscription.id == subscription.id) + ) + refreshed_subscription = refetch_result.scalar_one_or_none() + if refreshed_subscription is None: + logger.warning( + 'Подписка пропала после списания — пропускаем шаги продления', + subscription_id=subscription.id, + user_id=user.id, + ) + processed_count += 1 + self._notified_users.add(autopay_key) + continue + subscription = refreshed_subscription + + # extend_subscription сам обработает EXPIRED→ACTIVE переход + # (проверяет status + end_date для определения was_expired) + if subscription.status == SubscriptionStatus.EXPIRED.value: + logger.info( + '🔄 Autopay: продление EXPIRED подписки (восстановление)', + subscription_id=subscription.id, + user_id=user.id, + ) + old_end_date = subscription.end_date + await extend_subscription(db, subscription, autopay_period) + await self.subscription_service.update_remnawave_user( + db, + subscription, + reset_traffic=settings.RESET_TRAFFIC_ON_PAYMENT, + reset_reason='автопродление подписки', + ) + + # Создаём транзакцию, чтобы автопродление было видно в статистике и карточке пользователя + try: + from app.database.crud.transaction import create_transaction + from app.database.models import PaymentMethod, TransactionType + + transaction = await create_transaction( + db=db, + user_id=user.id, + type=TransactionType.SUBSCRIPTION_PAYMENT, + amount_kopeks=charge_amount, + description=f'Автопродление подписки на {autopay_period} дней', + payment_method=PaymentMethod.BALANCE, + ) + except Exception as exc: + logger.warning('Не удалось создать транзакцию автопродления', user_id=user.id, exc=exc) + transaction = None + + # Отправляем уведомление администраторам + try: + from app.services.subscription_renewal_service import with_admin_notification_service + + if transaction: + await with_admin_notification_service( + lambda svc: svc.send_subscription_extension_notification( + db, + user, + subscription, + transaction, + autopay_period, + old_end_date, + new_end_date=subscription.end_date, + balance_after=user.balance_kopeks, + ) + ) + except Exception as exc: + logger.warning( + 'Не удалось отправить админ-уведомление об автопродлении', user_id=user.id, exc=exc + ) + + # Send notification via appropriate channel + if user.telegram_id and self.bot: + await self._send_autopay_success_notification( + user, charge_amount, autopay_period, subscription=subscription + ) + elif not user.telegram_id: + # Email-only user - use notification delivery service + await notification_delivery_service.notify_autopay_success( + user=user, + amount_kopeks=charge_amount, + new_expires_at=subscription.end_date, + ) + + processed_count += 1 + self._notified_users.add(autopay_key) + logger.info( + '💳 Автопродление подписки пользователя успешно (списано , скидка %)', + user_identifier=user_identifier, + charge_amount=charge_amount, + promo_discount_percent=promo_discount_percent, + ) + else: + failed_count += 1 + if await self._check_autopay_fail_cooldown(user.id, user_identifier): + if user.telegram_id and self.bot: + await self._send_autopay_failed_notification( + user, user.balance_kopeks, charge_amount, subscription=subscription + ) + elif not user.telegram_id: + await notification_delivery_service.notify_autopay_failed( + user=user, + reason='Ошибка списания средств', + ) + await self._set_autopay_fail_cooldown(user.id, user_identifier) logger.warning( - 'Не удалось отправить админ-уведомление об автопродлении', user_id=user.id, exc=exc + '💳 Ошибка списания средств для автопродления пользователя', + user_identifier=user_identifier, ) - - # Send notification via appropriate channel - if user.telegram_id and self.bot: - await self._send_autopay_success_notification( - user, charge_amount, autopay_period, subscription=subscription - ) - elif not user.telegram_id: - # Email-only user - use notification delivery service - await notification_delivery_service.notify_autopay_success( - user=user, - amount_kopeks=charge_amount, - new_expires_at=subscription.end_date, - ) - - processed_count += 1 - self._notified_users.add(autopay_key) - logger.info( - '💳 Автопродление подписки пользователя успешно (списано , скидка %)', - user_identifier=user_identifier, - charge_amount=charge_amount, - promo_discount_percent=promo_discount_percent, - ) else: failed_count += 1 + if await self._check_autopay_fail_cooldown(user.id, user_identifier): if user.telegram_id and self.bot: await self._send_autopay_failed_notification( @@ -1364,30 +1407,33 @@ class MonitoringService: elif not user.telegram_id: await notification_delivery_service.notify_autopay_failed( user=user, - reason='Ошибка списания средств', + reason='Недостаточно средств на балансе', ) await self._set_autopay_fail_cooldown(user.id, user_identifier) + logger.warning( - '💳 Ошибка списания средств для автопродления пользователя', user_identifier=user_identifier + '💳 Недостаточно средств для автопродления у пользователя', + user_identifier=user_identifier, ) - else: + except Exception as sub_error: failed_count += 1 - - if await self._check_autopay_fail_cooldown(user.id, user_identifier): - if user.telegram_id and self.bot: - await self._send_autopay_failed_notification( - user, user.balance_kopeks, charge_amount, subscription=subscription - ) - elif not user.telegram_id: - await notification_delivery_service.notify_autopay_failed( - user=user, - reason='Недостаточно средств на балансе', - ) - await self._set_autopay_fail_cooldown(user.id, user_identifier) - - logger.warning( - '💳 Недостаточно средств для автопродления у пользователя', user_identifier=user_identifier + logger.error( + 'Ошибка автопродления отдельной подписки', + subscription_id=getattr(subscription, 'id', None), + user_id=getattr(subscription, 'user_id', None), + error=sub_error, + exc_info=True, ) + # Сессия могла «протухнуть» (MissingGreenlet, rollback после commit и т.п.) — + # откатываемся, чтобы следующая итерация работала с чистой сессией. + try: + await db.rollback() + except Exception as rollback_error: + logger.warning( + 'Не удалось сделать rollback сессии после ошибки автопродления', + rollback_error=rollback_error, + ) + continue if processed_count > 0 or failed_count > 0: await self._log_monitoring_event( @@ -1398,7 +1444,7 @@ class MonitoringService: ) except Exception as e: - logger.error('Ошибка обработки автоплатежей', error=e) + logger.error('Ошибка обработки автоплатежей', error=e, exc_info=True) async def _send_subscription_expired_notification( self, user: User, subscription: Subscription, *, tariff_name: str | None = None