search

kindai-ecl / discord-bot-commit-time

0 stars 0 forks source link

[BUG] アプリケーションの応答がない #7

Closed lCyou closed 5 months ago

lCyou commented 5 months ago

バグの詳細

コマンドを打ってもアプリケーションが応答しない。

再現

不明 2023/05/20朝までは機能していたが2023/05/22 0200の時点でレスポンスがないのを確認

Botで何がしたかったか

コマンドを打って作業のログを確認したかった。 ログや時間計測のコマンドでアプリケーションが応答しない。

スクリーンショット

動作環境

追加詳細t

コマンドの種類にデータベース周りの処理が必要なものが該当する。DbはSQLiteを使用しているのでファイルベースだが、データベースが生きているかどうか、コネクションが異常じゃないかが1番考えられるポイントだと思う。

lCyou commented 5 months ago

研究室にてログを見返していると以下のようなログが流れていた。 下記のプリントは障害発生時のプリントです

2024-05-21 16:21:46 2024-05-21 07:21:46 ERROR    discord.client Ignoring exception in on_voice_state_update
2024-05-21 16:21:46 Traceback (most recent call last):
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 1971, in _exec_single_context
2024-05-21 16:21:46     self.dialect.do_execute(
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/engine/default.py", line 919, in do_execute
2024-05-21 16:21:46     cursor.execute(statement, parameters)
2024-05-21 16:21:46 sqlite3.IntegrityError: FOREIGN KEY constraint failed
2024-05-21 16:21:46 
2024-05-21 16:21:46 The above exception was the direct cause of the following exception:
2024-05-21 16:21:46 
2024-05-21 16:21:46 Traceback (most recent call last):
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/discord/client.py", line 441, in _run_event
2024-05-21 16:21:46     await coro(*args, **kwargs)
2024-05-21 16:21:46   File "/app/bot/bot.py", line 41, in on_voice_state_update
2024-05-21 16:21:46     timelogger.stamp_time_log(member.id, now, 'start')
2024-05-21 16:21:46   File "/app/bot/timelogger.py", line 48, in stamp_time_log
2024-05-21 16:21:46     session.commit()
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/orm/scoping.py", line 597, in commit
2024-05-21 16:21:46     return self._proxied.commit()
2024-05-21 16:21:46            ^^^^^^^^^^^^^^^^^^^^^^
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/orm/session.py", line 1972, in commit
2024-05-21 16:21:46     trans.commit(_to_root=True)
2024-05-21 16:21:46   File "<string>", line 2, in commit
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/orm/state_changes.py", line 139, in _go
2024-05-21 16:21:46     ret_value = fn(self, *arg, **kw)
2024-05-21 16:21:46                 ^^^^^^^^^^^^^^^^^^^^
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/orm/session.py", line 1257, in commit
2024-05-21 16:21:46     self._prepare_impl()
2024-05-21 16:21:46   File "<string>", line 2, in _prepare_impl
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/orm/state_changes.py", line 139, in _go
2024-05-21 16:21:46     ret_value = fn(self, *arg, **kw)
2024-05-21 16:21:46                 ^^^^^^^^^^^^^^^^^^^^
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/orm/session.py", line 1232, in _prepare_impl
2024-05-21 16:21:46     self.session.flush()
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/orm/session.py", line 4296, in flush
2024-05-21 16:21:46     self._flush(objects)
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/orm/session.py", line 4431, in _flush
2024-05-21 16:21:46     with util.safe_reraise():
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/util/langhelpers.py", line 146, in __exit__
2024-05-21 16:21:46     raise exc_value.with_traceback(exc_tb)
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/orm/session.py", line 4392, in _flush
2024-05-21 16:21:46     flush_context.execute()
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/orm/unitofwork.py", line 466, in execute
2024-05-21 16:21:46     rec.execute(self)
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/orm/unitofwork.py", line 642, in execute
2024-05-21 16:21:46     util.preloaded.orm_persistence.save_obj(
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/orm/persistence.py", line 93, in save_obj
2024-05-21 16:21:46     _emit_insert_statements(
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/orm/persistence.py", line 1233, in _emit_insert_statements
2024-05-21 16:21:46     result = connection.execute(
2024-05-21 16:21:46              ^^^^^^^^^^^^^^^^^^^
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 1422, in execute
2024-05-21 16:21:46     return meth(
2024-05-21 16:21:46            ^^^^^
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/sql/elements.py", line 514, in _execute_on_connection
2024-05-21 16:21:46     return connection._execute_clauseelement(
2024-05-21 16:21:46            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 1644, in _execute_clauseelement
2024-05-21 16:21:46     ret = self._execute_context(
2024-05-21 16:21:46           ^^^^^^^^^^^^^^^^^^^^^^
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 1850, in _execute_context
2024-05-21 16:21:46     return self._exec_single_context(
2024-05-21 16:21:46            ^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 1990, in _exec_single_context
2024-05-21 16:21:46     self._handle_dbapi_exception(
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 2357, in _handle_dbapi_exception
2024-05-21 16:21:46     raise sqlalchemy_exception.with_traceback(exc_info[2]) from e
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 1971, in _exec_single_context
2024-05-21 16:21:46     self.dialect.do_execute(
2024-05-21 16:21:46   File "/usr/local/lib/python3.12/site-packages/sqlalchemy/engine/default.py", line 919, in do_execute
2024-05-21 16:21:46     cursor.execute(statement, parameters)
2024-05-21 16:21:46 sqlalchemy.exc.IntegrityError: (sqlite3.IntegrityError) FOREIGN KEY constraint failed
2024-05-21 16:21:46 [SQL: INSERT INTO time_logs (user_id, timestamp, status) VALUES (?, ?, ?)]
2024-05-21 16:21:46 [parameters: (486320094390255637, '2024-05-21 16:21:46.789919', 'start')]
2024-05-21 16:21:46 (Background on this error at: https://sqlalche.me/e/20/gkpj)
lCyou commented 5 months ago

最初にエラーが発生してからこのクエリがORMでスタックしているので正常な処理でも一番最初に起きた上記のクエリが実行されるので後続のクエリが実行されていない。 これはセッションが同一なものでトランザクションが解決しないからと考えられる。 これの解決には公式にも書いてある通り，一度Session.rollback()をして未解決のトランザクションをセッションから解消する必要がある

lCyou commented 5 months ago

2024-05-21 22:51:12 discord.app_commands.errors.CommandInvokeError: Command 'register' raised an exception: PendingRollbackError: This Session's transaction has been rolled back due to a previous exception during flush. To begin a new transaction with this Session, first issue Session.rollback(). Original exception was: (sqlite3.IntegrityError) FOREIGN KEY constraint failed 2024-05-21 22:51:12 [SQL: INSERT INTO time_logs (user_id, timestamp, status) VALUES (?, ?, ?)] 2024-05-21 22:51:12 [parameters: (486320094390255637, '2024-05-21 16:21:46.789919', 'start')] 2024-05-21 22:51:12 (Background on this error at: https://sqlalche.me/e/20/gkpj) (Background on this error at: https://sqlalche.me/e/20/7s2a)

lCyou commented 5 months ago

今回はVCに未登録の人が入ってから全てトランザクションを正常に扱えていなかったため発生した。 未登録の人がVCに入っても大丈夫なようにfixしたのを対応とする。https://github.com/kindai-ecl/discord-bot-commit-time/pull/8

これ以外にSQLalchemyのトランザクションの設定やZabbixによる監視を考えてもいい？（過剰かもしれないが）