Shards.test: messages are not received instantly, restart is required when updating from 0.14 to 0.15

[anastasiyaig]

Description

I updated my app being on 0.14 to latest release of 0.15 and I cant receive instant messages in 0.15 on shards.test fleet. Restart is required to get them

NOTE: this issue does not happen to the same account restored from seed (with clean DB)

1. open app
2. add a contact
3. send some messages to that contact
4. check the receiver - no messages
5. restart the app on receiver side - messages received from restart

I was having 6 peers when experimenting with that. Attaching geth.log

Messages ids that i was not able to receive instantly:

0xf2fd5bca122d1b30cd2f58f555b6136c90f9aa16b51ddc7af1f298488bbb4bcc
0x67951bc1527eb29800ba120b4cb73f0972e0f8cfe5b8fab2349ee25c9c0fc82f
0x8f5d20fad9f935a74dfb9e1ddd3ec74cf6d2dce2031c8ade278040a125c7e9d2

geth.log.zip

[anastasiyaig]

@chaitanyaprem @richard-ramos pls take a look

[igor-sirotin]

Sender side log. Unfortunately, it was not debug level 🙁

geth_sender.log

[anastasiyaig]

so it turns out the problem is reproducible when you have a DB migrated (0.14 to 0.15 in my case). Not sure do we need to do anything about it? Restoring account from seed works okay, 1x1 and group messages are received just fine

[anastasiyaig]

@richard-ramos i tried to reproduce today this way:

• install 0.14.1 and send a contact request to @igor-sirotin (he was on shards.test, did not receive contact request -> expected)
• update to 0.15 -> Igor confirmed he received a contact request
• try to receive some messages -> all works just fine

I was not able to reproduce the bug above with this steps. When i was reporting an issue, i was using my main app instance which has DB migrations for a long time (from 0.12 i think). God knows what happened in between
i think i will close the ticket for now :(

[richard-ramos]

Let's reopen this issue if it happens again. Ideally it would be useful to see the result of {"method":"settings_nodeConfig"} before restarting.

[anastasiyaig]

@plopezlpz hey, i read in the community you had a similar problem recently with @kaichaosun , can u provide some logs?

[plopezlpz]

Received a 1:1 message only after restarting, Kaichao sent me a message 25/01/24 and I received it after restarting on the 28/01/24, my local logs about this message when I finally received them upon restarting on the 28th (3 days later):

INF 2024-01-28 09:14:34.273+02:00 received                                   topics="signals-manager" tid=2419081 file=messages.nim:72 signal=messages.new messageID=0xabd99bfc74299ead23c8848203427dadd1ffd20734f38afc355d41ad1c581aaa
DBG 2024-01-28 09:14:37.426+02:00 [threadpool task thread] initiating task   topics="task-threadpool" tid=2419166 file=threadpool.nim:54 messageType=AsyncGetMessageByMessageIdTaskArg:ObjectType threadid=2419166 task="{\"$type\":\"AsyncGetMessageByMessageIdTaskArg:ObjectType\",\"requestId\":\"5536ef2b-afe9-409b-a3c4-f9b7fe8b9259\",\"messageId\":\"0xabd99bfc74299ead23c8848203427dadd1ffd20734f38afc355d41ad1c581aaa\",\"vptr\":105553121436480,\"slot\":\"onAsyncGetMessageById\",\"tptr\":4438422896}"
DBG 2024-01-28 09:14:39.730+02:00 [threadpool task thread] initiating task   topics="task-threadpool" tid=2419169 file=threadpool.nim:54 messageType=AsyncGetMessageByMessageIdTaskArg:ObjectType threadid=2419169 task="{\"$type\":\"AsyncGetMessageByMessageIdTaskArg:ObjectType\",\"requestId\":\"cc0e5982-df95-4af7-b1ad-2c1eee62652a\",\"messageId\":\"0xabd99bfc74299ead23c8848203427dadd1ffd20734f38afc355d41ad1c581aaa\",\"vptr\":105553121436480,\"slot\":\"onAsyncGetMessageById\",\"tptr\":4438422896}"

[chaitanyaprem]

Received a 1:1 message only after restarting, Kaichao sent me a message 25/01/24 and I received it after restarting on the 28/01/24, my local logs about this message when I finally received them upon restarting on the 28th (3 days later):

INF 2024-01-28 09:14:34.273+02:00 received                                   topics="signals-manager" tid=2419081 file=messages.nim:72 signal=messages.new messageID=0xabd99bfc74299ead23c8848203427dadd1ffd20734f38afc355d41ad1c581aaa
DBG 2024-01-28 09:14:37.426+02:00 [threadpool task thread] initiating task   topics="task-threadpool" tid=2419166 file=threadpool.nim:54 messageType=AsyncGetMessageByMessageIdTaskArg:ObjectType threadid=2419166 task="{\"$type\":\"AsyncGetMessageByMessageIdTaskArg:ObjectType\",\"requestId\":\"5536ef2b-afe9-409b-a3c4-f9b7fe8b9259\",\"messageId\":\"0xabd99bfc74299ead23c8848203427dadd1ffd20734f38afc355d41ad1c581aaa\",\"vptr\":105553121436480,\"slot\":\"onAsyncGetMessageById\",\"tptr\":4438422896}"
DBG 2024-01-28 09:14:39.730+02:00 [threadpool task thread] initiating task   topics="task-threadpool" tid=2419169 file=threadpool.nim:54 messageType=AsyncGetMessageByMessageIdTaskArg:ObjectType threadid=2419169 task="{\"$type\":\"AsyncGetMessageByMessageIdTaskArg:ObjectType\",\"requestId\":\"cc0e5982-df95-4af7-b1ad-2c1eee62652a\",\"messageId\":\"0xabd99bfc74299ead23c8848203427dadd1ffd20734f38afc355d41ad1c581aaa\",\"vptr\":105553121436480,\"slot\":\"onAsyncGetMessageById\",\"tptr\":4438422896}"

This looks like a different issue compared the the one seen during upgrade.
Also, it would be good to have debug logs when message was not received to investigate the cause.

[igor-sirotin]

@plopezlpz @kaichaosun can you guys please post:

1. Full application log: Status/logs/<corresponding-date-time>.log
2. Full status-go log: Status/data/geth-<corresponding-date-time>.log (or just geth.log if it's the active one).

And we're speaking of message 0xabd99bfc74299ead23c8848203427dadd1ffd20734f38afc355d41ad1c581aaa, right?

[plopezlpz]

logs.zip

Receiving peer logs of the 25th & 28th, message id only shows up on the 28th when I received it.

[kaichaosun]

logs.zip

This is logs after I upgrade the app to v0.15.0 today. There is not much info in previous logs with old version app.

[igor-sirotin]

I was able to reproduce the issue that @plopezlpz and @kaichaosun faced.

To reproduce I used 2 separate devices to keep them online/offline independently.

1. desktop: turn off WiFi (or other internet connection)
2. mobile: send message A
3. mobile: wait for message to be sent (message opacity goes to 100%)
4. mobile: go to flight mode (to prevent messages resending)
5. desktop: wait 2 minutes (the duration is heuristic, but the idea is not to receive the message A by relay)
6. desktop: turn on WiFi
7. desktop: wait some reasonble time, message A is not received <----- ❌ error here
8. desktop: right-click the chat -> "Fetch messages" <----- message A fetched

Fix here: status-im/status-go#4651

[kaichaosun]

Here is the geth.log in case it's still needed.