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: Complex Setup with Streams and Group metadata causes forked groups #416

Closed
alexrisch opened this issue Jun 12, 2024 · 4 comments · Fixed by xmtp/libxmtp#846
Closed

Bug: Complex Setup with Streams and Group metadata causes forked groups #416

alexrisch opened this issue Jun 12, 2024 · 4 comments · Fixed by xmtp/libxmtp#846
Assignees
@cameronvoell
Labels
bug Something isn't working Client App Group Chat - Prod

Comments

@alexrisch
Copy link
Contributor

Describe the bug

When setting streamAllMessages and updating group metadata fairly quickly after group creation
Group syncing stops working

 const [alix, bo] = await createClients(2)
  console.log('created clients')

  //#region Stream All Messages
  await bo.conversations.streamAllMessages(async () => {
    console.log('message received')
  }, true)
  //#endregion
  // #region create group
  const alixGroup = await alix.conversations.newGroup([bo.address])
  await alixGroup.updateGroupName('hello')
  await alixGroup.send('hello1')
  console.log('sent group message')
  // #endregion
  // #region sync groups
  await bo.conversations.syncGroups()
  // #endregion
  const boGroups = await bo.conversations.listGroups()
  assert(boGroups.length === 1, 'bo should have 1 group')
  const boGroup = boGroups[0]
  await boGroup.sync()

  const boMessages1 = await boGroup.messages()
  assert(
    boMessages1.length === 2,
    `should have 2 messages on first load received ${boMessages1.length}`
  )
  await boGroup.send('hello2')
  await boGroup.send('hello3')
  await alixGroup.sync()
  const alixMessages = await alixGroup.messages()
  for (const message of alixMessages) {
    console.log(
      'message',
      message.contentTypeId,
      message.contentTypeId === 'xmtp.org/text:1.0'
        ? message.content()
        : 'Group Updated'
    )
  }
  // alix sees 3 messages
  assert(
    alixMessages.length === 5,
    `should have 5 messages on first load received ${alixMessages.length}`
  )
  await alixGroup.send('hello4')
  await boGroup.sync()
  const boMessages2 = await boGroup.messages()
  for (const message of boMessages2) {
    console.log(
      'message',
      message.contentTypeId,
      message.contentTypeId === 'xmtp.org/text:1.0'
        ? message.content()
        : 'Group Updated'
    )
  }
  // bo sees 4 messages
  assert(
    boMessages2.length === 5,
    `should have 5 messages on second load received ${boMessages2.length}`
  )

Expected behavior

No response

Steps to reproduce the bug

No response
@alexrisch alexrisch added the bug Something isn't working label Jun 12, 2024
@cameronvoell cameronvoell self-assigned this Jun 13, 2024
@cameronvoell
Copy link
Contributor

cameronvoell commented Jun 13, 2024 •
edited
Loading

Logs with extra logging from Nick's libxmtp branch:

What seems notable to me is that it looks like the commit for updating the group name is being processed by both clients, however we start seeing Wrong Epoch: message.epoch() 2 > 1 self.group_context().epoch() for the non group creator. This seems to me like the second member processed the external message for the group name update, and successfully merged the commit, however their Group Context epoch did not increase from 1 to 2.

logs 
2024-06-13 07:07:39.597 19829-19888 INFO                    e  I  [libxmtp] Getting inbox_ids for account addresses: ["0xa7c16f129aa9dec5a9fd0321381ad8568bfe5e3d"]
2024-06-13 07:07:39.601   391-478   AudioFlinger            pid-391                              D  mixer(0xb400007afe601930) throttle end: throttle time(33)
2024-06-13 07:07:39.605 19829-19888 INFO                    e  I  [libxmtp] Creating API client for host: http://10.0.2.2:5556, isSecure: false
2024-06-13 07:07:39.608 19829-19888 INFO                    e  I  [libxmtp] Creating message store with path: Some("/data/user/0/expo.modules.xmtpreactnativesdk.example/files/xmtp_db/xmtp-LOCAL-0e922b3d7ac597d11df41ccb34dbbdf82d2c6e454738d52cbe48e0ef05c604e8.db3") and encryption key: true
2024-06-13 07:07:39.608 19829-19888 INFO                    e  I  [libxmtp] Setting up DB connection pool
2024-06-13 07:07:39.612 19829-19888 INFO                    e  I  [libxmtp] Running DB migrations
2024-06-13 07:07:39.617 19829-19888 INFO                    e  I  [libxmtp] Migrations successful
2024-06-13 07:07:39.617 19829-19888 INFO                    e  I  [libxmtp] Creating XMTP client 
2024-06-13 07:07:39.618 19829-19888 INFO                    e  I  [libxmtp] Initializing identity
2024-06-13 07:07:39.618 19829-19888 INFO                    e  I  [libxmtp] Getting inbox_ids for account addresses: ["0xa7c16f129aa9dec5a9fd0321381ad8568bfe5e3d"]
2024-06-13 07:07:39.623 19829-19888 INFO                    e  I  [libxmtp] Provided Signer: fc8206bdaf48928ea76219c077c81b14bb581005a8f7db2f2940cb478541a855
2024-06-13 07:07:39.624 19829-19888 INFO                    e  I  [libxmtp] Missing Signatures: [Address("0xa7c16f129aa9dec5a9fd0321381ad8568bfe5e3d"), Installation([252, 130, 6, 189, 175, 72, 146, 142, 167, 98, 25, 192, 119, 200, 27, 20, 187, 88, 16, 5, 168, 247, 219, 47, 41, 64, 203, 71, 133, 65, 168, 85])]
2024-06-13 07:07:39.625 19829-19888 INFO                    e  I  [libxmtp] Provided Signer: 0xa7c16f129aa9dec5a9fd0321381ad8568bfe5e3d
2024-06-13 07:07:39.626 19829-19888 INFO                    e  I  [libxmtp] Missing Signatures: [Address("0xa7c16f129aa9dec5a9fd0321381ad8568bfe5e3d")]
2024-06-13 07:07:39.657 19829-19888 INFO                    e  I  [libxmtp] Created XMTP client for inbox_id: 0e922b3d7ac597d11df41ccb34dbbdf82d2c6e454738d52cbe48e0ef05c604e8
2024-06-13 07:07:39.657 19829-19888 Client                  e  I  LibXMTP Version: 6797fd55
                                                                                                    Branch: nm/forked-group-state
                                                                                                    Date: 2024-06-12 16:37:37 +0000
2024-06-13 07:07:39.676 19829-19888 XMTPModule              e  V  createRandom
2024-06-13 07:07:39.680 19829-22291 TrafficStats            e  D  tagSocket(458) with statsTag=0xffffffff, statsUid=-1
2024-06-13 07:07:39.714   391-478   audioserver             pid-391                              D  FGS Logger Transaction failed
2024-06-13 07:07:39.714   391-478   audioserver             pid-391                              D  -129
2024-06-13 07:07:39.720 19829-19888 INFO                    e  I  [libxmtp] Getting inbox_ids for account addresses: ["0x53a9321d28a209df2a1260bd2fb0ae86691aa874"]
2024-06-13 07:07:39.725 19829-19888 INFO                    e  I  [libxmtp] Creating API client for host: http://10.0.2.2:5556, isSecure: false
2024-06-13 07:07:39.728 19829-19888 INFO                    e  I  [libxmtp] Creating message store with path: Some("/data/user/0/expo.modules.xmtpreactnativesdk.example/files/xmtp_db/xmtp-LOCAL-cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6.db3") and encryption key: true
2024-06-13 07:07:39.728 19829-19888 INFO                    e  I  [libxmtp] Setting up DB connection pool
2024-06-13 07:07:39.731 19829-19888 INFO                    e  I  [libxmtp] Running DB migrations
2024-06-13 07:07:39.736 19829-19888 INFO                    e  I  [libxmtp] Migrations successful
2024-06-13 07:07:39.737 19829-19888 INFO                    e  I  [libxmtp] Creating XMTP client 
2024-06-13 07:07:39.738 19829-19888 INFO                    e  I  [libxmtp] Initializing identity
2024-06-13 07:07:39.739 19829-19888 INFO                    e  I  [libxmtp] Getting inbox_ids for account addresses: ["0x53a9321d28a209df2a1260bd2fb0ae86691aa874"]
2024-06-13 07:07:39.742 19829-19888 INFO                    e  I  [libxmtp] Provided Signer: 853f1cf116e7f43c9a7392503bca92399891394c37a6b94be8ee90c9dfa6efce
2024-06-13 07:07:39.742 19829-19888 INFO                    e  I  [libxmtp] Missing Signatures: [Address("0x53a9321d28a209df2a1260bd2fb0ae86691aa874"), Installation([133, 63, 28, 241, 22, 231, 244, 60, 154, 115, 146, 80, 59, 202, 146, 57, 152, 145, 57, 76, 55, 166, 185, 75, 232, 238, 144, 201, 223, 166, 239, 206])]
2024-06-13 07:07:39.743 19829-19888 INFO                    e  I  [libxmtp] Provided Signer: 0x53a9321d28a209df2a1260bd2fb0ae86691aa874
2024-06-13 07:07:39.744 19829-19888 INFO                    e  I  [libxmtp] Missing Signatures: [Address("0x53a9321d28a209df2a1260bd2fb0ae86691aa874")]
2024-06-13 07:07:39.773 19829-19888 INFO                    e  I  [libxmtp] Created XMTP client for inbox_id: cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6
2024-06-13 07:07:39.773 19829-19888 Client                  e  I  LibXMTP Version: 6797fd55
                                                                                                    Branch: nm/forked-group-state
                                                                                                    Date: 2024-06-12 16:37:37 +0000
2024-06-13 07:07:39.791 19829-19892 ReactNativeJS           e  I  created clients
2024-06-13 07:07:39.791 19829-19892 XMTPModule              e  V  subscribeToAllMessages
2024-06-13 07:07:39.793 19829-20204 XMTPModule              e  V  createGroup
2024-06-13 07:07:39.796 19829-20204 INFO                    e  I  [libxmtp] Getting inbox_ids for account addresses: ["0x53a9321d28a209df2a1260bd2fb0ae86691aa874"]
2024-06-13 07:07:39.799 19829-22305 TrafficStats            e  D  tagSocket(437) with statsTag=0xffffffff, statsUid=-1
2024-06-13 07:07:39.803 19829-19999 INFO                    e  I  [libxmtp] creating group with account addresses: 0x53A9321d28A209Df2A1260bD2FB0AE86691aA874
2024-06-13 07:07:39.806 19829-19999 INFO                    e  I  [libxmtp] creating group
2024-06-13 07:07:39.826 19829-19999 INFO                    e  I  [libxmtp] Getting inbox_ids for account addresses: ["0x53a9321d28a209df2a1260bd2fb0ae86691aa874"]
2024-06-13 07:07:39.837 19829-19999 INFO                    e  I  [libxmtp] old group membership: {"0e922b3d7ac597d11df41ccb34dbbdf82d2c6e454738d52cbe48e0ef05c604e8": 0}
2024-06-13 07:07:39.839 19829-19999 INFO                    e  I  [libxmtp] updated group membership: {"0e922b3d7ac597d11df41ccb34dbbdf82d2c6e454738d52cbe48e0ef05c604e8": 2963, "cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6": 2964}
2024-06-13 07:07:39.857 19829-19999 INFO                    e  I  [libxmtp] [0e922b3d7ac597d11df41ccb34dbbdf82d2c6e454738d52cbe48e0ef05c604e8] Validating commit for intent 1. Message timestamp: 1718287661464649000
2024-06-13 07:07:39.858 19829-19999 INFO                    e  I  [libxmtp] Group context extensions proposal found: GroupMembership { members: {"0e922b3d7ac597d11df41ccb34dbbdf82d2c6e454738d52cbe48e0ef05c604e8": 2963, "cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6": 2964} }
2024-06-13 07:07:39.858 19829-19999 INFO                    e  I  [libxmtp] [0e922b3d7ac597d11df41ccb34dbbdf82d2c6e454738d52cbe48e0ef05c604e8] merging pending commit for intent 1
2024-06-13 07:07:39.859 19829-19999 INFO                    e  I  [libxmtp] 0e922b3d7ac597d11df41ccb34dbbdf82d2c6e454738d52cbe48e0ef05c604e8: Storing a transcript message with 1 members added and 0 members removed and 0 metadata changes
2024-06-13 07:07:39.864 19829-19987 INFO                    e  I  [libxmtp] Received conversation streaming payload
2024-06-13 07:07:39.883 19829-19999 XMTPModule              e  V  updateGroupName
2024-06-13 07:07:39.891 19829-19987 INFO                    e  I  [libxmtp] closing stream
2024-06-13 07:07:39.894 19829-19987 INFO                    e  I  [libxmtp] Received message streaming payload
2024-06-13 07:07:39.896 19829-19987 INFO                    e  I  [libxmtp] [cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6] processing external message
2024-06-13 07:07:39.896 19829-19987 ERROR                   e  E  [libxmtp] Wrong Epoch: message.epoch() 0 != 1 self.group_context().epoch() 
2024-06-13 07:07:39.900 19829-20204 INFO                    e  I  [libxmtp] [0e922b3d7ac597d11df41ccb34dbbdf82d2c6e454738d52cbe48e0ef05c604e8] Validating commit for intent 2. Message timestamp: 1718287661508577000
2024-06-13 07:07:39.901 19829-20204 INFO                    e  I  [libxmtp] Group context extensions proposal found: GroupMembership { members: {"cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6": 2964, "0e922b3d7ac597d11df41ccb34dbbdf82d2c6e454738d52cbe48e0ef05c604e8": 2963} }
2024-06-13 07:07:39.902 19829-20204 INFO                    e  I  [libxmtp] [0e922b3d7ac597d11df41ccb34dbbdf82d2c6e454738d52cbe48e0ef05c604e8] merging pending commit for intent 2
2024-06-13 07:07:39.903 19829-20204 INFO                    e  I  [libxmtp] 0e922b3d7ac597d11df41ccb34dbbdf82d2c6e454738d52cbe48e0ef05c604e8: Storing a transcript message with 0 members added and 0 members removed and 1 metadata changes
2024-06-13 07:07:39.904 19829-19987 INFO                    e  I  [libxmtp] [cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6] processing external message
2024-06-13 07:07:39.905 19829-19987 ERROR                   e  E  [libxmtp] Wrong Epoch: message.epoch() 0 != 1 self.group_context().epoch() 
2024-06-13 07:07:39.906 19829-19987 INFO                    e  I  [libxmtp] [cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6] processing external message
2024-06-13 07:07:39.907 19829-19987 INFO                    e  I  [libxmtp] [cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6] extracted sender inbox id: 0e922b3d7ac597d11df41ccb34dbbdf82d2c6e454738d52cbe48e0ef05c604e8
2024-06-13 07:07:39.908 19829-20204 XMTPModule              e  V  sendMessageToGroup
2024-06-13 07:07:39.914 19829-19987 INFO                    e  I  [libxmtp] [cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6] received staged commit. Merging and clearing any pending commits
2024-06-13 07:07:39.914 19829-19987 INFO                    e  I  [libxmtp] Group context extensions proposal found: GroupMembership { members: {"cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6": 2964, "0e922b3d7ac597d11df41ccb34dbbdf82d2c6e454738d52cbe48e0ef05c604e8": 2963} }
2024-06-13 07:07:39.915 19829-19987 INFO                    e  I  [libxmtp] [cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6] staged commit is valid
2024-06-13 07:07:39.916 19829-19987 INFO                    e  I  [libxmtp] [cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6] staged commit merged successfully 
2024-06-13 07:07:39.917 19829-19987 INFO                    e  I  [libxmtp] cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6: Storing a transcript message with 0 members added and 0 members removed and 1 metadata changes
2024-06-13 07:07:39.918 19829-19987 ERROR                   e  E  [libxmtp] Message processing errors: [OpenMlsProcessMessage(ValidationError(WrongEpoch))]
2024-06-13 07:07:39.919 19829-19987 ERROR                   e  E  [libxmtp] receive error ReceiveErrors([OpenMlsProcessMessage(ValidationError(WrongEpoch))])
2024-06-13 07:07:39.920 19829-19987 INFO                    e  I  [libxmtp] Skipped message streaming payload 
2024-06-13 07:07:39.921 19829-19987 INFO                    e  I  [libxmtp] Received message streaming payload
2024-06-13 07:07:39.922 19829-19987 INFO                    e  I  [libxmtp] [cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6] processing external message
2024-06-13 07:07:39.922 19829-19987 ERROR                   e  E  [libxmtp] Wrong Epoch: message.epoch() 1 != 2 self.group_context().epoch() 
2024-06-13 07:07:39.928 19829-19892 ReactNativeJS           e  I  message received
2024-06-13 07:07:39.937 19829-19987 INFO                    e  I  [libxmtp] Received message streaming payload
2024-06-13 07:07:39.939 19829-19987 INFO                    e  I  [libxmtp] [cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6] processing external message
2024-06-13 07:07:39.940 19829-19987 INFO                    e  I  [libxmtp] [cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6] extracted sender inbox id: 0e922b3d7ac597d11df41ccb34dbbdf82d2c6e454738d52cbe48e0ef05c604e8
2024-06-13 07:07:39.940 19829-19987 INFO                    e  I  [libxmtp] [cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6] decoding application message
2024-06-13 07:07:39.941 19829-19892 ReactNativeJS           e  I  sent group message
2024-06-13 07:07:39.941 19829-22304 XMTPModule              e  V  syncGroups
2024-06-13 07:07:39.948 19829-19892 ReactNativeJS           e  I  message received
2024-06-13 07:07:39.951 19829-22302 XMTPModule              e  V  listGroups
2024-06-13 07:07:39.960 19829-22302 XMTPModule              e  V  syncGroup
2024-06-13 07:07:39.966 19829-22302 INFO                    e  I  [libxmtp] [cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6] processing external message
2024-06-13 07:07:39.966 19829-22302 ERROR                   e  E  [libxmtp] Wrong Epoch: message.epoch() 2 > 1 self.group_context().epoch()
2024-06-13 07:07:39.967 19829-22302 ERROR                   e  E  [libxmtp] Message processing errors: [OpenMlsProcessMessage(ValidationError(WrongEpoch))]
2024-06-13 07:07:39.968 19829-22302 ERROR                   e  E  [libxmtp] receive error ReceiveErrors([OpenMlsProcessMessage(ValidationError(WrongEpoch))])
2024-06-13 07:07:39.969 19829-22302 XMTPModule              e  V  groupMessages
2024-06-13 07:07:39.979 19829-22302 XMTPModule              e  V  sendMessageToGroup
2024-06-13 07:07:40.002 19829-19987 INFO                    e  I  [libxmtp] Received message streaming payload
2024-06-13 07:07:40.005 19829-22302 XMTPModule              e  V  sendMessageToGroup
2024-06-13 07:07:40.007 19829-19892 ReactNativeJS           e  I  message received
2024-06-13 07:07:40.022 19829-19987 INFO                    e  I  [libxmtp] Received message streaming payload
2024-06-13 07:07:40.023 19829-19987 INFO                    e  I  [libxmtp] [cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6] processing external message
2024-06-13 07:07:40.024 19829-19987 ERROR                   e  E  [libxmtp] This is the wrong ratchet type.
2024-06-13 07:07:40.024 19829-22302 XMTPModule              e  V  syncGroup
2024-06-13 07:07:40.025 19829-19987 ERROR                   e  E  [libxmtp]   Ciphertext generation out of bounds 1
                                                                                                        RatchetTypeError
2024-06-13 07:07:40.028 19829-19987 INFO                    e  I  [libxmtp] [cff60102f491735783d93cae79d11891b93a8f389e0de3a54f7868cc9d38e0b6] processing external message
2024-06-13 07:07:40.028 19829-19987 ERROR                   e  E  [libxmtp] Wrong Epoch: message.epoch() 2 > 1 self.group_context().epoch()
2024-06-13 07:07:40.030 19829-19987 ERROR                   e  E  [libxmtp] Message processing errors: [OpenMlsProcessMessage(ValidationError(WrongEpoch))]
2024-06-13 07:07:40.030 19829-19987 ERROR                   e  E  [libxmtp] receive error ReceiveErrors([OpenMlsProcessMessage(ValidationError(WrongEpoch))])
2024-06-13 07:07:40.036 19829-19892 ReactNativeJS           e  I  message received
2024-06-13 07:07:40.040 19829-22302 INFO                    e  I  [libxmtp] [0e922b3d7ac597d11df41ccb34dbbdf82d2c6e454738d52cbe48e0ef05c604e8] processing external message
2024-06-13 07:07:40.040 19829-22302 INFO                    e  I  [libxmtp] [0e922b3d7ac597d11df41ccb34dbbdf82d2c6e454738d52cbe48e0ef05c604e8] processing external message
2024-06-13 07:07:40.041 19829-22302 ERROR                   e  E  [libxmtp] Message processing errors: [OpenMlsProcessMessage(ValidationError(UnableToDecrypt(AeadError))), OpenMlsProcessMessage(ValidationError(UnableToDecrypt(AeadError)))]
2024-06-13 07:07:40.042 19829-22302 ERROR                   e  E  [libxmtp] receive error ReceiveErrors([OpenMlsProcessMessage(ValidationError(UnableToDecrypt(AeadError))), OpenMlsProcessMessage(ValidationError(UnableToDecrypt(AeadError)))])
2024-06-13 07:07:40.044 19829-22302 XMTPModule              e  V  groupMessages

@neekolas
Copy link
Contributor

It feels like we are getting somewhere.

Maybe it would be helpful to compare the logs with a run through the same actions that doesn't fork the group state. Then we can see what's different. Some Wrong epoch errors are harmless and expected, since new members will read all messages in a group starting at the beginning (before they joined).

It would also be helpful to start logging hashes of the envelope payloads all over the place so we can see exactly which messages are failing to process. That way when a message fails to decrypt we can tie it back to when it was sent and figure out what intent it was related to (adding the member, changing the name) and whether or not it was a retry.

@neekolas
Copy link
Contributor

One other thing I could see being helpful to log is any transaction rollbacks. Want to make super sure that messages which appear to have been processed successfully aren't rolling back at the last minute silently somewhere.

Maybe we just throw a line somewhere in the Storage transaction and transaction_async functions

@cameronvoell
Copy link
Contributor

cameronvoell commented Jun 13, 2024 •
edited
Loading

New error log, with envelope hashes and messages on transaction commits and rollbacks, replaced inboxIDs with CREATOR and USER2 for readability:

logs 
2024-06-13 08:41:12.921 29161-29335 INFO                      I  [libxmtp] Getting inbox_ids for account addresses: ["0x923c22e0b8f53942dd7f79e676aa0d756f67c12b"]
2024-06-13 08:41:12.927 29161-29281 TrafficStats              D  tagSocket(222) with statsTag=0xffffffff, statsUid=-1
2024-06-13 08:41:12.929 29161-29333 INFO                      I  [libxmtp] creating group with account addresses: 0x923C22e0b8f53942dd7f79e676aA0D756f67C12b
2024-06-13 08:41:12.930 29161-29333 INFO                      I  [libxmtp] creating group
2024-06-13 08:41:12.947 29161-29333 INFO                      I  [libxmtp] Getting inbox_ids for account addresses: ["0x923c22e0b8f53942dd7f79e676aa0d756f67c12b"]
2024-06-13 08:41:12.957 29161-29335 INFO                      I  [libxmtp] old group membership: {"CREATOR": 0}
2024-06-13 08:41:12.957 29161-29335 INFO                      I  [libxmtp] updated group membership: {"CREATOR": 2995, "USER2": 2996}
2024-06-13 08:41:12.976 29161-29335 INFO                      I  [libxmtp] Transaction Async beginning
2024-06-13 08:41:12.977 29161-29335 INFO                      I  [libxmtp] client [CREATOR] is  about to process own envelope [3111]
2024-06-13 08:41:12.977 29161-29335 INFO                      I  [libxmtp] envelope [3111] is equal to intent [1]
2024-06-13 08:41:12.978 29161-29335 INFO                      I  [libxmtp] [CREATOR] Validating commit for intent 1. Message timestamp: 1718293274607845000
2024-06-13 08:41:12.978 29161-29335 INFO                      I  [libxmtp] Group context extensions proposal found: GroupMembership { members: {"USER2": 2996, "CREATOR": 2995} }
2024-06-13 08:41:12.979 29161-29335 INFO                      I  [libxmtp] [CREATOR] merging pending commit for intent 1
2024-06-13 08:41:12.979 29161-29335 INFO                      I  [libxmtp] CREATOR: Storing a transcript message with 1 members added and 0 members removed and 0 metadata changes
2024-06-13 08:41:12.980 29161-29335 INFO                      I  [libxmtp] Transaction Async being committed
2024-06-13 08:41:12.986 29161-29321 INFO                      I  [libxmtp] Received conversation streaming payload
2024-06-13 08:41:13.007 29161-29333 XMTPModule                V  updateGroupName
2024-06-13 08:41:13.013 29161-29321 INFO                      I  [libxmtp] closing stream
2024-06-13 08:41:13.016 29161-29321 INFO                      I  [libxmtp] Received message streaming payload
2024-06-13 08:41:13.017 29161-29321 INFO                      I  [libxmtp] client [USER2]  is about to process streamed envelope: [3111]
2024-06-13 08:41:13.017 29161-29321 INFO                      I  [libxmtp] Transaction Async beginning
2024-06-13 08:41:13.018 29161-29321 INFO                      I  [libxmtp] client [USER2] is about to process external envelope [3111]
2024-06-13 08:41:13.018 29161-29321 ERROR                     E  [libxmtp] Wrong Epoch: message.epoch() 0 != 1 self.group_context().epoch()
2024-06-13 08:41:13.019 29161-29321 INFO                      I  [libxmtp] Transaction Async being rolled back
2024-06-13 08:41:13.029 29161-29333 INFO                      I  [libxmtp] Transaction Async beginning
2024-06-13 08:41:13.030 29161-29333 INFO                      I  [libxmtp] client [CREATOR] is  about to process own envelope [3112]
2024-06-13 08:41:13.030 29161-29333 INFO                      I  [libxmtp] envelope [3112] is equal to intent [2]
2024-06-13 08:41:13.031 29161-29333 INFO                      I  [libxmtp] [CREATOR] Validating commit for intent 2. Message timestamp: 1718293274657447000
2024-06-13 08:41:13.031 29161-29321 INFO                      I  [libxmtp] Transaction Async beginning
2024-06-13 08:41:13.032 29161-29333 INFO                      I  [libxmtp] Group context extensions proposal found: GroupMembership { members: {"CREATOR": 2995, "USER2": 2996} }
2024-06-13 08:41:13.033 29161-29321 INFO                      I  [libxmtp] client [USER2] is about to process external envelope [3111]
2024-06-13 08:41:13.033 29161-29321 ERROR                     E  [libxmtp] Wrong Epoch: message.epoch() 0 != 1 self.group_context().epoch()
2024-06-13 08:41:13.034 29161-29321 INFO                      I  [libxmtp] Transaction Async being rolled back
2024-06-13 08:41:13.035 29161-29321 INFO                      I  [libxmtp] Transaction Async beginning
2024-06-13 08:41:13.035 29161-29333 INFO                      I  [libxmtp] [CREATOR] merging pending commit for intent 2
2024-06-13 08:41:13.036 29161-29321 INFO                      I  [libxmtp] client [USER2] is about to process external envelope [3112]
2024-06-13 08:41:13.037 29161-29333 INFO                      I  [libxmtp] CREATOR: Storing a transcript message with 0 members added and 0 members removed and 1 metadata changes
2024-06-13 08:41:13.037 29161-29333 INFO                      I  [libxmtp] Transaction Async being committed
2024-06-13 08:41:13.038 29161-29321 INFO                      I  [libxmtp] [USER2] extracted sender inbox id: CREATOR
2024-06-13 08:41:13.039 29161-29321 INFO                      I  [libxmtp] [USER2] received staged commit. Merging and clearing any pending commits
2024-06-13 08:41:13.040 29161-29321 INFO                      I  [libxmtp] Group context extensions proposal found: GroupMembership { members: {"CREATOR": 2995, "USER2": 2996} }
2024-06-13 08:41:13.041 29161-29321 INFO                      I  [libxmtp] [USER2] staged commit is valid
2024-06-13 08:41:13.042 29161-29321 INFO                      I  [libxmtp] [USER2] staged commit merged successfully
2024-06-13 08:41:13.042 29161-29333 XMTPModule                V  sendMessageToGroup
2024-06-13 08:41:13.043 29161-29321 INFO                      I  [libxmtp] USER2: Storing a transcript message with 0 members added and 0 members removed and 1 metadata changes 
2024-06-13 08:41:13.044 29161-29321 INFO                      I  [libxmtp] Transaction Async being committed
2024-06-13 08:41:13.046 29161-29321 ERROR                     E  [libxmtp] Message processing errors: [OpenMlsProcessMessage(ValidationError(WrongEpoch))]
2024-06-13 08:41:13.046 29161-29321 ERROR                     E  [libxmtp] receive error ReceiveErrors([OpenMlsProcessMessage(ValidationError(WrongEpoch))])
2024-06-13 08:41:13.048 29161-29321 INFO                      I  [libxmtp] Skipped message streaming payload
2024-06-13 08:41:13.048 29161-29321 INFO                      I  [libxmtp] Received message streaming payload
2024-06-13 08:41:13.049 29161-29321 INFO                      I  [libxmtp] client [USER2]  is about to process streamed envelope: [3112]
2024-06-13 08:41:13.049 29161-29321 INFO                      I  [libxmtp] Transaction Async beginning
2024-06-13 08:41:13.050 29161-29321 INFO                      I  [libxmtp] client [USER2] is about to process external envelope [3112]
2024-06-13 08:41:13.051 29161-29321 ERROR                     E  [libxmtp] Wrong Epoch: message.epoch() 1 != 2 self.group_context().epoch()
2024-06-13 08:41:13.052 29161-29321 INFO                      I  [libxmtp] Transaction Async being rolled back
2024-06-13 08:41:13.060 29161-29224 ReactNativeJS             I  message received
2024-06-13 08:41:13.069 29161-29321 INFO                      I  [libxmtp] Received message streaming payload
2024-06-13 08:41:13.070 29161-29321 INFO                      I  [libxmtp] client [USER2]  is about to process streamed envelope: [3113]
2024-06-13 08:41:13.070 29161-29321 INFO                      I  [libxmtp] Transaction Async beginning
2024-06-13 08:41:13.072 29161-29224 ReactNativeJS             I  sent group message
2024-06-13 08:41:13.072 29161-29335 XMTPModule                V  syncGroups
2024-06-13 08:41:13.074 29161-29321 INFO                      I  [libxmtp] client [USER2] is about to process external envelope [3113]
2024-06-13 08:41:13.075 29161-29321 INFO                      I  [libxmtp] [USER2] extracted sender inbox id: CREATOR
2024-06-13 08:41:13.076 29161-29321 INFO                      I  [libxmtp] [USER2] decoding application message
2024-06-13 08:41:13.077 29161-29321 INFO                      I  [libxmtp] Transaction Async being committed
2024-06-13 08:41:13.081 29161-29224 ReactNativeJS             I  message received
2024-06-13 08:41:13.085 29161-29335 INFO                      I  [libxmtp] Transaction Async beginning
2024-06-13 08:41:13.089 29161-29335 INFO                      I  [libxmtp] Transaction Async being committed
2024-06-13 08:41:13.091 29161-29335 XMTPModule                V  listGroups
2024-06-13 08:41:13.101 29161-29335 XMTPModule                V  syncGroup
2024-06-13 08:41:13.108 29161-29335 INFO                      I  [libxmtp] Transaction Async beginning
2024-06-13 08:41:13.109 29161-29335 INFO                      I  [libxmtp] client [USER2] is about to process external envelope [3113]
2024-06-13 08:41:13.109 29161-29335 ERROR                     E  [libxmtp] Wrong Epoch: message.epoch() 2 > 1 self.group_context().epoch()
2024-06-13 08:41:13.110 29161-29335 INFO                      I  [libxmtp] Transaction Async being rolled back
2024-06-13 08:41:13.111 29161-29335 ERROR                     E  [libxmtp] Message processing errors: [OpenMlsProcessMessage(ValidationError(WrongEpoch))]
2024-06-13 08:41:13.111 29161-29335 ERROR                     E  [libxmtp] receive error ReceiveErrors([OpenMlsProcessMessage(ValidationError(WrongEpoch))])
2024-06-13 08:41:13.113 29161-29335 XMTPModule                V  groupMessages
2024-06-13 08:41:13.123 29161-29335 XMTPModule                V  sendMessageToGroup
2024-06-13 08:41:13.150 29161-29321 INFO                      I  [libxmtp] Received message streaming payload
2024-06-13 08:41:13.151 29161-29321 INFO                      I  [libxmtp] client [USER2]  is about to process streamed envelope: [3114]
2024-06-13 08:41:13.152 29161-29321 INFO                      I  [libxmtp] Transaction Async beginning
2024-06-13 08:41:13.153 29161-29321 INFO                      I  [libxmtp] client [USER2] is  about to process own envelope [3114]
2024-06-13 08:41:13.153 29161-29333 XMTPModule                V  sendMessageToGroup
2024-06-13 08:41:13.154 29161-29321 INFO                      I  [libxmtp] envelope [3114] is equal to intent [1]
2024-06-13 08:41:13.154 29161-29321 INFO                      I  [libxmtp] Transaction Async being committed
2024-06-13 08:41:13.160 29161-29224 ReactNativeJS             I  message received
2024-06-13 08:41:13.172 29161-29321 INFO                      I  [libxmtp] Received message streaming payload
2024-06-13 08:41:13.173 29161-29321 INFO                      I  [libxmtp] client [USER2]  is about to process streamed envelope: [3115]
2024-06-13 08:41:13.174 29161-29321 INFO                      I  [libxmtp] Transaction Async beginning
2024-06-13 08:41:13.175 29161-29321 INFO                      I  [libxmtp] client [USER2] is  about to process own envelope [3115]
2024-06-13 08:41:13.176 29161-29321 INFO                      I  [libxmtp] envelope [3115] is equal to intent [2]
2024-06-13 08:41:13.176 29161-29333 XMTPModule                V  syncGroup
2024-06-13 08:41:13.176 29161-29321 INFO                      I  [libxmtp] Transaction Async being committed
2024-06-13 08:41:13.182 29161-29224 ReactNativeJS             I  message received
2024-06-13 08:41:13.185 29161-29333 INFO                      I  [libxmtp] Transaction Async beginning
2024-06-13 08:41:13.185 29161-29333 INFO                      I  [libxmtp] client [CREATOR] is  about to process own envelope [3113]
2024-06-13 08:41:13.186 29161-29333 INFO                      I  [libxmtp] envelope [3113] is equal to intent [3]
2024-06-13 08:41:13.189 29161-29333 INFO                      I  [libxmtp] Transaction Async being committed
2024-06-13 08:41:13.191 29161-29333 INFO                      I  [libxmtp] Transaction Async beginning
2024-06-13 08:41:13.191 29161-29333 INFO                      I  [libxmtp] client [CREATOR] is about to process external envelope [3114]
2024-06-13 08:41:13.192 29161-29333 INFO                      I  [libxmtp] Transaction Async being rolled back
2024-06-13 08:41:13.193 29161-29333 INFO                      I  [libxmtp] Transaction Async beginning
2024-06-13 08:41:13.193 29161-29333 INFO                      I  [libxmtp] client [CREATOR] is about to process external envelope [3115]
2024-06-13 08:41:13.194 29161-29333 INFO                      I  [libxmtp] Transaction Async being rolled back
2024-06-13 08:41:13.194 29161-29333 ERROR                     E  [libxmtp] Message processing errors: [OpenMlsProcessMessage(ValidationError(UnableToDecrypt(AeadError))), OpenMlsProcessMessage(ValidationError(UnableToDecrypt(AeadError)))]
2024-06-13 08:41:13.195 29161-29333 ERROR                     E  [libxmtp] receive error ReceiveErrors([OpenMlsProcessMessage(ValidationError(UnableToDecrypt(AeadError))), OpenMlsProcessMessage(ValidationError(UnableToDecrypt(AeadError)))])
2024-06-13 08:41:13.198 29161-29333 XMTPModule                V  groupMessages
2024-06-13 08:41:13.212 29161-29224 ReactNativeJS             I  'message', 'xmtp.org/text:1.0', 'hello1'
2024-06-13 08:41:13.212 29161-29224 ReactNativeJS             I  'message', 'xmtp.org/group_updated:1.0', 'Group Updated'
2024-06-13 08:41:13.213 29161-29224 ReactNativeJS             I  'message', 'xmtp.org/group_updated:1.0', 'Group Updated

This was referenced Jun 13, 2024
Closed
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@cameronvoell cameronvoell

Labels
bug Something isn't working Client App Group Chat - Prod
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Don't process same seq id welcome message twice xmtp/libxmtp
4 participants
@neekolas @cameronvoell @alexrisch @bwcDvorak