search

SkygearIO / chat

Skygear Plugin - Chat SDK
Apache License 2.0
17 stars 18 forks source link

Database deadlock when messages are sent rapidly #235

Open kiootic opened 5 years ago

kiootic commented 5 years ago

Reproduction steps: send messages between two users rapidly (e.g. 0.5s)

Expected result: messages are sent normally

Actual result: sometimes error would occur:

Error Domain=SKYOperationErrorDomain Code=10000 "An unexpected error has occurred." UserInfo={SKYErrorMessage=(psycopg2.extensions.TransactionRollbackError) deadlock detected
DETAIL:  Process 1402 waits for ShareLock on transaction 33541; blocked by process 1543.
Process 1543 waits for ShareLock on transaction 33595; blocked by process 1402.
HINT:  See server log for query details.
CONTEXT:  while updating tuple (11,10) in relation "user_conversation"
 [SQL: '\n            UPDATE %(schema_name)s.user_conversation\n            SET\n                "_updated_at" = CURRENT_TIMESTAMP\n            WHERE\n                "conversation" = %(conversation_id)s\n                AND "user" = %(user_id)s\n        '] [parameters: {'schema_name': <psycopg2.extensions.AsIs object at 0x7f8ecc0a4540>, 'conversation_id': 'a1924405-71d8-4262-ae46-2baf5e175c38', 'user_id': 'c1001719-8171-44c7-9a33-d356c407b01a'}] (Background on this error at: http://sqlalche.me/e/e3q8), NSErrorFailingURLKey=http://127.0.0.1:3000/record/save, trace=Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
    context)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 509, in do_execute
    cursor.execute(statement, parameters)
psycopg2.extensions.TransactionRollbackError: deadlock detected
DETAIL:  Process 1402 waits for ShareLock on transaction 33541; blocked by process 1543.
Process 1543 waits for ShareLock on transaction 33595; blocked by process 1402.
HINT:  See server log for query details.
CONTEXT:  while updating tuple (11,10) in relation "user_conversation"

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/skygear/transmitter/common.py", line 43, in wrapper
    return dict(result=f(self, *args, **kwargs))
  File "/usr/local/lib/python3.6/site-packages/skygear/transmitter/common.py", line 102, in call_func
    return self.hook(obj, param)
  File "/usr/local/lib/python3.6/site-packages/skygear/transmitter/common.py", line 187, in hook
    returned = func(record, original_record, conn)
  File "/usr/local/lib/python3.6/site-packages/skygear/decorators.py", line 90, in hook_func
    func(record, original_record, db)
  File "chat/chat/message_handlers.py", line 336, in message_after_save_handler
    return handle_message_after_save(record, original_record, conn)
  File "chat/chat/message_handlers.py", line 193, in handle_message_after_save
    'user_id': current_user_id()
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 942, in execute
    return self._execute_text(object, multiparams, params)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1104, in _execute_text
    statement, parameters
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1200, in _execute_context
    context)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1413, in _handle_dbapi_exception
    exc_info
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 265, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb, cause=cause)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 248, in reraise
    raise value.with_traceback(tb)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
    context)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 509, in do_execute
    cursor.execute(statement, parameters)
sqlalchemy.exc.OperationalError: (psycopg2.extensions.TransactionRollbackError) deadlock detected
DETAIL:  Process 1402 waits for ShareLock on transaction 33541; blocked by process 1543.
Process 1543 waits for ShareLock on transaction 33595; blocked by process 1402.
HINT:  See server log for query details.
CONTEXT:  while updating tuple (11,10) in relation "user_conversation"
 [SQL: '\n            UPDATE %(schema_name)s.user_conversation\n            SET\n                "_updated_at" = CURRENT_TIMESTAMP\n            WHERE\n                "conversation" = %(conversation_id)s\n                AND "user" = %(user_id)s\n        '] [parameters: {'schema_name': <psycopg2.extensions.AsIs object at 0x7f8ecc0a4540>, 'conversation_id': 'a1924405-71d8-4262-ae46-2baf5e175c38', 'user_id': 'c1001719-8171-44c7-9a33-d356c407b01a'}] (Background on this error at: http://sqlalche.me/e/e3q8)
, SKYOperationErrorHTTPStatusCodeKey=200, SKYErrorName=UnexpectedError, NSLocalizedDescription=An unexpected error has occurred.}
kiootic commented 5 years ago

Also following error may occur in same situation:

Error Domain=SKYOperationErrorDomain Code=10000 "An unexpected error has occurred." UserInfo={SKYErrorMessage=QueuePool limit of size 5 overflow 10 reached, connection timed out, timeout 30 (Background on this error at: http://sqlalche.me/e/3o7r), NSErrorFailingURLKey=http://127.0.0.1:3000/chat/mark_as_read, trace=Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/skygear/transmitter/common.py", line 43, in wrapper
    return dict(result=f(self, *args, **kwargs))
  File "/usr/local/lib/python3.6/site-packages/skygear/transmitter/common.py", line 100, in call_func
    return self.op(obj, param.get('args', {}))
  File "/usr/local/lib/python3.6/site-packages/skygear/transmitter/common.py", line 181, in op
    return serialize_value(func(*args, **kwargs))
  File "chat/chat/receipt_handlers.py", line 275, in mark_as_read_lambda
    return handle_mark_as_read(arg)
  File "chat/chat/receipt_handlers.py", line 49, in handle_mark_as_read
    mark_messages(message_ids, True, True)
  File "chat/chat/receipt_handlers.py", line 107, in mark_messages
    __update_and_notify_messages(new_message_ids)
  File "chat/chat/receipt_handlers.py", line 235, in __update_and_notify_messages
    message.notifyParticipants()
  File "chat/chat/message.py", line 105, in notifyParticipants
    self)
  File "chat/chat/pubsub.py", line 33, in _publish_record_event
    'record': serialize_record(record)
  File "chat/chat/pubsub.py", line 14, in _publish_event
    channel_names = _get_channels_by_user_ids(user_ids)
  File "chat/chat/utils.py", line 21, in _get_channels_by_user_ids
    with db.conn() as conn:
  File "/usr/local/lib/python3.6/contextlib.py", line 81, in __enter__
    return next(self.gen)
  File "/usr/local/lib/python3.6/site-packages/skygear/utils/db.py", line 120, in conn
    with _get_engine().begin() as conn:
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1992, in begin
    conn = self.contextual_connect(close_with_result=close_with_result)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 2123, in contextual_connect
    self._wrap_pool_connect(self.pool.connect, None),
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 2158, in _wrap_pool_connect
    return fn()
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/pool.py", line 403, in connect
    return _ConnectionFairy._checkout(self)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/pool.py", line 791, in _checkout
    fairy = _ConnectionRecord.checkout(pool)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/pool.py", line 532, in checkout
    rec = pool._do_get()
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/pool.py", line 1189, in _do_get
    (self.size(), self.overflow(), self._timeout), code="3o7r")
sqlalchemy.exc.TimeoutError: QueuePool limit of size 5 overflow 10 reached, connection timed out, timeout 30 (Background on this error at: http://sqlalche.me/e/3o7r)
, SKYOperationErrorHTTPStatusCodeKey=500, SKYErrorName=UnexpectedError, NSLocalizedDescription=An unexpected error has occurred.}
AdrianM commented 4 years ago

Hi, we have the same issue on our on-premise setup (skygear + skygear chat, 1.7.X). Is there some news about this issue or a possible solution?