search

xmtp / libxmtp

MIT License
33 stars 13 forks source link

Return existing group on duplicate welcome message #855

Closed cameronvoell closed 1 week ago

cameronvoell commented 1 week ago

Related to https://github.com/xmtp/xmtp-react-native/issues/427

cameronvoell commented 1 week ago

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` ```
cameronvoell commented 1 week ago

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.