fix periodic activity-check algorithm silently losing player activity
All checks were successful
CI/CD Pipeline / build-and-deploy (push) Successful in 38s
All checks were successful
CI/CD Pipeline / build-and-deploy (push) Successful in 38s
Errors from Lichess (timeouts/5xx/invalid tokens) were being disguised as "no activity" (HTTP 200, games_count/puzzles_in_period=0), causing the bot to silently advance its checkpoint past real, undetected activity. Puzzle-fetch failures weren't counted as errors at all, and the periodic task died permanently after 5 consecutive errors with no way to recover short of a manual restart. /setperiod also unconditionally reset the checkpoint, dropping the window between the last check and the command. - API now returns success=false/502 on real errors instead of masking them as zero activity (models.py, stats_service.py, main.py) - Puzzle-fetch errors are now treated the same as game-fetch errors: retry the same window instead of reporting "no puzzles" - Notification delivery failures no longer silently advance the checkpoint - Replaced the hard 5-error kill switch with capped backoff that keeps retrying indefinitely, plus an admin-bot notification if a player's monitoring has been failing for a prolonged period (~2h+) - /setperiod only clears the checkpoint when disabling notifications, preserving continuity when a period is just changed Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
This commit is contained in:
parent
75e62b57a1
commit
4a783225af
4 changed files with 118 additions and 58 deletions
|
|
@ -134,7 +134,45 @@ class LichessBot:
|
||||||
logger.error(f"Failed to send admin notification via API: {e}")
|
logger.error(f"Failed to send admin notification via API: {e}")
|
||||||
import traceback
|
import traceback
|
||||||
logger.error(traceback.format_exc())
|
logger.error(traceback.format_exc())
|
||||||
|
|
||||||
|
@staticmethod
|
||||||
|
def _estimate_backoff_elapsed_hours(consecutive_errors: int) -> float:
|
||||||
|
"""Оценивает, сколько времени прошло при данном числе подряд идущих ошибок,
|
||||||
|
исходя из формулы бэкоффа periodic_check: min(300, 60 * n) секунд на попытку."""
|
||||||
|
total_seconds = sum(min(300, 60 * i) for i in range(1, consecutive_errors + 1))
|
||||||
|
return total_seconds / 3600
|
||||||
|
|
||||||
|
async def _notify_admin_periodic_check_failing(self, gamer_username: str, user_id: int, consecutive_errors: int):
|
||||||
|
"""Notify admin that periodic check for a gamer has been failing for a long time."""
|
||||||
|
try:
|
||||||
|
admin_chat_id = self.db.get_admin_chat_id()
|
||||||
|
if not admin_chat_id:
|
||||||
|
logger.warning("Admin chat id is not set; cannot send admin notification.")
|
||||||
|
return
|
||||||
|
hours = self._estimate_backoff_elapsed_hours(consecutive_errors)
|
||||||
|
url = f"https://api.telegram.org/bot{ADMINPANEL_TELEGRAM_BOT_TOKEN}/sendMessage"
|
||||||
|
message = (
|
||||||
|
f"⚠️ <b>Мониторинг игрока не работает</b>\n\n"
|
||||||
|
f"Игрок: {gamer_username}\n"
|
||||||
|
f"Владелец: user_id={user_id}\n"
|
||||||
|
f"Подряд идущих ошибок: {consecutive_errors} (~{hours:.1f} ч)\n\n"
|
||||||
|
f"Проверьте токен игрока или доступность Lichess API."
|
||||||
|
)
|
||||||
|
logger.info(f"Sending admin 'periodic check failing' notification via direct API to chat_id={admin_chat_id}")
|
||||||
|
async with aiohttp.ClientSession() as session:
|
||||||
|
async with session.post(url, json={
|
||||||
|
"chat_id": admin_chat_id,
|
||||||
|
"text": message,
|
||||||
|
"parse_mode": "HTML"
|
||||||
|
}) as response:
|
||||||
|
if response.status == 200:
|
||||||
|
logger.info("Admin 'periodic check failing' notification sent successfully")
|
||||||
|
else:
|
||||||
|
error_text = await response.text()
|
||||||
|
logger.error(f"Failed to send admin 'periodic check failing' notification: {response.status} - {error_text}")
|
||||||
|
except Exception as e:
|
||||||
|
logger.error(f"Failed to send admin 'periodic check failing' notification: {e}")
|
||||||
|
|
||||||
async def test_admin_notify(self, update: Update, context: ContextTypes.DEFAULT_TYPE):
|
async def test_admin_notify(self, update: Update, context: ContextTypes.DEFAULT_TYPE):
|
||||||
"""Manual test to verify admin notifications delivery path."""
|
"""Manual test to verify admin notifications delivery path."""
|
||||||
user = update.effective_user
|
user = update.effective_user
|
||||||
|
|
@ -1284,9 +1322,11 @@ class LichessBot:
|
||||||
|
|
||||||
# Set period for this user-gamer pair
|
# Set period for this user-gamer pair
|
||||||
self.db.set_user_gamer_period(user_id, gamer_id, period)
|
self.db.set_user_gamer_period(user_id, gamer_id, period)
|
||||||
self.db.clear_period_checkpoint(user_id, gamer_id)
|
|
||||||
|
|
||||||
if period == 0:
|
if period == 0:
|
||||||
|
# Отключаем мониторинг: чистим чекпоинт, чтобы при повторном включении
|
||||||
|
# не было catch-up на потенциально очень старое (устаревшее) окно.
|
||||||
|
self.db.clear_period_checkpoint(user_id, gamer_id)
|
||||||
await self.stop_periodic_task(gamer_id, user_id)
|
await self.stop_periodic_task(gamer_id, user_id)
|
||||||
await query.edit_message_text(
|
await query.edit_message_text(
|
||||||
t('notifications_disabled', lang, username=selected_gamer['username'])
|
t('notifications_disabled', lang, username=selected_gamer['username'])
|
||||||
|
|
@ -1446,6 +1486,10 @@ class LichessBot:
|
||||||
)
|
)
|
||||||
self.periodic_tasks[task_key] = task
|
self.periodic_tasks[task_key] = task
|
||||||
|
|
||||||
|
# Оповещать админ-бота о затяжной серии ошибок каждые ADMIN_NOTIFY_ERROR_THRESHOLD
|
||||||
|
# подряд идущих ошибок (~2 часа при капнутом бэкоффе в 300с на попытку)
|
||||||
|
ADMIN_NOTIFY_ERROR_THRESHOLD = 25
|
||||||
|
|
||||||
async def periodic_check(self, gamer: Dict[str, Any], user_id: int, period_minutes: int):
|
async def periodic_check(self, gamer: Dict[str, Any], user_id: int, period_minutes: int):
|
||||||
"""Periodic check for gamer activity"""
|
"""Periodic check for gamer activity"""
|
||||||
task_key = f"{gamer['id']}_{user_id}"
|
task_key = f"{gamer['id']}_{user_id}"
|
||||||
|
|
@ -1551,27 +1595,33 @@ class LichessBot:
|
||||||
except Exception as e:
|
except Exception as e:
|
||||||
logger.error(f"❌ Error getting games data for {gamer['username']}: {e}")
|
logger.error(f"❌ Error getting games data for {gamer['username']}: {e}")
|
||||||
consecutive_errors += 1
|
consecutive_errors += 1
|
||||||
|
backoff_seconds = min(300, 60 * consecutive_errors)
|
||||||
if consecutive_errors >= max_consecutive_errors:
|
if consecutive_errors >= max_consecutive_errors:
|
||||||
logger.error(f"Too many consecutive errors for {gamer['username']}, stopping periodic check")
|
logger.error(f"⚠️ {consecutive_errors} consecutive errors for {gamer['username']}; still retrying the same period (backoff {backoff_seconds}s)")
|
||||||
break
|
else:
|
||||||
logger.warning(f"⚠️ Games data unavailable for {gamer['username']}; retrying the same period in 60 seconds")
|
logger.warning(f"⚠️ Games data unavailable for {gamer['username']}; retrying the same period in {backoff_seconds}s")
|
||||||
await asyncio.sleep(60)
|
if consecutive_errors == self.ADMIN_NOTIFY_ERROR_THRESHOLD or (
|
||||||
|
consecutive_errors > self.ADMIN_NOTIFY_ERROR_THRESHOLD
|
||||||
|
and consecutive_errors % self.ADMIN_NOTIFY_ERROR_THRESHOLD == 0
|
||||||
|
):
|
||||||
|
await self._notify_admin_periodic_check_failing(gamer['username'], user_id, consecutive_errors)
|
||||||
|
await asyncio.sleep(backoff_seconds)
|
||||||
continue
|
continue
|
||||||
|
|
||||||
if gamer.get('token'):
|
if gamer.get('token'):
|
||||||
try:
|
# Ошибки получения пазлов обрабатываются так же, как ошибки игр:
|
||||||
# Добавляем запрос в очередь (будет выполнен с задержкой 7 секунд)
|
# исключение всплывает во внешний обработчик, чекпоинт не продвигается,
|
||||||
logger.info(f"📥 Adding puzzles request to queue for {gamer['username']}")
|
# то же окно ретраится на следующей итерации (не считаем "пазлов не было").
|
||||||
puzzles_data = await self.request_queue.add_request(
|
logger.info(f"📥 Adding puzzles request to queue for {gamer['username']}")
|
||||||
self.lichess_api.get_puzzles_period,
|
puzzles_data = await self.request_queue.add_request(
|
||||||
gamer['token'], since_timestamp, until_timestamp_approx, 150
|
self.lichess_api.get_puzzles_period,
|
||||||
)
|
gamer['token'], since_timestamp, until_timestamp_approx, 150
|
||||||
# Обновляем фактическое время после получения ответа по пазлам
|
)
|
||||||
request_end_time = datetime.now()
|
if puzzles_data is None:
|
||||||
logger.info(f"✅ Puzzles API response received for {gamer['username']} at {request_end_time}")
|
raise RuntimeError("Puzzles period API returned no data")
|
||||||
except Exception as e:
|
# Обновляем фактическое время после получения ответа по пазлам
|
||||||
logger.warning(f"⚠️ Error getting puzzles data for {gamer['username']}: {e}")
|
request_end_time = datetime.now()
|
||||||
# Продолжаем без данных по пазлам
|
logger.info(f"✅ Puzzles API response received for {gamer['username']} at {request_end_time}")
|
||||||
|
|
||||||
# Сбрасываем счетчик ошибок при успешном запросе
|
# Сбрасываем счетчик ошибок при успешном запросе
|
||||||
consecutive_errors = 0
|
consecutive_errors = 0
|
||||||
|
|
@ -1628,35 +1678,28 @@ class LichessBot:
|
||||||
|
|
||||||
logger.info(f"🔍 Activity check result for {username}: has_games={has_games} (total={total_games}), has_puzzles={has_puzzles} (total={total_puzzles})")
|
logger.info(f"🔍 Activity check result for {username}: has_games={has_games} (total={total_games}), has_puzzles={has_puzzles} (total={total_puzzles})")
|
||||||
|
|
||||||
# Отправляем уведомление только если есть реальная активность
|
# Отправляем уведомление только если есть реальная активность.
|
||||||
|
# Ошибки форматирования/отправки НЕ перехватываются здесь: они должны
|
||||||
|
# всплыть во внешний обработчик, чтобы чекпоинт не продвинулся и уже
|
||||||
|
# обнаруженная активность была отправлена повторно на следующей попытке,
|
||||||
|
# а не потеряна молча.
|
||||||
if has_games or has_puzzles:
|
if has_games or has_puzzles:
|
||||||
logger.info(f"📊 Activity detected for {gamer['username']}, preparing notification...")
|
logger.info(f"📊 Activity detected for {gamer['username']}, preparing notification...")
|
||||||
try:
|
user_lang = self.db.get_user_language(user_id)
|
||||||
# Get user language from database
|
notification = StatsFormatter.format_period_notification(
|
||||||
user_lang = self.db.get_user_language(user_id)
|
gamer['username'], games_data, puzzles_data, period_minutes, lang=user_lang
|
||||||
notification = StatsFormatter.format_period_notification(
|
)
|
||||||
gamer['username'], games_data, puzzles_data, period_minutes, lang=user_lang
|
|
||||||
)
|
if not self.application:
|
||||||
|
raise RuntimeError(f"Application not initialized, cannot send notification for {gamer['username']} to user {user_id}")
|
||||||
if self.application:
|
|
||||||
try:
|
await self.application.bot.send_message(
|
||||||
await self.application.bot.send_message(
|
chat_id=user_id,
|
||||||
chat_id=user_id,
|
text=notification
|
||||||
text=notification
|
)
|
||||||
)
|
logger.info(f"✅ Sent periodic notification for {gamer['username']} to user {user_id}")
|
||||||
logger.info(f"✅ Sent periodic notification for {gamer['username']} to user {user_id}")
|
# Increment periodic notification counter
|
||||||
# Increment periodic notification counter
|
self.counters.increment('periodic_notification')
|
||||||
self.counters.increment('periodic_notification')
|
|
||||||
except Exception as e:
|
|
||||||
logger.error(f"❌ Failed to send notification to user {user_id}: {e}")
|
|
||||||
import traceback
|
|
||||||
logger.error(f"Traceback: {traceback.format_exc()}")
|
|
||||||
else:
|
|
||||||
logger.error(f"❌ Application not initialized, cannot send notification for {gamer['username']} to user {user_id}")
|
|
||||||
except Exception as e:
|
|
||||||
logger.error(f"Error formatting notification for {gamer['username']}: {e}")
|
|
||||||
import traceback
|
|
||||||
logger.error(f"Traceback: {traceback.format_exc()}")
|
|
||||||
else:
|
else:
|
||||||
logger.debug(f"⏭️ No activity found for {gamer['username']} in the last {period_minutes} minutes")
|
logger.debug(f"⏭️ No activity found for {gamer['username']} in the last {period_minutes} minutes")
|
||||||
|
|
||||||
|
|
@ -1686,17 +1729,19 @@ class LichessBot:
|
||||||
logger.error(f"Error in periodic check for {gamer['username']}: {e}")
|
logger.error(f"Error in periodic check for {gamer['username']}: {e}")
|
||||||
import traceback
|
import traceback
|
||||||
logger.error(f"Full traceback: {traceback.format_exc()}")
|
logger.error(f"Full traceback: {traceback.format_exc()}")
|
||||||
|
|
||||||
if consecutive_errors >= max_consecutive_errors:
|
|
||||||
logger.error(f"Too many consecutive errors for {gamer['username']}, stopping periodic check")
|
|
||||||
if task_key in self.periodic_tasks:
|
|
||||||
del self.periodic_tasks[task_key]
|
|
||||||
if task_key in self.period_start_times:
|
|
||||||
del self.period_start_times[task_key]
|
|
||||||
break
|
|
||||||
|
|
||||||
# Ждем перед повторной попыткой при ошибке
|
# Не убиваем задачу навсегда: ретраим то же окно с растущим бэкоффом
|
||||||
await asyncio.sleep(60) # 1 minute delay before retry
|
# (капается на 300с), пока Lichess/Telegram не восстановятся.
|
||||||
|
backoff_seconds = min(300, 60 * consecutive_errors)
|
||||||
|
if consecutive_errors >= max_consecutive_errors:
|
||||||
|
logger.error(f"⚠️ {consecutive_errors} consecutive errors for {gamer['username']}; still retrying the same period (backoff {backoff_seconds}s)")
|
||||||
|
if consecutive_errors == self.ADMIN_NOTIFY_ERROR_THRESHOLD or (
|
||||||
|
consecutive_errors > self.ADMIN_NOTIFY_ERROR_THRESHOLD
|
||||||
|
and consecutive_errors % self.ADMIN_NOTIFY_ERROR_THRESHOLD == 0
|
||||||
|
):
|
||||||
|
await self._notify_admin_periodic_check_failing(gamer['username'], user_id, consecutive_errors)
|
||||||
|
await asyncio.sleep(backoff_seconds)
|
||||||
|
continue
|
||||||
|
|
||||||
def setup_handlers(self, application: Application):
|
def setup_handlers(self, application: Application):
|
||||||
"""Setup all handlers"""
|
"""Setup all handlers"""
|
||||||
|
|
|
||||||
|
|
@ -555,7 +555,12 @@ async def get_games_of_period(
|
||||||
since_seconds = since // 1000
|
since_seconds = since // 1000
|
||||||
until_seconds = until // 1000
|
until_seconds = until // 1000
|
||||||
result = await stats_service.get_games_of_period(username, since_seconds, until_seconds, rated_only)
|
result = await stats_service.get_games_of_period(username, since_seconds, until_seconds, rated_only)
|
||||||
|
if not result.success:
|
||||||
|
# Реальная ошибка при обращении к Lichess — не маскируем её под "0 игр"
|
||||||
|
raise HTTPException(status_code=502, detail=result.message)
|
||||||
return result
|
return result
|
||||||
|
except HTTPException:
|
||||||
|
raise
|
||||||
except Exception as e:
|
except Exception as e:
|
||||||
logger.error(f"Ошибка в endpoint get_games_of_period: {e}")
|
logger.error(f"Ошибка в endpoint get_games_of_period: {e}")
|
||||||
raise HTTPException(status_code=500, detail=f"Внутренняя ошибка сервера: {str(e)}")
|
raise HTTPException(status_code=500, detail=f"Внутренняя ошибка сервера: {str(e)}")
|
||||||
|
|
@ -695,7 +700,12 @@ async def get_puzzle_of_period(
|
||||||
|
|
||||||
try:
|
try:
|
||||||
result = await stats_service.get_puzzle_of_period(token, since, until, max)
|
result = await stats_service.get_puzzle_of_period(token, since, until, max)
|
||||||
|
if not result.success:
|
||||||
|
# Реальная ошибка при обращении к Lichess — не маскируем её под "0 пазлов"
|
||||||
|
raise HTTPException(status_code=502, detail=result.message)
|
||||||
return result
|
return result
|
||||||
|
except HTTPException:
|
||||||
|
raise
|
||||||
except Exception as e:
|
except Exception as e:
|
||||||
logger.error(f"Ошибка в endpoint get_puzzle_of_period: {e}")
|
logger.error(f"Ошибка в endpoint get_puzzle_of_period: {e}")
|
||||||
raise HTTPException(status_code=500, detail=f"Внутренняя ошибка сервера: {str(e)}")
|
raise HTTPException(status_code=500, detail=f"Внутренняя ошибка сервера: {str(e)}")
|
||||||
|
|
|
||||||
|
|
@ -186,6 +186,7 @@ class GamesOfPeriodResponse(BaseModel):
|
||||||
Содержит метаинформацию о запросе и агрегированную статистику игр.
|
Содержит метаинформацию о запросе и агрегированную статистику игр.
|
||||||
"""
|
"""
|
||||||
message: str = Field(..., description="Сообщение о результате запроса", example="Статистика игр за период")
|
message: str = Field(..., description="Сообщение о результате запроса", example="Статистика игр за период")
|
||||||
|
success: bool = Field(True, description="False, если запрос к Lichess завершился ошибкой (а не легитимным нулевым результатом)", example=True)
|
||||||
username: str = Field(..., description="Имя пользователя", example="magnus")
|
username: str = Field(..., description="Имя пользователя", example="magnus")
|
||||||
period_start: int = Field(..., description="Начало периода (Unix timestamp)", example=1640995200)
|
period_start: int = Field(..., description="Начало периода (Unix timestamp)", example=1640995200)
|
||||||
period_end: int = Field(..., description="Конец периода (Unix timestamp)", example=1641081600)
|
period_end: int = Field(..., description="Конец периода (Unix timestamp)", example=1641081600)
|
||||||
|
|
@ -232,6 +233,7 @@ class PuzzleOfPeriodResponse(BaseModel):
|
||||||
Содержит метаинформацию о запросе и агрегированную статистику решения задач.
|
Содержит метаинформацию о запросе и агрегированную статистику решения задач.
|
||||||
"""
|
"""
|
||||||
message: str = Field(..., description="Сообщение о результате запроса", example="Статистика решения задач за период")
|
message: str = Field(..., description="Сообщение о результате запроса", example="Статистика решения задач за период")
|
||||||
|
success: bool = Field(True, description="False, если запрос к Lichess завершился ошибкой (а не легитимным нулевым результатом)", example=True)
|
||||||
period_start: int = Field(..., description="Начало периода (Unix timestamp в миллисекундах)", example=1640995200000)
|
period_start: int = Field(..., description="Начало периода (Unix timestamp в миллисекундах)", example=1640995200000)
|
||||||
period_end: int = Field(..., description="Конец периода (Unix timestamp в миллисекундах)", example=1641081600000)
|
period_end: int = Field(..., description="Конец периода (Unix timestamp в миллисекундах)", example=1641081600000)
|
||||||
max_puzzles: int = Field(..., description="Максимальное количество задач для получения", example=50)
|
max_puzzles: int = Field(..., description="Максимальное количество задач для получения", example=50)
|
||||||
|
|
|
||||||
|
|
@ -699,6 +699,7 @@ class StatsService:
|
||||||
logger.error(f"Ошибка при получении статистики игр за период: {e}")
|
logger.error(f"Ошибка при получении статистики игр за период: {e}")
|
||||||
return GamesOfPeriodResponse(
|
return GamesOfPeriodResponse(
|
||||||
message=f"Ошибка при получении статистики: {str(e)}",
|
message=f"Ошибка при получении статистики: {str(e)}",
|
||||||
|
success=False,
|
||||||
username=username,
|
username=username,
|
||||||
period_start=since_timestamp,
|
period_start=since_timestamp,
|
||||||
period_end=until_timestamp,
|
period_end=until_timestamp,
|
||||||
|
|
@ -765,6 +766,7 @@ class StatsService:
|
||||||
if activities is None:
|
if activities is None:
|
||||||
return PuzzleOfPeriodResponse(
|
return PuzzleOfPeriodResponse(
|
||||||
message="Неверный токен авторизации или доступ запрещен",
|
message="Неверный токен авторизации или доступ запрещен",
|
||||||
|
success=False,
|
||||||
period_start=since_ms,
|
period_start=since_ms,
|
||||||
period_end=until_ms,
|
period_end=until_ms,
|
||||||
max_puzzles=max_puzzles,
|
max_puzzles=max_puzzles,
|
||||||
|
|
@ -796,6 +798,7 @@ class StatsService:
|
||||||
logger.error(f"Ошибка при получении статистики решения задач за период: {e}")
|
logger.error(f"Ошибка при получении статистики решения задач за период: {e}")
|
||||||
return PuzzleOfPeriodResponse(
|
return PuzzleOfPeriodResponse(
|
||||||
message=f"Ошибка при получении статистики: {str(e)}",
|
message=f"Ошибка при получении статистики: {str(e)}",
|
||||||
|
success=False,
|
||||||
period_start=since_ms,
|
period_start=since_ms,
|
||||||
period_end=until_ms,
|
period_end=until_ms,
|
||||||
max_puzzles=max_puzzles,
|
max_puzzles=max_puzzles,
|
||||||
|
|
|
||||||
Loading…
Add table
Add a link
Reference in a new issue