Database locks and bot doesn't work

[Lamroy95]

Transaction manager inside middleware, introduced in #136, now locks the event loop and the whole application stops responding.

Steps to reproduce:

1. Use sqlite as a database
2. Stop the bot
3. Send a multiple updates to a bot (for example lot's of /start commands)
4. Start the bot without skipping pending updates
5. App throws the traceback after recieving SIGINT signal

  File "/Users//personal-projects/KarmaBot/app/middlewares/db_middleware.py", line 37, in __call__
    async with in_transaction() as session:
  File "/Users//personal-projects/KarmaBot/venv/lib/python3.11/site-packages/tortoise/backends/base/client.py", line 245, in __aenter__
    await self.connection.start()
  File "/Users//personal-projects/KarmaBot/venv/lib/python3.11/site-packages/tortoise/backends/sqlite/client.py", line 181, in start
    await self._connection.commit()
  File "/Users//personal-projects/KarmaBot/venv/lib/python3.11/site-packages/aiosqlite/core.py", line 162, in commit
    await self._execute(self._conn.commit)
                        ^^^^^^^^^^
  File "/Users//personal-projects/KarmaBot/venv/lib/python3.11/site-packages/aiosqlite/core.py", line 67, in _conn
    raise ValueError("no active connection")
ValueError: no active connection

Using postgresql doesn't really resolve this issue. I tried to run the app with a clean postgres database and after proceeding the above steps, bot throws a different traceback, but responds to all the pending updates:

  File "/Users//personal-projects/KarmaBot/app/middlewares/db_middleware.py", line 37, in __call__
    async with in_transaction() as session:
  File "/Users//personal-projects/KarmaBot/venv/lib/python3.11/site-packages/tortoise/backends/base/client.py", line 283, in __aexit__
    await self.connection._parent._pool.release(self.connection._connection)
  File "/Users//personal-projects/KarmaBot/venv/lib/python3.11/site-packages/asyncpg/pool.py", line 841, in release
    raise exceptions.InterfaceError(
asyncpg.exceptions._base.InterfaceError: Pool.release() received invalid connection: <PoolConnectionProxy <asyncpg.connection.Connection object at 0x106a3fd30> 0x1069e2650> is not a member of this pool

However, this is not the only issue with moving to postgresql: bot responds to some commands, unless it needs to register a new user:

After that it locks and stops responding. And after recieving SIGINT signal it throws lots of tracebacks (tortoise and db_client logs has DEBUG level, two messages were sent to the chat: !settings command and "-" minus sign):

2023-11-24 02:25:12,519 - app.config.logging_config:11 - INFO - Logging configured successfully
2023-11-24 02:25:12,546 - app.models.config.storage:11 - INFO - creating storage for type StorageType.memory
2023-11-24 02:25:12,546 - app.models.config.db:11 - DEBUG - postgres://postgres:mysecretpassword@localhost:5432/karmabot
2023-11-24 02:25:12,547 - app.models.db.db:11 - INFO - connecting to db postgres://postgres:mysecretpassword@localhost:5432/karmabot
2023-11-24 02:25:12,547 - tortoise:570 - DEBUG - Tortoise-ORM startup
    connections: {'default': {'engine': 'tortoise.backends.asyncpg', 'credentials': {'port': 5432, 'database': 'karmabot', 'host': 'localhost', 'user': 'postgres', 'password': 'mysec***'}}}
    apps: {'models': {'models': ['app.infrastructure.database.models'], 'default_connection': 'default'}}
2023-11-24 02:25:12,568 - app.utils.cli:11 - DEBUG - As application dir using: /Users/username/personal-projects/KarmaBot
2023-11-24 02:25:12,568 - app.middlewares:11 - INFO - Configure middlewares...
2023-11-24 02:25:12,568 - app.utils.cli:11 - INFO - Configure handlers...
2023-11-24 02:25:13,255 - app.utils.executor:11 - INFO - Notified about bot is started.
2023-11-24 02:25:13,256 - app.utils.cli:11 - INFO - starting polling...
2023-11-24 02:25:13,256 - aiogram.dispatcher:524 - INFO - Start polling
2023-11-24 02:25:13,473 - aiogram.dispatcher:340 - INFO - Run polling for bot @botusername id=123 - 'Test Bot'
2023-11-24 02:25:24,758 - tortoise.db_client:60 - DEBUG - Created connection pool <asyncpg.pool.Pool object at 0x103ff2560> with params: {'host': 'localhost', 'port': 5432, 'user': 'postgres', 'database': 'karmabot', 'min_size': 1, 'max_size': 5, 'connection_class': <class 'asyncpg.connection.Connection'>, 'loop': None, 'server_settings': {}}
2023-11-24 02:25:24,764 - tortoise.db_client:130 - DEBUG - SELECT "id","first_name","is_bot","last_name","tg_id","username" FROM "users" WHERE "tg_id"=111229630 LIMIT 2: None
2023-11-24 02:25:24,771 - tortoise.db_client:130 - DEBUG - SELECT "description","type_","chat_id","title","username" FROM "chats" WHERE "chat_id"=-1001425278854 LIMIT 2: None
2023-11-24 02:25:24,775 - tortoise.db_client:130 - DEBUG - SELECT "id","karmic_restrictions","karma_counting","chat_id" FROM "chat_settings" WHERE "chat_id"=-1001425278854 LIMIT 2 FOR UPDATE: None
2023-11-24 02:25:24,784 - app.handlers.karma:11 - INFO - user 111229630 ask his karma in chat -1001425278854
2023-11-24 02:25:24,785 - tortoise.db_client:130 - DEBUG - SELECT "chat_id","karma","user_id","uc_id" FROM "user_karma" WHERE "chat_id"=-1001425278854 AND "user_id"=1 LIMIT 2 FOR UPDATE: None
2023-11-24 02:25:24,790 - tortoise.db_client:130 - DEBUG - SELECT COUNT(*) FROM "user_karma" WHERE "chat_id"=-1001425278854 AND "karma">=50.0: None
2023-11-24 02:25:25,467 - aiogram.event:171 - INFO - Update id=561900853 is handled. Duration 767 ms by bot id=123
2023-11-24 02:25:27,816 - tortoise.db_client:130 - DEBUG - SELECT "id","first_name","is_bot","last_name","tg_id","username" FROM "users" WHERE "tg_id"=111229630 LIMIT 2: None
2023-11-24 02:25:27,822 - tortoise.db_client:130 - DEBUG - SELECT "description","type_","chat_id","title","username" FROM "chats" WHERE "chat_id"=-1001425278854 LIMIT 2: None
2023-11-24 02:25:27,824 - tortoise.db_client:130 - DEBUG - SELECT "id","karmic_restrictions","karma_counting","chat_id" FROM "chat_settings" WHERE "chat_id"=-1001425278854 LIMIT 2 FOR UPDATE: None
2023-11-24 02:25:27,831 - tortoise.db_client:130 - DEBUG - SELECT "id","karmic_restrictions","karma_counting","chat_id" FROM "chat_settings" WHERE "chat_id"=-1001425278854 LIMIT 2 FOR UPDATE: None
2023-11-24 02:25:28,105 - aiogram.event:171 - INFO - Update id=561900854 is handled. Duration 291 ms by bot id=123
2023-11-24 02:25:39,130 - tortoise.db_client:130 - DEBUG - SELECT "id","first_name","is_bot","last_name","tg_id","username" FROM "users" WHERE "tg_id"=111229630 LIMIT 2: None
2023-11-24 02:25:39,135 - tortoise.db_client:130 - DEBUG - SELECT "description","type_","chat_id","title","username" FROM "chats" WHERE "chat_id"=-1001425278854 LIMIT 2: None
2023-11-24 02:25:39,138 - tortoise.db_client:130 - DEBUG - SELECT "id","karmic_restrictions","karma_counting","chat_id" FROM "chat_settings" WHERE "chat_id"=-1001425278854 LIMIT 2 FOR UPDATE: None
2023-11-24 02:25:39,142 - tortoise.db_client:130 - DEBUG - SELECT "id","first_name","is_bot","last_name","tg_id","username" FROM "users" WHERE "tg_id"=5596979981 LIMIT 2: None
2023-11-24 02:25:39,145 - app.services.adaptive_trottle:11 - DEBUG - check throttle time for chat -1001425278854, user 111229630, target 5596979981 and key karma_change
2023-11-24 02:25:39,145 - app.services.adaptive_trottle:11 - DEBUG - there is no one last call
2023-11-24 02:26:22,838 - aiogram.dispatcher:452 - WARNING - Received SIGINT signal
2023-11-24 02:26:22,840 - aiogram.dispatcher:356 - INFO - Polling stopped for bot @botusername id=123 - 'Test Bot'
2023-11-24 02:26:22,841 - aiogram.dispatcher:551 - INFO - Polling stopped
2023-11-24 02:26:32,849 - tortoise.db_client:78 - DEBUG - Closed connection pool None with params: {'host': 'localhost', 'port': 5432, 'user': 'postgres', 'database': 'karmabot', 'min_size': 1, 'max_size': 5, 'connection_class': <class 'asyncpg.connection.Connection'>, 'loop': None, 'server_settings': {}}
2023-11-24 02:26:32,852 - tortoise:616 - INFO - Tortoise-ORM shutdown
2023-11-24 02:26:32,857 - app.handlers.errors:11 - ERROR - Cause exception cannot call Transaction.rollback(): the underlying connection is closed in update update_id=561900855 message=Message(message_id=9560, date=datetime.datetime(2023, 11, 23, 19, 25, 39, tzinfo=TzInfo(UTC)), chat=Chat(id=-1001425278854, type='supergroup', title='test', username=None, first_name=None, last_name=None, is_forum=None, photo=None, active_usernames=None, emoji_status_custom_emoji_id=None, emoji_status_expiration_date=None, bio=None, has_private_forwards=None, has_restricted_voice_and_video_messages=None, join_to_send_messages=None, join_by_request=None, description=None, invite_link=None, pinned_message=None, permissions=None, slow_mode_delay=None, message_auto_delete_time=None, has_aggressive_anti_spam_enabled=None, has_hidden_members=None, has_protected_content=None, sticker_set_name=None, can_set_sticker_set=None, linked_chat_id=None, location=None), message_thread_id=9535, from_user=User(id=111229630, is_bot=False, first_name='🍉', last_name=None, username='Lamroy95', language_code='en', is_premium=True, added_to_attachment_menu=None, can_join_groups=None, can_read_all_group_messages=None, supports_inline_queries=None), sender_chat=None, forward_from=None, forward_from_chat=None, forward_from_message_id=None, forward_signature=None, forward_sender_name=None, forward_date=None, is_topic_message=None, is_automatic_forward=None, reply_to_message=Message(message_id=9535, date=datetime.datetime(2023, 11, 23, 19, 7, 30, tzinfo=TzInfo(UTC)), chat=Chat(id=-1001425278854, type='supergroup', title='test', username=None, first_name=None, last_name=None, is_forum=None, photo=None, active_usernames=None, emoji_status_custom_emoji_id=None, emoji_status_expiration_date=None, bio=None, has_private_forwards=None, has_restricted_voice_and_video_messages=None, join_to_send_messages=None, join_by_request=None, description=None, invite_link=None, pinned_message=None, permissions=None, slow_mode_delay=None, message_auto_delete_time=None, has_aggressive_anti_spam_enabled=None, has_hidden_members=None, has_protected_content=None, sticker_set_name=None, can_set_sticker_set=None, linked_chat_id=None, location=None), message_thread_id=None, from_user=User(id=5596979981, is_bot=False, first_name='🍋', last_name=None, username='lemon_fruit', language_code=None, is_premium=None, added_to_attachment_menu=None, can_join_groups=None, can_read_all_group_messages=None, supports_inline_queries=None), sender_chat=None, forward_from=None, forward_from_chat=None, forward_from_message_id=None, forward_signature=None, forward_sender_name=None, forward_date=None, is_topic_message=None, is_automatic_forward=None, reply_to_message=None, via_bot=None, edit_date=None, has_protected_content=None, media_group_id=None, author_signature=None, text='🗿', entities=None, animation=None, audio=None, document=None, photo=None, sticker=None, story=None, video=None, video_note=None, voice=None, caption=None, caption_entities=None, has_media_spoiler=None, contact=None, dice=None, game=None, poll=None, venue=None, location=None, new_chat_members=None, left_chat_member=None, new_chat_title=None, new_chat_photo=None, delete_chat_photo=None, group_chat_created=None, supergroup_chat_created=None, channel_chat_created=None, message_auto_delete_timer_changed=None, migrate_to_chat_id=None, migrate_from_chat_id=None, pinned_message=None, invoice=None, successful_payment=None, user_shared=None, chat_shared=None, connected_website=None, write_access_allowed=None, passport_data=None, proximity_alert_triggered=None, forum_topic_created=None, forum_topic_edited=None, forum_topic_closed=None, forum_topic_reopened=None, general_forum_topic_hidden=None, general_forum_topic_unhidden=None, video_chat_scheduled=None, video_chat_started=None, video_chat_ended=None, video_chat_participants_invited=None, web_app_data=None, reply_markup=None), via_bot=None, edit_date=None, has_protected_content=None, media_group_id=None, author_signature=None, text='-', entities=None, animation=None, audio=None, document=None, photo=None, sticker=None, story=None, video=None, video_note=None, voice=None, caption=None, caption_entities=None, has_media_spoiler=None, contact=None, dice=None, game=None, poll=None, venue=None, location=None, new_chat_members=None, left_chat_member=None, new_chat_title=None, new_chat_photo=None, delete_chat_photo=None, group_chat_created=None, supergroup_chat_created=None, channel_chat_created=None, message_auto_delete_timer_changed=None, migrate_to_chat_id=None, migrate_from_chat_id=None, pinned_message=None, invoice=None, successful_payment=None, user_shared=None, chat_shared=None, connected_website=None, write_access_allowed=None, passport_data=None, proximity_alert_triggered=None, forum_topic_created=None, forum_topic_edited=None, forum_topic_closed=None, forum_topic_reopened=None, general_forum_topic_hidden=None, general_forum_topic_unhidden=None, video_chat_scheduled=None, video_chat_started=None, video_chat_ended=None, video_chat_participants_invited=None, web_app_data=None, reply_markup=None) edited_message=None channel_post=None edited_channel_post=None inline_query=None chosen_inline_result=None callback_query=None shipping_query=None pre_checkout_query=None poll=None poll_answer=None my_chat_member=None chat_member=None chat_join_request=None
Traceback (most recent call last):
  File "/Users/username/personal-projects/KarmaBot/app/services/change_karma.py", line 54, in change_karma
    uk, abs_change, relative_change = await UserKarma.change_or_create(
                                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/app/infrastructure/database/models/user_karma.py", line 99, in change_or_create
    uk, _ = await UserKarma.get_or_create(
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/tortoise/models.py", line 1056, in get_or_create
    async with in_transaction(connection_name=db.connection_name) as connection:
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/tortoise/backends/base/client.py", line 301, in __aenter__
    await self.lock.acquire()  # type:ignore
    ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/locks.py", line 114, in acquire
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/username/personal-projects/KarmaBot/app/middlewares/db_middleware.py", line 39, in __call__
    return await handler(event, data)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/aiogram/dispatcher/router.py", line 111, in _wrapped
    return await self._propagate_event(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/aiogram/dispatcher/router.py", line 144, in _propagate_event
    response = await router.propagate_event(update_type=update_type, event=event, **kwargs)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/aiogram/dispatcher/router.py", line 116, in propagate_event
    return await observer.wrap_outer_middleware(_wrapped, event=event, data=kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/aiogram/dispatcher/router.py", line 111, in _wrapped
    return await self._propagate_event(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/aiogram/dispatcher/router.py", line 136, in _propagate_event
    response = await observer.trigger(event, **kwargs)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/aiogram/dispatcher/event/telegram.py", line 120, in trigger
    return await wrapped_inner(event, kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/app/middlewares/fix_target_middleware.py", line 24, in __call__
    return await handler(event, data)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/aiogram/dispatcher/event/handler.py", line 42, in call
    return await wrapped()
           ^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/app/services/adaptive_trottle.py", line 46, in wrapped
    return await func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/app/handlers/change_karma.py", line 65, in karma_change
    result_change_karma = await change_karma(
                          ^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/app/services/change_karma.py", line 53, in change_karma
    async with in_transaction() as conn:
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/tortoise/backends/base/client.py", line 310, in __aexit__
    await self.connection.rollback()
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/tortoise/backends/asyncpg/client.py", line 193, in rollback
    await self.transaction.rollback()
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/asyncpg/connresource.py", line 19, in _check
    self._check_conn_validity(meth.__name__)
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/asyncpg/connresource.py", line 41, in _check_conn_validity
    raise exceptions.InterfaceError(
asyncpg.exceptions._base.InterfaceError: cannot call Transaction.rollback(): the underlying connection is closed

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/username/personal-projects/KarmaBot/app/handlers/errors.py", line 19, in errors_handler
    raise error.exception
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/aiogram/dispatcher/middlewares/error.py", line 25, in __call__
    return await handler(event, data)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/aiogram/dispatcher/middlewares/user_context.py", line 27, in __call__
    return await handler(event, data)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/aiogram/fsm/middleware.py", line 39, in __call__
    return await handler(event, data)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/app/middlewares/config_middleware.py", line 21, in __call__
    return await handler(event, data)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/aiogram/dispatcher/event/telegram.py", line 120, in trigger
    return await wrapped_inner(event, kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/aiogram/dispatcher/event/handler.py", line 42, in call
    return await wrapped()
           ^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/aiogram/dispatcher/dispatcher.py", line 275, in _listen_update
    return await self.propagate_event(update_type=update_type, event=event, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/aiogram/dispatcher/router.py", line 116, in propagate_event
    return await observer.wrap_outer_middleware(_wrapped, event=event, data=kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/app/middlewares/db_middleware.py", line 37, in __call__
    async with in_transaction() as session:
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/tortoise/backends/base/client.py", line 279, in __aexit__
    await self.connection.rollback()
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/tortoise/backends/asyncpg/client.py", line 193, in rollback
    await self.transaction.rollback()
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/asyncpg/connresource.py", line 19, in _check
    self._check_conn_validity(meth.__name__)
  File "/Users/username/personal-projects/KarmaBot/venv/lib/python3.11/site-packages/asyncpg/connresource.py", line 41, in _check_conn_validity
    raise exceptions.InterfaceError(
asyncpg.exceptions._base.InterfaceError: cannot call Transaction.rollback(): the underlying connection is closed
2023-11-24 02:26:33,484 - aiogram.event:171 - INFO - Update id=561900855 is handled. Duration 54356 ms by bot id=123