Return existing group on duplicate welcome message #855

cameronvoell · 2024-06-21T02:01:10Z

…come id

cameronvoell · 2024-06-21T14:13:22Z

The new repro test passes about 3/10 times.
Before the fix it passed 0/10 times.

When it passes I see that that we are entering the code of the fix, and returning an existing group after failing to process a welcome_id(bc group already exists).

When it fails I see db locking errors. See logs below

here is a log of the new test passing:

logs

warning: Patch `openssl-sys v0.9.92 (https://github.com/xmtp/rust-openssl.git?branch=clone-v0.9.92#00dacb93)` was not used in the crate graph.
Check that the patched package version and available features are compatible
with the dependency requirements. If the patch has a different version from
what is locked in the Cargo.lock file, run `cargo update` to use the new
version. This may also occur with an optional dependency that is not enabled.
    Finished `test` profile [unoptimized + debuginfo] target(s) in 0.29s
     Running unittests src/lib.rs (target/debug/deps/xmtpv3-7af2e052c28a47b0)

running 1 test
[INFO][t:27583595]: [libxmtp] Logger initialized
[INFO][t:27583595]: [libxmtp] Creating API client for host: http://localhost:5556, isSecure: false
[INFO][t:27583595]: [libxmtp] Creating message store with path: Some("/var/folders/04/0j7sl4v138zcg6dlvkn8sshr0000gn/T//mLG54pT2VEnHPEWdE4615AEO.db3") and encryption key: false
[INFO][t:27583595]: [libxmtp] Setting up DB connection pool
[INFO][t:27583595]: [libxmtp] Running DB migrations
[INFO][t:27583595]: [libxmtp] Migrations successful
[INFO][t:27583595]: [libxmtp] Creating XMTP client
[INFO][t:27583595]: [libxmtp] Initializing identity
[INFO][t:27583595]: [libxmtp] Getting inbox_ids for account addresses: ["0x0e7c90d3a9cbb4922cff81c1dd6966b797edaf67"]
[INFO][t:27583595]: [libxmtp] Provided Signer: 19fbca7ec102a34f3daa972f46db75b377ab592add2dafe05eb7a4eec990f355
[INFO][t:27583595]: [libxmtp] Missing Signatures: [Address("0x0e7c90d3a9cbb4922cff81c1dd6966b797edaf67"), Installation([25, 251, 202, 126, 193, 2, 163, 79, 61, 170, 151, 47, 70, 219, 117, 179, 119, 171, 89, 42, 221, 45, 175, 224, 94, 183, 164, 238, 201, 144, 243, 85])]
[INFO][t:27583595]: [libxmtp] Created XMTP client for inbox_id: 8f42c8c702f0c726f0369bae399b9a34a5053905207db201f9c5faffde64878f
[INFO][t:27583595]: [libxmtp] Provided Signer: 0x0e7c90d3a9cbb4922cff81c1dd6966b797edaf67
[INFO][t:27583595]: [libxmtp] Missing Signatures: [Address("0x0e7c90d3a9cbb4922cff81c1dd6966b797edaf67")]
[INFO][t:27583595]: [libxmtp] registering identity
[INFO][t:27583595]: [libxmtp] Creating API client for host: http://localhost:5556, isSecure: false
[INFO][t:27583595]: [libxmtp] Creating message store with path: Some("/var/folders/04/0j7sl4v138zcg6dlvkn8sshr0000gn/T//d9KD7qKHLJqIZkDPLRjRjUFj.db3") and encryption key: false
[INFO][t:27583595]: [libxmtp] Setting up DB connection pool
[INFO][t:27583595]: [libxmtp] Running DB migrations
[INFO][t:27583595]: [libxmtp] Migrations successful
[INFO][t:27583595]: [libxmtp] Creating XMTP client
[INFO][t:27583595]: [libxmtp] Initializing identity
[INFO][t:27583595]: [libxmtp] Getting inbox_ids for account addresses: ["0x1db52df4649ed8714317735ce847099d3f220b09"]
[INFO][t:27583595]: [libxmtp] Provided Signer: 3f2321f3d2cc4a0db4e4cf91dbd1442424aaf27a5fe1efe265bd3ff6158c4bd5
[INFO][t:27583595]: [libxmtp] Missing Signatures: [Address("0x1db52df4649ed8714317735ce847099d3f220b09"), Installation([63, 35, 33, 243, 210, 204, 74, 13, 180, 228, 207, 145, 219, 209, 68, 36, 36, 170, 242, 122, 95, 225, 239, 226, 101, 189, 63, 246, 21, 140, 75, 213])]
[INFO][t:27583595]: [libxmtp] Created XMTP client for inbox_id: 9a7dfc7c6b26d783901dabf8b050b1edd2b56d195b0c198314506889e7000c3f
[INFO][t:27583595]: [libxmtp] Provided Signer: 0x1db52df4649ed8714317735ce847099d3f220b09
[INFO][t:27583595]: [libxmtp] Missing Signatures: [Address("0x1db52df4649ed8714317735ce847099d3f220b09")]
[INFO][t:27583595]: [libxmtp] registering identity
[INFO][t:27583595]: [libxmtp] creating group with account addresses: 0x1db52df4649ed8714317735ce847099d3f220b09
[INFO][t:27583595]: [libxmtp] creating group
[INFO][t:27583595]: [libxmtp] Getting inbox_ids for account addresses: ["0x1db52df4649ed8714317735ce847099d3f220b09"]
[INFO][t:27583595]: [libxmtp] old group membership: {"8f42c8c702f0c726f0369bae399b9a34a5053905207db201f9c5faffde64878f": 0}
[INFO][t:27583595]: [libxmtp] updated group membership: {"8f42c8c702f0c726f0369bae399b9a34a5053905207db201f9c5faffde64878f": 111, "9a7dfc7c6b26d783901dabf8b050b1edd2b56d195b0c198314506889e7000c3f": 112}
[INFO][t:27583595]: [libxmtp] Getting installation diff. Old: GroupMembership { members: {"8f42c8c702f0c726f0369bae399b9a34a5053905207db201f9c5faffde64878f": 0} }. New GroupMembership { members: {"8f42c8c702f0c726f0369bae399b9a34a5053905207db201f9c5faffde64878f": 111, "9a7dfc7c6b26d783901dabf8b050b1edd2b56d195b0c198314506889e7000c3f": 112} }
[INFO][t:27583595]: [libxmtp] [8f42c8c702f0c726f0369bae399b9a34a5053905207db201f9c5faffde64878f] published intent [1] of type [UpdateGroupMembership]
[INFO][t:27583595]: [libxmtp] client [8f42c8c702f0c726f0369bae399b9a34a5053905207db201f9c5faffde64878f] is  about to process own envelope [195]
[INFO][t:27583595]: [libxmtp] envelope [195] is equal to intent [1]
[INFO][t:27583595]: [libxmtp] [8f42c8c702f0c726f0369bae399b9a34a5053905207db201f9c5faffde64878f] Validating commit for intent 1. Message timestamp: 1718978359121174000
[INFO][t:27583595]: [libxmtp] Group context extensions proposal found: GroupMembership { members: {"8f42c8c702f0c726f0369bae399b9a34a5053905207db201f9c5faffde64878f": 111, "9a7dfc7c6b26d783901dabf8b050b1edd2b56d195b0c198314506889e7000c3f": 112} }
[INFO][t:27583595]: [libxmtp] Getting installation diff. Old: GroupMembership { members: {"8f42c8c702f0c726f0369bae399b9a34a5053905207db201f9c5faffde64878f": 0} }. New GroupMembership { members: {"8f42c8c702f0c726f0369bae399b9a34a5053905207db201f9c5faffde64878f": 111, "9a7dfc7c6b26d783901dabf8b050b1edd2b56d195b0c198314506889e7000c3f": 112} }
[INFO][t:27583595]: [libxmtp] [8f42c8c702f0c726f0369bae399b9a34a5053905207db201f9c5faffde64878f] merging pending commit for intent 1
[INFO][t:27583595]: [libxmtp] 8f42c8c702f0c726f0369bae399b9a34a5053905207db201f9c5faffde64878f: Storing a transcript message with 1 members added and 0 members removed and 0 metadata changes
[INFO][t:27583599]: [libxmtp] Received conversation streaming payload
[INFO][t:27583600]: [libxmtp] Received conversation streaming payload
received new conversation
Found existing group by welcome id
[INFO][t:27583599]: [libxmtp] closing stream
[INFO][t:27583600]: [libxmtp] Received message streaming payload
[INFO][t:27583600]: [libxmtp] client [9a7dfc7c6b26d783901dabf8b050b1edd2b56d195b0c198314506889e7000c3f]  is about to process streamed envelope: [195]
[INFO][t:27583600]: [libxmtp] current epoch for [9a7dfc7c6b26d783901dabf8b050b1edd2b56d195b0c198314506889e7000c3f] in process_stream_entry() is Epoch: [1]
[INFO][t:27583600]: [libxmtp] client [9a7dfc7c6b26d783901dabf8b050b1edd2b56d195b0c198314506889e7000c3f] is about to process external envelope [195]
[ERROR][t:27583600]: [libxmtp] Wrong Epoch: message.epoch() 0 != 1 self.group_context().epoch()
[INFO][t:27583600]: [libxmtp] [9a7dfc7c6b26d783901dabf8b050b1edd2b56d195b0c198314506889e7000c3f] syncing group
[INFO][t:27583600]: [libxmtp] current epoch for [9a7dfc7c6b26d783901dabf8b050b1edd2b56d195b0c198314506889e7000c3f] in sync() is Epoch: [1]
[INFO][t:27583600]: [libxmtp] client [9a7dfc7c6b26d783901dabf8b050b1edd2b56d195b0c198314506889e7000c3f] is about to process external envelope [195]
[ERROR][t:27583600]: [libxmtp] Wrong Epoch: message.epoch() 0 != 1 self.group_context().epoch()
[ERROR][t:27583600]: [libxmtp] Message processing errors: [OpenMlsProcessMessage(ValidationError(WrongEpoch))]
[ERROR][t:27583600]: [libxmtp] receive error ReceiveErrors([OpenMlsProcessMessage(ValidationError(WrongEpoch))])
[INFO][t:27583600]: [libxmtp] Skipped message streaming payload
[INFO][t:27583595]: [libxmtp] [8f42c8c702f0c726f0369bae399b9a34a5053905207db201f9c5faffde64878f] published intent [2] of type [SendMessage]
[INFO][t:27583597]: [libxmtp] Received message streaming payload
[INFO][t:27583597]: [libxmtp] client [9a7dfc7c6b26d783901dabf8b050b1edd2b56d195b0c198314506889e7000c3f]  is about to process streamed envelope: [196]
[INFO][t:27583597]: [libxmtp] current epoch for [9a7dfc7c6b26d783901dabf8b050b1edd2b56d195b0c198314506889e7000c3f] in process_stream_entry() is Epoch: [1]
[INFO][t:27583597]: [libxmtp] client [9a7dfc7c6b26d783901dabf8b050b1edd2b56d195b0c198314506889e7000c3f] is about to process external envelope [196]
[INFO][t:27583597]: [libxmtp] [9a7dfc7c6b26d783901dabf8b050b1edd2b56d195b0c198314506889e7000c3f] extracted sender inbox id: 8f42c8c702f0c726f0369bae399b9a34a5053905207db201f9c5faffde64878f
[INFO][t:27583597]: [libxmtp] [9a7dfc7c6b26d783901dabf8b050b1edd2b56d195b0c198314506889e7000c3f] decoding application message
Got a message
[INFO][t:27583597]: [libxmtp] Received: hello1
[INFO][t:27583597]: [libxmtp] closing stream
[INFO][t:27583600]: [libxmtp] closing stream
[INFO][t:27583600]: [libxmtp] closing stream
test mls::tests::test_stream_groups_gets_callback_when_streaming_messages ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 21 filtered out; finished in 4.18s

     Running unittests src/bin.rs (target/debug/deps/ffi_uniffi_bindgen-4e4e5566cf2375ca)

running 0 tests

test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

     Running tests/test_generated_bindings.rs (target/debug/deps/test_generated_bindings-b5f934fd814ccdb0)

running 0 tests

test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 1 filtered out; finished in 0.00s

here is a log of the new test failing:

logs

warning: Patch `openssl-sys v0.9.92 (https://github.com/xmtp/rust-openssl.git?branch=clone-v0.9.92#00dacb93)` was not used in the crate graph.
Check that the patched package version and available features are compatible
with the dependency requirements. If the patch has a different version from
what is locked in the Cargo.lock file, run `cargo update` to use the new
version. This may also occur with an optional dependency that is not enabled.
    Finished `test` profile [unoptimized + debuginfo] target(s) in 0.30s
     Running unittests src/lib.rs (target/debug/deps/xmtpv3-7af2e052c28a47b0)

running 1 test
[INFO][t:27582768]: [libxmtp] Logger initialized
[INFO][t:27582768]: [libxmtp] Creating API client for host: http://localhost:5556, isSecure: false
[INFO][t:27582768]: [libxmtp] Creating message store with path: Some("/var/folders/04/0j7sl4v138zcg6dlvkn8sshr0000gn/T//fi1hLQx0yXwnnmf1GYLYqPRy.db3") and encryption key: false
[INFO][t:27582768]: [libxmtp] Setting up DB connection pool
[INFO][t:27582768]: [libxmtp] Running DB migrations
[INFO][t:27582768]: [libxmtp] Migrations successful
[INFO][t:27582768]: [libxmtp] Creating XMTP client
[INFO][t:27582768]: [libxmtp] Initializing identity
[INFO][t:27582768]: [libxmtp] Getting inbox_ids for account addresses: ["0xc2188424ce1ff549bbfbbc7a738c80ea510b8ef9"]
[INFO][t:27582768]: [libxmtp] Provided Signer: 99015e75245c58b6af13ff8ec0affa579a2c0ce102bfd5ac41d33250416eaf67
[INFO][t:27582768]: [libxmtp] Missing Signatures: [Installation([153, 1, 94, 117, 36, 92, 88, 182, 175, 19, 255, 142, 192, 175, 250, 87, 154, 44, 12, 225, 2, 191, 213, 172, 65, 211, 50, 80, 65, 110, 175, 103]), Address("0xc2188424ce1ff549bbfbbc7a738c80ea510b8ef9")]
[INFO][t:27582768]: [libxmtp] Created XMTP client for inbox_id: 1aa733c956e5d2a565f3ba2a0a12e6933f875161a70e4575af08da5b5ea7c4c7
[INFO][t:27582768]: [libxmtp] Provided Signer: 0xc2188424ce1ff549bbfbbc7a738c80ea510b8ef9
[INFO][t:27582768]: [libxmtp] Missing Signatures: [Address("0xc2188424ce1ff549bbfbbc7a738c80ea510b8ef9")]
[INFO][t:27582768]: [libxmtp] registering identity
[INFO][t:27582768]: [libxmtp] Creating API client for host: http://localhost:5556, isSecure: false
[INFO][t:27582768]: [libxmtp] Creating message store with path: Some("/var/folders/04/0j7sl4v138zcg6dlvkn8sshr0000gn/T//JFydYyWT7yQFAKTPZ23ED2sK.db3") and encryption key: false
[INFO][t:27582768]: [libxmtp] Setting up DB connection pool
[INFO][t:27582768]: [libxmtp] Running DB migrations
[INFO][t:27582768]: [libxmtp] Migrations successful
[INFO][t:27582768]: [libxmtp] Creating XMTP client
[INFO][t:27582768]: [libxmtp] Initializing identity
[INFO][t:27582768]: [libxmtp] Getting inbox_ids for account addresses: ["0x6759216b9fa1e46be86d689882da8f2f0995e63b"]
[INFO][t:27582768]: [libxmtp] Provided Signer: 2131254851672fd26562756b3ec52104f885accd6a2048b6cc2f7d0ed2ce6149
[INFO][t:27582768]: [libxmtp] Missing Signatures: [Address("0x6759216b9fa1e46be86d689882da8f2f0995e63b"), Installation([33, 49, 37, 72, 81, 103, 47, 210, 101, 98, 117, 107, 62, 197, 33, 4, 248, 133, 172, 205, 106, 32, 72, 182, 204, 47, 125, 14, 210, 206, 97, 73])]
[INFO][t:27582768]: [libxmtp] Created XMTP client for inbox_id: 53bc6da398536a12c7ac4266d38283a9c29a4745addc6c37aee8ace78dc60302
[INFO][t:27582768]: [libxmtp] Provided Signer: 0x6759216b9fa1e46be86d689882da8f2f0995e63b
[INFO][t:27582768]: [libxmtp] Missing Signatures: [Address("0x6759216b9fa1e46be86d689882da8f2f0995e63b")]
[INFO][t:27582768]: [libxmtp] registering identity
[INFO][t:27582768]: [libxmtp] creating group with account addresses: 0x6759216b9fa1e46be86d689882da8f2f0995e63b
[INFO][t:27582768]: [libxmtp] creating group
[INFO][t:27582768]: [libxmtp] Getting inbox_ids for account addresses: ["0x6759216b9fa1e46be86d689882da8f2f0995e63b"]
[INFO][t:27582768]: [libxmtp] old group membership: {"1aa733c956e5d2a565f3ba2a0a12e6933f875161a70e4575af08da5b5ea7c4c7": 0}
[INFO][t:27582768]: [libxmtp] updated group membership: {"1aa733c956e5d2a565f3ba2a0a12e6933f875161a70e4575af08da5b5ea7c4c7": 107, "53bc6da398536a12c7ac4266d38283a9c29a4745addc6c37aee8ace78dc60302": 108}
[INFO][t:27582768]: [libxmtp] Getting installation diff. Old: GroupMembership { members: {"1aa733c956e5d2a565f3ba2a0a12e6933f875161a70e4575af08da5b5ea7c4c7": 0} }. New GroupMembership { members: {"1aa733c956e5d2a565f3ba2a0a12e6933f875161a70e4575af08da5b5ea7c4c7": 107, "53bc6da398536a12c7ac4266d38283a9c29a4745addc6c37aee8ace78dc60302": 108} }
[INFO][t:27582768]: [libxmtp] [1aa733c956e5d2a565f3ba2a0a12e6933f875161a70e4575af08da5b5ea7c4c7] published intent [1] of type [UpdateGroupMembership]
[INFO][t:27582768]: [libxmtp] client [1aa733c956e5d2a565f3ba2a0a12e6933f875161a70e4575af08da5b5ea7c4c7] is  about to process own envelope [191]
[INFO][t:27582768]: [libxmtp] envelope [191] is equal to intent [1]
[INFO][t:27582768]: [libxmtp] [1aa733c956e5d2a565f3ba2a0a12e6933f875161a70e4575af08da5b5ea7c4c7] Validating commit for intent 1. Message timestamp: 1718978309206206000
[INFO][t:27582768]: [libxmtp] Group context extensions proposal found: GroupMembership { members: {"53bc6da398536a12c7ac4266d38283a9c29a4745addc6c37aee8ace78dc60302": 108, "1aa733c956e5d2a565f3ba2a0a12e6933f875161a70e4575af08da5b5ea7c4c7": 107} }
[INFO][t:27582768]: [libxmtp] Getting installation diff. Old: GroupMembership { members: {"1aa733c956e5d2a565f3ba2a0a12e6933f875161a70e4575af08da5b5ea7c4c7": 0} }. New GroupMembership { members: {"53bc6da398536a12c7ac4266d38283a9c29a4745addc6c37aee8ace78dc60302": 108, "1aa733c956e5d2a565f3ba2a0a12e6933f875161a70e4575af08da5b5ea7c4c7": 107} }
[INFO][t:27582768]: [libxmtp] [1aa733c956e5d2a565f3ba2a0a12e6933f875161a70e4575af08da5b5ea7c4c7] merging pending commit for intent 1
[INFO][t:27582768]: [libxmtp] 1aa733c956e5d2a565f3ba2a0a12e6933f875161a70e4575af08da5b5ea7c4c7: Storing a transcript message with 1 members added and 0 members removed and 0 metadata changes
[INFO][t:27582770]: [libxmtp] Received conversation streaming payload
[INFO][t:27582769]: [libxmtp] Received conversation streaming payload
[ERROR][t:27582771]: [libxmtp] Error processing stream entry: Generic("client: storage error: Diesel result error: database is locked")
received new conversation
[INFO][t:27582768]: [libxmtp] [1aa733c956e5d2a565f3ba2a0a12e6933f875161a70e4575af08da5b5ea7c4c7] published intent [2] of type [SendMessage]
thread 'mls::tests::test_stream_groups_gets_callback_when_streaming_messages' panicked at src/mls.rs:1833:9:
assertion `left == right` failed
  left: 0
 right: 1
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
[INFO][t:27582771]: [libxmtp] closing stream
[INFO][t:27582769]: [libxmtp] closing stream
[INFO][t:27582770]: [libxmtp] closing stream
test mls::tests::test_stream_groups_gets_callback_when_streaming_messages ... FAILED

failures:

failures:
    mls::tests::test_stream_groups_gets_callback_when_streaming_messages

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 21 filtered out; finished in 4.16s

error: test failed, to rerun pass `--lib`

xmtp_mls/src/storage/encrypted_store/group.rs

xmtp_mls/src/subscriptions.rs

cameronvoell · 2024-06-22T00:22:14Z

heads up @richardhuaaa, I added [ignore] for the test_can_stream_and_update_name_without_forking_group test in this PR since it seems to show database locked intermittently on CI as well.

on streamed welcome error, check for existing group with matching wel…

f16d147

…come id

cameronvoell force-pushed the cv/keep-streaming-after-we-skip-extra-welcome-message branch from 70414d9 to f16d147 Compare June 21, 2024 13:45

cameronvoell added 2 commits June 21, 2024 07:00

Added extra log message

d2d4aef

lint fix

a797f12

cameronvoell mentioned this pull request Jun 21, 2024

Bug: Stream groups does not get callback when streaming all messages xmtp/xmtp-react-native#427

Closed

cameronvoell added 2 commits June 21, 2024 16:35

made test ignore for now, update seems to improve behavior overall

a7111ec

replace println with log message

24cd2ad

cameronvoell marked this pull request as ready for review June 21, 2024 23:40

cameronvoell requested a review from a team as a code owner June 21, 2024 23:40

richardhuaaa approved these changes Jun 21, 2024

View reviewed changes

xmtp_mls/src/storage/encrypted_store/group.rs Outdated Show resolved Hide resolved

xmtp_mls/src/subscriptions.rs Outdated Show resolved Hide resolved

cameronvoell added 3 commits June 21, 2024 16:48

log an error if more than one group found with same welcome_id

f7f0c74

added welcome id to log message

6dc2001

ignore fork test until it passes consistently

1a500e3

cameronvoell merged commit ec0fb83 into main Jun 22, 2024
7 checks passed

cameronvoell deleted the cv/keep-streaming-after-we-skip-extra-welcome-message branch June 22, 2024 00:28

bwcDvorak added the V3 Followups label Jun 24, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Return existing group on duplicate welcome message #855

Return existing group on duplicate welcome message #855

cameronvoell commented Jun 21, 2024 •

edited

Loading

cameronvoell commented Jun 21, 2024 •

edited

Loading

cameronvoell commented Jun 22, 2024 •

edited

Loading

Return existing group on duplicate welcome message #855

Return existing group on duplicate welcome message #855

Conversation

cameronvoell commented Jun 21, 2024 • edited Loading

cameronvoell commented Jun 21, 2024 • edited Loading

cameronvoell commented Jun 22, 2024 • edited Loading

cameronvoell commented Jun 21, 2024 •

edited

Loading

cameronvoell commented Jun 21, 2024 •

edited

Loading

cameronvoell commented Jun 22, 2024 •

edited

Loading