[Local pairing] Application crash when pairing 3rd device

[igor-sirotin]

Problem

The app crashes here during local pairing, because there's no contactRequest.From in m.allContacts:

status-go/protocol/messenger_contacts.go

Line 282 in 9c59634

contact, _ := m.allContacts.Load(contactRequest.From)

At that point contactRequest.From is our public key.

Steps to reproduce

1. Alice [device-1]:
   • create account
   • send CR to Bob
2. Bob:
   • accept CR from Alice
3. Alice [device-2]:
   • local pairing from [device-1]
4. Alice [device-3]:
   • local pairing from [device-2]
   • <-- crash here during pairing

[igor-sirotin]

1. Pairing desktop-1 → desktop-2

1.1. During the first pairing, device-2 receives SYNC_INSTALLATION_CONTACT message with Bob contact, where:

ContactRequestLocalState  = 2 // ContactRequestStateSent
ContactRequestLocalClock  = 1687951105312   
ContactRequestRemoteState = 3 // ContactRequestStateReceived
ContactRequestRemoteClock = 1687951110959

1.2. At this stage, there's no CR for this contact (it will try to sync it later) so a new CR record is created in syncContactRequestForInstallationContact as implemented in #3495.

1.3. Because of ContactRequestLocalState == ContactRequestStateSent, we have outgoing == true here:

status-go/protocol/messenger_handler.go

Line 475 in 03f8237

contactRequest, err := m.generateContactRequest(clock, timestamp, contact, defaultContactRequestText(), outgoing)

1.4. Therefore, contactRequest.From == m.myHexIdentity() and contactRequest.ID is generated as default appending 0x20 to contact's public key.

1.5. We also receive some real contact request during syncing, but we don't save it, because there's such CR ID in the database. This looks suspicious to me, but anyway.

So after the first sync we end up with user_messages table containing one generated CR.

2. Pairing desktop-2 → desktop 3

2.1. Again, first the contact is synced, and we generate a fake CR for that contact, just as the first pairing.

2.2. Then device-3 syncs contact requests, and during that the generated CR is synced to device-3.
But comparing to 1.5, this time device-3 does find the CR (as it was generated in 2.1).
We try to load the From contact here:

status-go/protocol/messenger_contacts.go

Line 290 in 03f8237

contact, ok := m.allContacts.Load(contactRequest.From)

But there's no such contact with our public key.
As I understand this right, that's because we skip it here in HandleSyncInstallationContact:

status-go/protocol/messenger_handler.go

Lines 510 to 512 in 03f8237

	if message.Id == m.myHexIdentity() {
	return nil
	}

Devices state

	device 1	device 2	device 3
contacts table	Alice, Bob	Bob	Bob
user_messages table	<real-contact-request-id> from Alice to Bob, Accepted	0x<Bob-public-key>20 From Alice to Bob, Accepted	0x<Bob-public-key>20 From Alice to Bob, Accepted
state	✅ working, syncing	✅ working, syncing	❌ working, not syncing Crash when syncing CR from device-2

---

P.S. Another thing to mention, this "generated fake CR" has static Please add me to your contacts message.
Though I know we don't sync messages during pairing, maybe it would make sense to sync CR messages? Or at least the last one. 🤔

[igor-sirotin]

Pushed a test that reproduces the bug: #3627

Removing unneccessary details from log, this is what you will see:

2023-06-30T14:32:23.930+0300    INFO    pairing/sync_device_test.go:552 pairing Alice-1 and Alice-2
...
ERROR[06-30|14:32:25.210] failed to HandleSyncChatMessagesRead when HandleSyncRawMessages error="can't find chat"
WARN [06-30|14:32:25.210] syncContactRequestForInstallationContact: generated contact request contactRequest="clock:1688124745233 text:\"Please add me to your contacts\" chat_id:\"0x04c69081f6242463a34ba3c5d353d5dc4cc0c49fc0a57a2cc2827308c22648412f077eb9e210aff8fb0bb2ecb1a3c350c32065c6b79a44ed2e01cfaddb9acde867\" content_type:CONTACT_REQUEST "
ERROR[06-30|14:32:25.211] contact request not found                contactRequestID=0xf8784917646693cfbda6f8e48569fe954cc00b59ca8d8f2d5c344de7f07e82cf error="record not found"
ERROR[06-30|14:32:25.211] failed to HandleSyncContactRequestDecision when HandleSyncRawMessages error="record not found"
...
2023-06-30T14:32:25.214+0300    INFO    pairing/sync_device_test.go:560 pairing Alice-2 and Alice-3
...
INFO [06-30|14:32:26.167] syncContactRequestDecision               from=0x04c69081f6242463a34ba3c5d353d5dc4cc0c49fc0a57a2cc2827308c22648412f077eb9e210aff8fb0bb2ecb1a3c350c32065c6b79a44ed2e01cfaddb9acde86720
WARN [06-30|14:32:26.168] syncContactRequestForInstallationContact: generated contact request contactRequest="clock:1688124746190 text:\"Please add me to your contacts\" chat_id:\"0x04c69081f6242463a34ba3c5d353d5dc4cc0c49fc0a57a2cc2827308c22648412f077eb9e210aff8fb0bb2ecb1a3c350c32065c6b79a44ed2e01cfaddb9acde867\" content_type:CONTACT_REQUEST "
ERROR[06-30|14:32:26.169] failed to update contact request: contact not found contact id=0x04b6891e5fa4a3302f52c42539c36af9eda8fe71a48e43d203bfc31a16bfb700d41f5b318e404d4922f2815d7e9f7223d8099365393fb3a656ff6f928f170cc4e0

I've added, but intentionally commented the return for an unknown contact here:

status-go/protocol/messenger_contacts.go

Lines 286 to 291 in 45d914c

	contact, ok := m.allContacts.Load(contactRequest.From)
	if !ok {
	m.logger.Error("failed to update contact request: contact not found", zap.String("contact id", contactRequest.From))
	// TODO: Uncomment return error when #3667 crash is fixed
	// return nil, errors.New("failed to update contact request: contact not found")
	}

So that leads to a crash:

        github.com/status-im/status-go/protocol.(*Messenger).getOneToOneAndNextClock(0x140018cadc0, 0x0)
                /Users/igorsirotin/Repositories/Status/status-desktop/vendor/status-go/protocol/messenger_chats.go:15 +0x2c
        github.com/status-im/status-go/protocol.(*Messenger).updateAcceptedContactRequest(0x140018cadc0, 0x0, {0x14002fa2510, 0x86})
                /Users/igorsirotin/Repositories/Status/status-desktop/vendor/status-go/protocol/messenger_contacts.go:293 +0x498
        github.com/status-im/status-go/protocol.(*Messenger).HandleSyncContactRequestDecision(0x103f6327a?, 0x14003e7a700, {0x1890c1369d1, {0x14002fa2510, 0x86}, 0x0, {}, {0x0, 0x0, 0x0}, ...})
                /Users/igorsirotin/Repositories/Status/status-desktop/vendor/status-go/protocol/messenger_handler.go:3229 +0x54
        github.com/status-im/status-go/protocol.(*Messenger).HandleSyncRawMessages(0x140018cadc0, {0x14001bf1200, 0xf, 0x24?})
                /Users/igorsirotin/Repositories/Status/status-desktop/vendor/status-go/protocol/messenger_sync_raw_messages.go:192 +0x2008
        github.com/status-im/status-go/server/pairing.(*SyncRawMessageHandler).HandleRawMessage(0x14003d41048?, 0x103d8d7b0?, 0x1400046d800?, {0x14000394d30?, 0x800?}, {0x14000394d20, 0x7}, 0x14000428f00)
                /Users/igorsirotin/Repositories/Status/status-desktop/vendor/status-go/server/pairing/raw_message_handler.go:125 +0x428