Test

epoch_in_stream

running 1 test
2025-02-04T22:35:32.676472Z  INFO xmtp_mls::storage::encrypted_store: Setting up DB connection pool
2025-02-04T22:35:32.676551Z DEBUG xmtp_mls::storage::encrypted_store::sqlcipher_connection: db @ [/tmp/0fsrwvAdW7imRM2G11uZTmJJ.db3] exists? [false]
2025-02-04T22:35:32.676921Z DEBUG xmtp_mls::storage::encrypted_store::sqlcipher_connection: migrating sqlcipher db=[/tmp/0fsrwvAdW7imRM2G11uZTmJJ.db3] to plaintext header with salt=[/tmp/0fsrwvAdW7imRM2G11uZTmJJ.db3.sqlcipher_salt]
2025-02-04T22:35:32.677894Z DEBUG xmtp_mls::storage::encrypted_store::sqlcipher_connection: writing salt to file
2025-02-04T22:35:32.680728Z  INFO xmtp_mls::storage::encrypted_store::sqlcipher_connection: Sqlite cipher_version=Some("4.5.7 community"), cipher_provider_version="OpenSSL 3.4.0 22 Oct 2024"
2025-02-04T22:35:32.680756Z DEBUG xmtp_mls::storage::encrypted_store::sqlcipher_connection: SQLCipher Database validated.
2025-02-04T22:35:32.681030Z  INFO xmtp_mls::storage::encrypted_store::private: Running DB migrations
2025-02-04T22:35:32.692084Z  INFO xmtp_mls::storage::encrypted_store::private: sqlite_version=3.45.3
2025-02-04T22:35:32.692098Z  INFO xmtp_mls::storage::encrypted_store::private: Migrations successful
2025-02-04T22:35:32.817698Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:32.817823Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being committed
2025-02-04T22:35:32.977562Z  INFO xmtp_mls::storage::encrypted_store: Setting up DB connection pool
2025-02-04T22:35:32.977585Z DEBUG xmtp_mls::storage::encrypted_store::sqlcipher_connection: db @ [/tmp/jCKh4cDxYaVQSWVKt5asE83A.db3] exists? [false]
2025-02-04T22:35:32.977714Z DEBUG xmtp_mls::storage::encrypted_store::sqlcipher_connection: migrating sqlcipher db=[/tmp/jCKh4cDxYaVQSWVKt5asE83A.db3] to plaintext header with salt=[/tmp/jCKh4cDxYaVQSWVKt5asE83A.db3.sqlcipher_salt]
2025-02-04T22:35:32.977940Z DEBUG xmtp_mls::storage::encrypted_store::sqlcipher_connection: writing salt to file
2025-02-04T22:35:32.980748Z  INFO xmtp_mls::storage::encrypted_store::sqlcipher_connection: Sqlite cipher_version=Some("4.5.7 community"), cipher_provider_version="OpenSSL 3.4.0 22 Oct 2024"
2025-02-04 17:35:32.980: sqlcipher_set_log: set log to stderr
2025-02-04T22:35:32.980799Z DEBUG xmtp_mls::storage::encrypted_store::sqlcipher_connection: SQLCipher Database validated.
2025-02-04T22:35:32.981080Z  INFO xmtp_mls::storage::encrypted_store::private: Running DB migrations
2025-02-04T22:35:32.991920Z  INFO xmtp_mls::storage::encrypted_store::private: sqlite_version=3.45.3
2025-02-04T22:35:32.991945Z  INFO xmtp_mls::storage::encrypted_store::private: Migrations successful
2025-02-04T22:35:33.084933Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.085056Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being committed
2025-02-04T22:35:33.153819Z DEBUG stream_all_messages: xmtp_mls::subscriptions: stream all messages
2025-02-04T22:35:33.180381Z DEBUG stream_all_messages: xmtp_mls::subscriptions::stream_conversations: Setting up conversation stream cursor = 0
2025-02-04T22:35:33.203776Z DEBUG stream_all_messages: xmtp_mls::subscriptions::stream_messages: setting up messages subscription
2025-02-04T22:35:33.284343Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.284675Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being committed
2025-02-04T22:35:33.297656Z DEBUG xmtp_mls::storage::encrypted_store::association_state: Wrote association state to cache: f04370cfd8e7f50a35c5fff7e02a375cb7c2b0f134c58fc59097e6b0958763b5 38788
2025-02-04T22:35:33.309418Z DEBUG xmtp_mls::storage::encrypted_store::association_state: Wrote association state to cache: d390776e49bf17bd9dc6b91a2b5859dbfb7b8a6de07bab32f49640b2603f417e 38787
2025-02-04T22:35:33.410292Z DEBUG xmtp_mls::storage::encrypted_store::association_state: Loaded association state from cache: f04370cfd8e7f50a35c5fff7e02a375cb7c2b0f134c58fc59097e6b0958763b5 38788
2025-02-04T22:35:33.410391Z DEBUG xmtp_mls::storage::encrypted_store::association_state: Loaded association state from cache: d390776e49bf17bd9dc6b91a2b5859dbfb7b8a6de07bab32f49640b2603f417e 38787
2025-02-04T22:35:33.410488Z DEBUG xmtp_mls::storage::encrypted_store::association_state: Loaded association state from cache: d390776e49bf17bd9dc6b91a2b5859dbfb7b8a6de07bab32f49640b2603f417e 38787
2025-02-04T22:35:33.410528Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.411605Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being committed
2025-02-04T22:35:33.437462Z  INFO xmtp_mls::subscriptions::stream_conversations: Trying to process streamed welcome
2025-02-04T22:35:33.499957Z DEBUG xmtp_mls::storage::encrypted_store::association_state: Wrote association state to cache: f04370cfd8e7f50a35c5fff7e02a375cb7c2b0f134c58fc59097e6b0958763b5 38788
2025-02-04T22:35:33.511578Z DEBUG xmtp_mls::storage::encrypted_store::association_state: Wrote association state to cache: d390776e49bf17bd9dc6b91a2b5859dbfb7b8a6de07bab32f49640b2603f417e 38787
2025-02-04T22:35:33.511627Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.512069Z  INFO xmtp_mls::storage::encrypted_store::group: Trying to insert group
2025-02-04T22:35:33.512260Z  INFO xmtp_mls::storage::encrypted_store::group: Group is inserted
2025-02-04T22:35:33.512434Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being committed
2025-02-04T22:35:33.512947Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.513224Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being committed
2025-02-04T22:35:33.513547Z DEBUG xmtp_mls::subscriptions::stream_conversations: finished processing with group 3ca0a0a486e65600b9dbcb7813f0bc70
2025-02-04T22:35:33.513570Z DEBUG xmtp_mls::subscriptions::stream_messages: begin establishing new message stream to include group_id=3ca0a0a486e65600b9dbcb7813f0bc70
2025-02-04T22:35:33.537544Z DEBUG xmtp_mls::subscriptions::stream_messages: added group_id=3ca0a0a486e65600b9dbcb7813f0bc70 at cursor=1 to messages stream
2025-02-04T22:35:33.538448Z DEBUG xmtp_mls::subscriptions::stream_messages: client inbox_id=[f04370cfd8e7f50a35c5fff7e02a375cb7c2b0f134c58fc59097e6b0958763b5]  is about to process streamed envelope cursor_id=[69472]
2025-02-04T22:35:33.544769Z DEBUG xmtp_mls::subscriptions::stream_messages: epoch=1 for [f04370cfd8e7f50a35c5fff7e02a375cb7c2b0f134c58fc59097e6b0958763b5] in process_stream_entry()
2025-02-04T22:35:33.544797Z  INFO xmtp_mls::subscriptions::stream_messages: error is not retryable. ReceiveGroup(EpochIncrementNotAllowed):processing group message in stream: epoch increment not allowed
2025-02-04T22:35:33.544807Z  WARN xmtp_mls::subscriptions::stream_messages: error processing streamed message epoch increment not allowed
2025-02-04T22:35:33.545382Z DEBUG xmtp_mls::subscriptions::stream_messages: attempting recovery sync epoch=1
2025-02-04T22:35:33.569251Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.569528Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being committed
2025-02-04T22:35:33.570615Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.570814Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being committed
2025-02-04T22:35:33.603534Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.603571Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being rolled back
2025-02-04T22:35:33.604233Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.612178Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being rolled back
2025-02-04T22:35:33.612752Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.621029Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being committed
2025-02-04T22:35:33.621839Z DEBUG xmtp_mls::subscriptions::stream_messages: recovery sync triggered by streamed message successful. epoch = 1
2025-02-04T22:35:33.621959Z  WARN xmtp_mls::subscriptions::stream_messages: group message not found
2025-02-04T22:35:33.621978Z  WARN xmtp_mls::subscriptions::stream_messages: skipping message streaming payload
2025-02-04T22:35:33.622026Z DEBUG xmtp_mls::subscriptions::stream_messages: client inbox_id=[f04370cfd8e7f50a35c5fff7e02a375cb7c2b0f134c58fc59097e6b0958763b5]  is about to process streamed envelope cursor_id=[69473]
2025-02-04T22:35:33.622178Z DEBUG xmtp_mls::subscriptions::stream_messages: client inbox_id=[f04370cfd8e7f50a35c5fff7e02a375cb7c2b0f134c58fc59097e6b0958763b5]  is about to process streamed envelope cursor_id=[69474]
2025-02-04T22:35:33.622820Z DEBUG xmtp_mls::subscriptions::stream_messages: epoch=1 for [f04370cfd8e7f50a35c5fff7e02a375cb7c2b0f134c58fc59097e6b0958763b5] in process_stream_entry()
2025-02-04T22:35:33.622842Z  INFO xmtp_mls::subscriptions::stream_messages: error is not retryable. ReceiveGroup(EpochIncrementNotAllowed):processing group message in stream: epoch increment not allowed
2025-02-04T22:35:33.622850Z  WARN xmtp_mls::subscriptions::stream_messages: error processing streamed message epoch increment not allowed
2025-02-04T22:35:33.623416Z DEBUG xmtp_mls::subscriptions::stream_messages: attempting recovery sync epoch=1
2025-02-04T22:35:33.628814Z DEBUG xmtp_mls::storage::encrypted_store::association_state: Loaded association state from cache: d390776e49bf17bd9dc6b91a2b5859dbfb7b8a6de07bab32f49640b2603f417e 38787
2025-02-04T22:35:33.628859Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.629914Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being committed
2025-02-04T22:35:33.630288Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.630451Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being committed
2025-02-04T22:35:33.662148Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.679464Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being rolled back
2025-02-04T22:35:33.680382Z DEBUG xmtp_mls::storage::encrypted_store::association_state: Loaded association state from cache: d390776e49bf17bd9dc6b91a2b5859dbfb7b8a6de07bab32f49640b2603f417e 38787
2025-02-04T22:35:33.680427Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.698884Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being committed
2025-02-04T22:35:33.699927Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.700281Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being committed
2025-02-04T22:35:33.701065Z DEBUG xmtp_mls::subscriptions::stream_messages: recovery sync triggered by streamed message successful. epoch = 2
2025-02-04T22:35:33.701179Z DEBUG xmtp_mls::subscriptions::stream_messages: client inbox_id=[f04370cfd8e7f50a35c5fff7e02a375cb7c2b0f134c58fc59097e6b0958763b5]  is about to process streamed envelope cursor_id=[69475]
2025-02-04T22:35:33.701912Z DEBUG xmtp_mls::subscriptions::stream_messages: epoch=2 for [f04370cfd8e7f50a35c5fff7e02a375cb7c2b0f134c58fc59097e6b0958763b5] in process_stream_entry()
2025-02-04T22:35:33.702606Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.710597Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being rolled back
2025-02-04T22:35:33.711252Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.719379Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being committed
2025-02-04T22:35:33.751592Z DEBUG xmtp_mls::storage::encrypted_store::association_state: Loaded association state from cache: d390776e49bf17bd9dc6b91a2b5859dbfb7b8a6de07bab32f49640b2603f417e 38787
2025-02-04T22:35:33.751679Z DEBUG xmtp_mls::storage::encrypted_store::association_state: Loaded association state from cache: f04370cfd8e7f50a35c5fff7e02a375cb7c2b0f134c58fc59097e6b0958763b5 38788
2025-02-04T22:35:33.751717Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.752178Z  INFO xmtp_mls::storage::encrypted_store::group: Trying to insert group
2025-02-04T22:35:33.752316Z  INFO xmtp_mls::storage::encrypted_store::group: Group welcome id already exists
2025-02-04T22:35:33.752344Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being rolled back
2025-02-04T22:35:33.781310Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.781430Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being committed
2025-02-04T22:35:33.836434Z DEBUG xmtp_mls::storage::encrypted_store: Transaction beginning
2025-02-04T22:35:33.836485Z DEBUG xmtp_mls::storage::encrypted_store: Transaction being rolled back
test mls::tests::test_can_stream_and_receive_metadata_update ... FAILED

failures:

Failure

running 1 test
2025-02-04 16:40:22.494: sqlcipher_set_log: set log to stderr
2025-02-04T21:40:22.683259Z DEBUG stream_all_messages: xmtp_mls::subscriptions: stream all messages
2025-02-04T21:40:22.711161Z DEBUG stream_all_messages: xmtp_mls::subscriptions::stream_conversations: Setting up conversation stream cursor = 0
2025-02-04T21:40:22.736603Z DEBUG stream_all_messages: xmtp_mls::subscriptions::stream_messages: setting up messages subscription
2025-02-04T21:40:22.986142Z  INFO xmtp_mls::subscriptions::stream_conversations: Trying to process streamed welcome
2025-02-04T21:40:23.064992Z DEBUG xmtp_mls::subscriptions::stream_conversations: finished processing with group a64d959f7e44c20e9491813d7a7a3157
2025-02-04T21:40:23.065016Z DEBUG xmtp_mls::subscriptions::stream_messages: begin establishing new message stream to include group_id=a64d959f7e44c20e9491813d7a7a3157
2025-02-04T21:40:23.091025Z DEBUG xmtp_mls::subscriptions::stream_messages: added group_id=a64d959f7e44c20e9491813d7a7a3157 at cursor=1 to messages stream
2025-02-04T21:40:23.091691Z DEBUG xmtp_mls::subscriptions::stream_messages: client inbox_id=[557cd8c6874c41bfa4d4d6545164c68cc47504452dea378343530ec1de008f37]  is about to process streamed envelope cursor_id=[69403]
2025-02-04T21:40:23.091890Z DEBUG xmtp_mls::subscriptions::stream_messages: current epoch for [557cd8c6874c41bfa4d4d6545164c68cc47504452dea378343530ec1de008f37] in process_stream_entry()
2025-02-04T21:40:23.091914Z  INFO xmtp_mls::subscriptions::stream_messages: error is not retryable. ReceiveGroup(EpochIncrementNotAllowed):processing group message in stream: epoch increment not allowed
2025-02-04T21:40:23.091924Z  WARN xmtp_mls::subscriptions::stream_messages: error processing streamed message epoch increment not allowed
2025-02-04T21:40:23.091934Z DEBUG xmtp_mls::subscriptions::stream_messages: attempting recovery sync
2025-02-04T21:40:23.147968Z DEBUG xmtp_mls::subscriptions::stream_messages: recovery sync triggered by streamed message successful
2025-02-04T21:40:23.148082Z  WARN xmtp_mls::subscriptions::stream_messages: group message not found
2025-02-04T21:40:23.148097Z  WARN xmtp_mls::subscriptions::stream_messages: skipping message streaming payload
2025-02-04T21:40:23.148138Z DEBUG xmtp_mls::subscriptions::stream_messages: client inbox_id=[557cd8c6874c41bfa4d4d6545164c68cc47504452dea378343530ec1de008f37]  is about to process streamed envelope cursor_id=[69404]
2025-02-04T21:40:23.148262Z DEBUG xmtp_mls::subscriptions::stream_messages: client inbox_id=[557cd8c6874c41bfa4d4d6545164c68cc47504452dea378343530ec1de008f37]  is about to process streamed envelope cursor_id=[69405]
2025-02-04T21:40:23.148356Z DEBUG xmtp_mls::subscriptions::stream_messages: current epoch for [557cd8c6874c41bfa4d4d6545164c68cc47504452dea378343530ec1de008f37] in process_stream_entry()
2025-02-04T21:40:23.148375Z  INFO xmtp_mls::subscriptions::stream_messages: error is not retryable. ReceiveGroup(EpochIncrementNotAllowed):processing group message in stream: epoch increment not allowed
2025-02-04T21:40:23.148384Z  WARN xmtp_mls::subscriptions::stream_messages: error processing streamed message epoch increment not allowed
2025-02-04T21:40:23.148392Z DEBUG xmtp_mls::subscriptions::stream_messages: attempting recovery sync
2025-02-04T21:40:23.230422Z DEBUG xmtp_mls::subscriptions::stream_messages: recovery sync triggered by streamed message successful
2025-02-04T21:40:23.230563Z DEBUG xmtp_mls::subscriptions::stream_messages: client inbox_id=[557cd8c6874c41bfa4d4d6545164c68cc47504452dea378343530ec1de008f37]  is about to process streamed envelope cursor_id=[69406]
2025-02-04T21:40:23.230684Z DEBUG xmtp_mls::subscriptions::stream_messages: current epoch for [557cd8c6874c41bfa4d4d6545164c68cc47504452dea378343530ec1de008f37] in process_stream_entry()
test mls::tests::test_can_stream_and_receive_metadata_update ... FAILED

failures:

---- mls::tests::test_can_stream_and_receive_metadata_update stdout ----
thread 'mls::tests::test_can_stream_and_receive_metadata_update' panicked at bindings_ffi/src/mls.rs:6537:9:
assertion `left == right` failed
  left: 2
 right: 1
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace


failures:
    mls::tests::test_can_stream_and_receive_metadata_update

Success

running 1 test

2025-02-04 16:27:39.040: sqlcipher_set_log: set log to stderr
2025-02-04T21:27:39.081839Z DEBUG stream_all_messages: xmtp_mls::subscriptions: stream all messages
2025-02-04T21:27:39.083381Z DEBUG stream_all_messages: xmtp_mls::subscriptions::stream_conversations: Setting up conversation stream cursor = 0
2025-02-04T21:27:39.083894Z DEBUG stream_all_messages: xmtp_mls::subscriptions::stream_messages: setting up messages subscription
2025-02-04T21:27:39.144009Z  INFO xmtp_mls::subscriptions::stream_conversations: Trying to process streamed welcome
2025-02-04T21:27:39.195514Z DEBUG xmtp_mls::subscriptions::stream_conversations: finished processing with group 1109306946df718a73dab7260505a205
2025-02-04T21:27:39.195538Z DEBUG xmtp_mls::subscriptions::stream_messages: begin establishing new message stream to include group_id=1109306946df718a73dab7260505a205
2025-02-04T21:27:39.196142Z DEBUG xmtp_mls::subscriptions::stream_messages: added group_id=1109306946df718a73dab7260505a205 at cursor=1 to messages stream
2025-02-04T21:27:39.196380Z DEBUG xmtp_mls::subscriptions::stream_messages: client inbox_id=[8bf14f47e330b9934bc6018c88c113a19c244ad995dae7e37fe452a0be909ebf]  is about to process streamed envelope cursor_id=[326]
2025-02-04T21:27:39.196698Z DEBUG xmtp_mls::subscriptions::stream_messages: current epoch for [8bf14f47e330b9934bc6018c88c113a19c244ad995dae7e37fe452a0be909ebf] in process_stream_entry()
2025-02-04T21:27:39.196753Z  INFO xmtp_mls::subscriptions::stream_messages: error is not retryable. ReceiveGroup(EpochIncrementNotAllowed):processing group message in stream: epoch increment not allowed
2025-02-04T21:27:39.196767Z  WARN xmtp_mls::subscriptions::stream_messages: error processing streamed message epoch increment not allowed
2025-02-04T21:27:39.196781Z DEBUG xmtp_mls::subscriptions::stream_messages: attempting recovery sync
2025-02-04T21:27:39.291488Z DEBUG xmtp_mls::subscriptions::stream_messages: recovery sync triggered by streamed message successful
2025-02-04T21:27:39.291624Z  WARN xmtp_mls::subscriptions::stream_messages: group message not found
2025-02-04T21:27:39.291644Z  WARN xmtp_mls::subscriptions::stream_messages: skipping message streaming payload
2025-02-04T21:27:39.291688Z DEBUG xmtp_mls::subscriptions::stream_messages: client inbox_id=[8bf14f47e330b9934bc6018c88c113a19c244ad995dae7e37fe452a0be909ebf]  is about to process streamed envelope cursor_id=[327]
2025-02-04T21:27:39.291840Z DEBUG xmtp_mls::subscriptions::stream_messages: client inbox_id=[8bf14f47e330b9934bc6018c88c113a19c244ad995dae7e37fe452a0be909ebf]  is about to process streamed envelope cursor_id=[328]
2025-02-04T21:27:39.291935Z DEBUG xmtp_mls::subscriptions::stream_messages: client inbox_id=[8bf14f47e330b9934bc6018c88c113a19c244ad995dae7e37fe452a0be909ebf]  is about to process streamed envelope cursor_id=[329]
test mls::tests::test_can_stream_and_receive_metadata_update ... ok