Bot loses lock occasionally

[RogueBurger]

While using the bot normally, every once in a while this exception will pop up when trying to execute a command: A restart seems to be required to fix the issue and reacquire a lock.

wordle-app-1    | 2022-02-01 15:52:26,739 DEBU [WordleBot.Wordle] New game started: overfishes
wordle-redis-1  | 1:M 01 Feb 2022 15:54:52.972 * 100 changes in 300 seconds. Saving...
wordle-redis-1  | 1:M 01 Feb 2022 15:54:52.973 * Background saving started by pid 96
wordle-redis-1  | 96:C 01 Feb 2022 15:54:52.977 * DB saved on disk
wordle-redis-1  | 96:C 01 Feb 2022 15:54:52.977 * RDB: 0 MB of memory used by copy-on-write
wordle-redis-1  | 1:M 01 Feb 2022 15:54:53.073 * Background saving terminated with success
wordle-app-1    | Ignoring exception in on_message
wordle-app-1    | Traceback (most recent call last):
wordle-app-1    |   File "/usr/local/lib/python3.9/site-packages/discord/ext/commands/bot.py", line 939, in invoke
wordle-app-1    |     await ctx.command.invoke(ctx)
wordle-app-1    |   File "/usr/local/lib/python3.9/site-packages/discord/ext/commands/core.py", line 863, in invoke
wordle-app-1    |     await injected(*ctx.args, **ctx.kwargs)
wordle-app-1    |   File "/usr/local/lib/python3.9/site-packages/discord/ext/commands/core.py", line 94, in wrapped
wordle-app-1    |     raise CommandInvokeError(exc) from exc
wordle-app-1    | discord.ext.commands.errors.CommandInvokeError: Command raised an exception: LockNotOwnedError: Cannot release a lock that's no longer owned
wordle-app-1    |
wordle-app-1    | During handling of the above exception, another exception occurred:
wordle-app-1    |
wordle-app-1    | Traceback (most recent call last):
wordle-app-1    |   File "/usr/local/lib/python3.9/site-packages/discord/ext/commands/core.py", line 71, in wrapped
wordle-app-1    |     ret = await coro(*args, **kwargs)
wordle-app-1    |   File "/srv/Wordle/Wordle.py", line 41, in cog_command_error
wordle-app-1    |     raise err
wordle-app-1    |   File "/usr/local/lib/python3.9/site-packages/discord/ext/commands/core.py", line 85, in wrapped
wordle-app-1    |     ret = await coro(*args, **kwargs)
wordle-app-1    |   File "/srv/Wordle/Wordle.py", line 114, in guess
wordle-app-1    |     return await ctx.send(message)
wordle-app-1    |   File "/usr/local/lib/python3.9/contextlib.py", line 199, in __aexit__
wordle-app-1    |     await self.gen.athrow(typ, value, traceback)
wordle-app-1    |   File "/srv/Wordle/GameManager.py", line 27, in lock
wordle-app-1    |     yield
wordle-app-1    |   File "/usr/local/lib/python3.9/contextlib.py", line 199, in __aexit__
wordle-app-1    |     await self.gen.athrow(typ, value, traceback)
wordle-app-1    |   File "/srv/Wordle/Store/Redis/RedisStore.py", line 34, in lock
wordle-app-1    |     yield
wordle-app-1    |   File "/usr/local/lib/python3.9/site-packages/aioredis/lock.py", line 165, in __aexit__
wordle-app-1    |     await self.release()
wordle-app-1    |   File "/usr/local/lib/python3.9/site-packages/aioredis/lock.py", line 255, in do_release
wordle-app-1    |     raise LockNotOwnedError("Cannot release a lock" " that's no longer owned")
wordle-app-1    | aioredis.exceptions.LockNotOwnedError: Cannot release a lock that's no longer owned
wordle-app-1    |
wordle-app-1    | The above exception was the direct cause of the following exception:
wordle-app-1    |
wordle-app-1    | Traceback (most recent call last):
wordle-app-1    |   File "/usr/local/lib/python3.9/site-packages/discord/client.py", line 343, in _run_event
wordle-app-1    |     await coro(*args, **kwargs)
wordle-app-1    |   File "/srv/Main.py", line 72, in on_message
wordle-app-1    |     await bot.process_commands(msg)
wordle-app-1    |   File "/usr/local/lib/python3.9/site-packages/discord/ext/commands/bot.py", line 976, in process_commands
wordle-app-1    |     await self.invoke(ctx)
wordle-app-1    |   File "/usr/local/lib/python3.9/site-packages/discord/ext/commands/bot.py", line 943, in invoke
wordle-app-1    |     await ctx.command.dispatch_error(ctx, exc)
wordle-app-1    |   File "/usr/local/lib/python3.9/site-packages/discord/ext/commands/core.py", line 431, in dispatch_error
wordle-app-1    |     await wrapped(ctx, error)
wordle-app-1    |   File "/usr/local/lib/python3.9/site-packages/discord/ext/commands/core.py", line 77, in wrapped
wordle-app-1    |     raise CommandInvokeError(exc) from exc
wordle-app-1    | discord.ext.commands.errors.CommandInvokeError: Command raised an exception: LockNotOwnedError: Cannot release a lock that's no longer owned

[hobochili]

Preceding successful commands in channel:

%s 10 puzzle
%h

Bombed on:

%g overfishes

(Issued ~3 min after last successful command in channel)

[hobochili]

I have found an issue with the lock implementation that will ultimately need to be resolved, however I do not believe that is what is actually behind this particular bug. I've been able to simulate the error message locally simply by adding an async sleep call of 5 seconds in the Wordle.guess function, however in that simulation the bot will still process incoming commands after raising the exception.

My theory right now is that something is hanging and erroring in the ctx.send call, possibly from rate limiting or some kind of connection error. Because of how the lock is implemented as a context manager, if ctx.send throws an exception after the lock has reached its timeout, the HTTP exception will get swallowed.

PR #16 adds a switch to apply the log_level setting globally. Once merged:

• set log_level to debug and verbose to true, restart the bot, and wait for the issue to emerge.

When it happens again, and before restarting:

1. check if the game lock exists in redis. The following will output all existing redis keys, which should suffice.

# assuming redis is listening on 127.0.0.1:6379

$ redis-cli -h 127.0.0.1
127.0.0.1:6379> keys *
1) "wordle:server:<server_id>:channel:<channel_id>:game"
2) "wordle:server:<server_id>:channel:<channel_id>:lock"

2. grab logs
3. wait at least a few minutes and then try entering some other commands prior to restarting