Challenge game started long after challenge was cancelled

[MarkZH]

In an issue reported to lichess-bot, it was discovered that a challenge that was cancelled could still result in a game.

Here's a timeline of events from the user's log for challenge/game ID re4ELMrx.

Challenge created:

2023-03-08 14:43:54,884 matchmaking INFO Will challenge Zagreus_Engine for a standard game.
2023-03-08 14:43:54,922 urllib3.connectionpool DEBUG https://lichess.org:443 "POST /api/challenge/Zagreus_Engine HTTP/1.1" 200 None
2023-03-08 14:43:54,924 matchmaking INFO Challenge id is re4ELMrx.
2023-03-08 14:43:54,926 __main__ DEBUG Event: {'type': 'challenge', 'challenge': {'id': 're4ELMrx', 'url': 'https://lichess.org/re4ELMrx', 'status': 'created', 'challenger': {'id': 'geit2023', 'name': 'geit2023', 'title': 'BOT', 'rating': 1954, 'online': True}, 'destUser': {'id': 'zagreus_engine', 'name': 'Zagreus_Engine', 'title': 'BOT', 'rating': 1962, 'online': True}, 'variant': {'key': 'standard', 'name': 'Standard', 'short': 'Std'}, 'rated': False, 'speed': 'blitz', 'timeControl': {'type': 'clock', 'limit': 300, 'increment': 1, 'show': '5+1'}, 'color': 'random', 'finalColor': 'white', 'perf': {'icon': '\ue01d', 'name': 'Blitz'}}, 'compat': {'bot': True, 'board': True}}

Challenge cancelled after 28 seconds with no response:

2023-03-08 14:44:22,597 urllib3.connectionpool DEBUG https://lichess.org:443 "POST /api/challenge/re4ELMrx/cancel HTTP/1.1" 200 11
2023-03-08 14:44:22,602 matchmaking DEBUG Challenge id re4ELMrx cancelled.
2023-03-08 14:44:22,610 __main__ DEBUG Event: {'type': 'challengeCanceled', 'challenge': {'id': 're4ELMrx', 'url': 'https://lichess.org/re4ELMrx', 'status': 'canceled', 'challenger': {'id': 'geit2023', 'name': 'geit2023', 'title': 'BOT', 'rating': 1954, 'online': True}, 'destUser': {'id': 'zagreus_engine', 'name': 'Zagreus_Engine', 'title': 'BOT', 'rating': 1962, 'online': True}, 'variant': {'key': 'standard', 'name': 'Standard', 'short': 'Std'}, 'rated': False, 'speed': 'blitz', 'timeControl': {'type': 'clock', 'limit': 300, 'increment': 1, 'show': '5+1'}, 'color': 'random', 'finalColor': 'white', 'perf': {'icon': '\ue01d', 'name': 'Blitz'}}}

Then, 13 minutes later, apparently the challenge is accepted and the game starts.

2023-03-08 14:57:38,283 __main__ DEBUG Event: {'type': 'gameStart', 'game': {'fullId': 're4ELMrx7MDG', 'gameId': 're4ELMrx', 'fen': 'rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq - 0 1', 'color': 'white', 'lastMove': '', 'source': 'friend', 'variant': {'key': 'standard', 'name': 'Standard'}, 'speed': 'blitz', 'perf': 'blitz', 'rated': False, 'hasMoved': False, 'opponent': {'id': 'zagreus_engine', 'username': 'BOT Zagreus_Engine', 'rating': 1963}, 'isMyTurn': True, 'secondsLeft': 300, 'compat': {'bot': True, 'board': True}, 'id': 're4ELMrx'}}

The same thing happens with challenge/game ID z9b50qTa, in which the game starts 20 minutes after the challenge is cancelled.

Link to full log from user

[ornicar]

Thanks for the report. My problem here is that I can't reproduce it. bot1 sends a challenge to bot2, then bot1 cancels the challenge. When bot2 hits /api/challenge/4PNDH8Lp/accept it gets 400 "error": "The challenge has been canceled." and the game doesn't start.

[ornicar]

I think I got it, and next deploy should fix it.

[MarkZH]

I was writing this when you made the commit, maybe this will be useful just in case there are any other issues.

---

Do the lichess logs show anything out of the ordinary for the game IDs listed above? It seems strange that 10 or 20 minutes could pass between a challenge and a game since the challenge should expire after 20 seconds for realtime games.

Now that I look at the logs, this only happened when the user's bot geit2023 challenged the bot Zagreus_Engine. IDs:

• re4ELMrx - 13 minute delay
• z9b50qTa - 20 minute delay
• VZsnUR71 - 40 minute delay
• NcjU7kQZ - 40 minute delay

[ornicar]

challenges switch to offline after 20s but they can still become online again, or be accepted.

The problem was that offline challenges could not be canceled properly.