Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Bug: Database Locked errors in downstream SDKs when sending consecutive messages #1480

Open
cameronvoell opened this issue Jan 8, 2025 · 0 comments
Open

Bug: Database Locked errors in downstream SDKs when sending consecutive messages #1480

cameronvoell opened this issue Jan 8, 2025 · 0 comments
Labels
bug Something isn't working

Comments

@cameronvoell
Copy link
Contributor

Describe the bug

I started noticing some flaky tests in xmtp-android, xmtp-ios, and xmtp-react-native where consecutive messages sent from the same person in the same group would lead to a DB locked error.

React Native test code:

test('can message in a group', async () => {
  const [alixClient, boClient] = await createClients(2)

  // alix creates a group
  const alixGroup = await alixClient.conversations.newGroup([
    boClient.address,
  ])

  // alix can send messages
  await alixGroup.send('hello, world')

  // Database is locked error intermittently on the second send
  await alixGroup.send('gm')

  return true
})

log of DB Lock Error:

01-08 14:27:14.348 18494 18682 V XMTPModule: sendMessage
01-08 14:27:14.349 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::encrypted_store::native: Pulling connection from pool, idle_connections=24, total_connections=25
01-08 14:27:14.349 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::encrypted_store::native: Pulling connection from pool, idle_connections=24, total_connections=25
01-08 14:27:14.349 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read Tree
01-08 14:27:14.349 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read_list ProposalQueueRefs
01-08 14:27:14.350 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read GroupContext
01-08 14:27:14.350 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read InterimTranscriptHash
01-08 14:27:14.350 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read ConfirmationTag
01-08 14:27:14.350 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read EpochSecrets
01-08 14:27:14.350 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read OwnLeafNodeIndex
01-08 14:27:14.350 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read MessageSecrets
01-08 14:27:14.350 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read ResumptionPskStore
01-08 14:27:14.350 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read MlsGroupJoinConfig
01-08 14:27:14.350 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: own_leaf_nodes
01-08 14:27:14.350 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read_list OwnLeafNodes
01-08 14:27:14.350 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read GroupState
01-08 14:27:14.350 18494 18653 D xmtpv3  : async-compat/tokio-1 sync_with_conn:receive: xmtp_mls::storage::encrypted_store::private: Transaction async being committed
01-08 14:27:14.350 18494 18653 I xmtpv3  : async-compat/tokio-1 sync_with_conn:receive: xmtp_mls::groups::mls_sync: Transaction completed successfully: process for group [005bd25d77a254d03688a9f330b6fe56] envelope cursor[33299]
01-08 14:27:14.351 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::encrypted_store::native: Pulling connection from pool, idle_connections=24, total_connections=25
01-08 14:27:14.352 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::groups: sending message inbox_id="0c3435a8b92c2a8409320c43ea6876752f04effc0970883a5c65a14498bbefa0"
01-08 14:27:14.352 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::encrypted_store::native: Pulling connection from pool, idle_connections=24, total_connections=25
01-08 14:27:14.352 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::encrypted_store::private: Transaction beginning
01-08 14:27:14.352 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::encrypted_store::private: Transaction being rolled back
01-08 14:27:14.352 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::encrypted_store::native: Pulling connection from pool, idle_connections=23, total_connections=25
01-08 14:27:14.352 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::encrypted_store::private: Transaction beginning
01-08 14:27:14.352 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::groups::intents: queued intent inbox_id="0c3435a8b92c2a8409320c43ea6876752f04effc0970883a5c65a14498bbefa0" intent_kind=SendMessage
01-08 14:27:14.354 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::encrypted_store::private: Transaction being committed
01-08 14:27:14.354 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::groups: Failed to decode message as EncodedContent: failed to decode Protobuf message: buffer underflow
01-08 14:27:14.354 18494 30078 I ReactNativeJS: 'ERROR in send()', 'Call to function \'XMTP.sendMessage\' has been rejected.\n→ Caused by: uniffi.xmtpv3.GenericException$GroupException: Group error: storage error: Diesel result error: database is locked'

Expected behavior

log when passing (same test on android, passes 25% of time)

01-08 14:39:20.113 18494 18682 V XMTPModule: sendMessage
01-08 14:39:20.116 18494 18653 D xmtpv3  : async-compat/tokio-1 sync_with_conn:receive: xmtp_mls::storage::encrypted_store::private: Transaction async being committed
01-08 14:39:20.116 18494 18653 I xmtpv3  : async-compat/tokio-1 sync_with_conn:receive: xmtp_mls::groups::mls_sync: Transaction completed successfully: process for group [ad59a091819c4d1a4e3ab7b7b2da4519] envelope cursor[33839]
01-08 14:39:20.118 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::encrypted_store::native: Pulling connection from pool, idle_connections=24, total_connections=25
01-08 14:39:20.119 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::encrypted_store::private: Transaction beginning
01-08 14:39:20.119 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::groups::intents: queued intent inbox_id="cb17c1479006372a7fabbbb6bff290918ca1d764887e314c85ed2e5ba03144c2" intent_kind=SendMessage
01-08 14:39:20.119 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::encrypted_store::native: Pulling connection from pool, idle_connections=24, total_connections=25
01-08 14:39:20.119 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read Tree
01-08 14:39:20.120 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read_list ProposalQueueRefs
01-08 14:39:20.120 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read GroupContext
01-08 14:39:20.121 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read InterimTranscriptHash
01-08 14:39:20.121 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read ConfirmationTag
01-08 14:39:20.121 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read EpochSecrets
01-08 14:39:20.121 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read OwnLeafNodeIndex
01-08 14:39:20.122 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read MessageSecrets
01-08 14:39:20.122 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read ResumptionPskStore
01-08 14:39:20.122 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read MlsGroupJoinConfig
01-08 14:39:20.122 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: own_leaf_nodes
01-08 14:39:20.122 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read_list OwnLeafNodes
01-08 14:39:20.122 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::sql_key_store: read GroupState
01-08 14:39:20.122 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::encrypted_store::private: Transaction being committed
01-08 14:39:20.122 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::groups: Failed to decode message as EncodedContent: failed to decode Protobuf message: buffer underflow
01-08 14:39:20.124 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::sql_key_store: read Tree
01-08 14:39:20.124 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::sql_key_store: read_list ProposalQueueRefs
01-08 14:39:20.124 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::sql_key_store: read GroupContext
01-08 14:39:20.124 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::sql_key_store: read InterimTranscriptHash
01-08 14:39:20.124 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::sql_key_store: read ConfirmationTag
01-08 14:39:20.124 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::sql_key_store: read EpochSecrets
01-08 14:39:20.124 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::sql_key_store: read OwnLeafNodeIndex
01-08 14:39:20.124 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::sql_key_store: read MessageSecrets
01-08 14:39:20.124 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::sql_key_store: read ResumptionPskStore
01-08 14:39:20.124 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::sql_key_store: read MlsGroupJoinConfig
01-08 14:39:20.124 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::sql_key_store: own_leaf_nodes
01-08 14:39:20.124 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::sql_key_store: read_list OwnLeafNodes
01-08 14:39:20.124 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::sql_key_store: read GroupState
01-08 14:39:20.124 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::sql_key_store: write MessageSecrets
01-08 14:39:20.127 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::encrypted_store::native: Pulling connection from pool, idle_connections=24, total_connections=25
01-08 14:39:20.128 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::groups::mls_sync: client [cb17c1479006372a7fabbbb6bff290918ca1d764887e314c85ed2e5ba03144c2] set stored intent [8] to state `published` inbox_id="cb17c1479006372a7fabbbb6bff290918ca1d764887e314c85ed2e5ba03144c2" installation_id=32b1fbf566929507e571d7b8bb32473111dc5d51d3e6f7fe52cfe38b301de56e intent.id=8 intent.kind=SendMessage group_id="ad59a091819c4d1a4e3ab7b7b2da4519"
01-08 14:39:20.128 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::storage::encrypted_store::native: Pulling connection from pool, idle_connections=24, total_connections=25
01-08 14:39:20.129 18494 18653 D xmtpv3  : async-compat/tokio-1 xmtp_mls::api::mls: sending [1] group messages inbox_id="cb17c1479006372a7fabbbb6bff290918ca1d764887e314c85ed2e5ba03144c2"
01-08 14:39:20.129 18494 18653 D xmtpv3  : async-compat/tokio-1 tower::buffer::worker: service.ready=true processing request
01-08 14:39:20.129 18494 18653 D xmtpv3  : async-compat/tokio-1 Connection{peer=Client}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(5755), flags: (0x4: END_HEADERS) }
01-08 14:39:20.129 18494 18653 D xmtpv3  : async-compat/tokio-1 Connection{peer=Client}: h2::codec::framed_write: send frame=Data { stream_id: StreamId(5755) }
01-08 14:39:20.129 18494 18653 D xmtpv3  : async-compat/tokio-1 Connection{peer=Client}: h2::codec::framed_write: send frame=Data { stream_id: StreamId(5755), flags: (0x1: END_STREAM) }
01-08 14:39:20.131 18494 18653 D xmtpv3  : async-compat/tokio-1 Connection{peer=Client}: h2::codec::framed_read: received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 273 }
01-08 14:39:20.131 18494 18653 D xmtpv3  : async-compat/tokio-1 Connection{peer=Client}: h2::codec::framed_read: received frame=Ping { ack: false, payload: [2, 4, 16, 16, 9, 14, 7, 7] }
01-08 14:39:20.131 18494 18653 D xmtpv3  : async-compat/tokio-1 Connection{peer=Client}: h2::codec::framed_write: send frame=Ping { ack: true, payload: [2, 4, 16, 16, 9, 14, 7, 7] }
01-08 14:39:20.131 18494 18653 D xmtpv3  : async-compat/tokio-1 Connection{peer=Client}: h2::codec::framed_read: received frame=Headers { stream_id: StreamId(5755), flags: (0x4: END_HEADERS) }
01-08 14:39:20.131 18494 18653 D xmtpv3  : async-compat/tokio-1 Connection{peer=Client}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(5755) }
01-08 14:39:20.131 18494 18653 D xmtpv3  : async-compat/tokio-1 Connection{peer=Client}: h2::codec::framed_read: received frame=Headers { stream_id: StreamId(5755), flags: (0x5: END_HEADERS | END_STREAM) }
01-08 14:39:20.131 18494 18653 D xmtpv3  : async-compat/tokio-1 Connection{peer=Client}: h2::codec::framed_read: received frame=Reset { stream_id: StreamId(5755), error_code: NO_ERROR }
01-08 14:39:20.131 18494 18653 I xmtpv3  : async-compat/tokio-1 xmtp_mls::groups::mls_sync: [cb17c1479006372a7fabbbb6bff290918ca1d764887e314c85ed2e5ba03144c2] published intent [8] of type [SendMessage] intent.id=8 intent.kind=SendMessage inbox_id="cb17c1479006372a7fabbbb6bff290918ca1d764887e314c85ed2e5ba03144c2" installation_id=32b1fbf566929507e571d7b8bb32473111dc5d51d3e6f7fe52cfe38b301de56e group_id="ad59a091819c4d1a4e3ab7b7b2da4519"
01-08 14:39:20.132 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::groups: sending message inbox_id="cb17c1479006372a7fabbbb6bff290918ca1d764887e314c85ed2e5ba03144c2"
01-08 14:39:20.132 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::encrypted_store::native: Pulling connection from pool, idle_connections=25, total_connections=25
01-08 14:39:20.132 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::encrypted_store::private: Transaction beginning
01-08 14:39:20.133 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::groups::intents: queued intent inbox_id="cb17c1479006372a7fabbbb6bff290918ca1d764887e314c85ed2e5ba03144c2" intent_kind=SendMessage
01-08 14:39:20.134 18494 18682 D xmtpv3  : ThreadId(20) xmtp_mls::storage::encrypted_store::private: Transaction being committed

Steps to reproduce the bug

  • Note can reproduce database locking error in xmtp-android and xmtp-ios as well when sending a second message, but have not been able to get it to happen in libxmtp when I tried in the ffi_bindings mls.rs
@cameronvoell cameronvoell added the bug Something isn't working label Jan 8, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
V3 Backlog
Status: No status
Milestone
No milestone
Development

No branches or pull requests
1 participant
@cameronvoell