Data delivery issues

[qoqobolo]

Bug Report

There are three most obvious data delivery issues that don't have exact steps to reproduce but that we encounter quite often.
As discussed, describing them here for further investigation (cc @siphiuel )
Logs and other details will be added as any of these are encountered.

1. Data loss on a synced device
Most often this can be observed in group chats (as described in #16786 with more details) or in Status Community.

2. After background on iOS
Sometimes we face the situation when data (messages/contact or membership requests/etc) stops being sent/received on iOS device after some time in background.
To start receiving/sending data again, you need to reopen the app and/or relogin.

3. Significant delivery delays in the late afternoon (for European users)
Sometimes the delivery of messages/requests becomes especially long in the afternoon compared to the morning for time zones such as UTC+2, UTC +3.

4. Some particular kind of data stops being delivered for no apparent reason
For example, you still can receive messages and contact requests, but stop getting approved to join the community.
Or you can receive messages but can't receive contact requests.
Sometimes relogin works, sometimes it doesn't.

Note

Some of these scenarios may actually be the same thing. Unfortunately, it is not always possible to distinguish between a delay in delivery and a complete loss of data.

[qoqobolo]

Example with a contact request from e2e tests:

1. UserA sends CR to UserB
2. UserB accepts CR

Actual result:
UserB does not appear in UserA's contacts

cr_sender_admin.log
cr_receiver_member_2.log

[pavloburykh]

Another example of CR not delivered. Currently it is causing the whole e2e group of tests to fail.

CR_receiver_logcut.log
CR_sender_logcat.log

Here is a video from saucelab

Device 1 sends CR to Device 2 https://app.eu-central-1.saucelabs.com/tests/70c14d8c67c94b509409174a9d107f85?auth=5b7b8a386f5c29002365977c4ac0bb1f#52

Device 2 does not receive CR https://app.eu-central-1.saucelabs.com/tests/b71969cb18bd4787866cac6a1068d9b5?auth=ec1bb0869ff82b5b6049c79f280834b0#55

waiting time: 60 sec

[cammellos]

@pavloburykh do you have the geth.log for both sender/receiver please?

[pavloburykh]

@pavloburykh do you have the geth.log for both sender/receiver please?

hi @cammellos! Unfortunately all we have are the above attached logcat files.

[churik]

One more issue with data delivery which was found and investigated during PR testing - more context is here: #17091 (comment)

[yevh-berdnyk]

Example of missing a message in a community channel after user unblock, which causes e2e test fail in about 10% runs:

1. User A blocks user B
2. User A unblocks user B
3. User B sends a message 'Hurray! unblocked' in a community channel

SauceLabs session of user A: https://app.eu-central-1.saucelabs.com/tests/b263360bc45f418c9a108c656b5bb208?auth=1443824e95e223f47a2eac9dc6161cfc#553
SauceLabs session of user B: https://app.eu-central-1.saucelabs.com/tests/c1d02548696049bb9aed4b691d7c3e02?auth=a6476d1fecd4aa06e67331d099632cea#375

Logs:
user_A_geth.log
user_B_geth.log

user_A_logcat.log
user_B_logcat.log

[vitvly]

Example of missing a message in a community channel after user unblock, which causes e2e test fail in about 10% runs:

1. User A blocks user B
2. User A unblocks user B
3. User B sends a message 'Hurray! unblocked' in a community channel

SauceLabs session of user A: https://app.eu-central-1.saucelabs.com/tests/b263360bc45f418c9a108c656b5bb208?auth=1443824e95e223f47a2eac9dc6161cfc#553 SauceLabs session of user B: https://app.eu-central-1.saucelabs.com/tests/c1d02548696049bb9aed4b691d7c3e02?auth=a6476d1fecd4aa06e67331d099632cea#375

Logs: user_A_geth.log user_B_geth.log

user_A_logcat.log user_B_logcat.log

In this scenario User A does not receive a message, and in their geth.log there's lots of could not add wakuv2 filter for peer messages:

53591:t=2023-09-12T02:38:52+0000 lvl=warn msg="could not add wakuv2 filter for peer" peer=16Uiu2HAm1fVVprL9EaDpDw4frNX3CPfZu5cBqhtk9Ncm6WCvprpv
53600:t=2023-09-12T02:38:52+0000 lvl=warn msg="could not add wakuv2 filter for peer" peer=16Uiu2HAm1fVVprL9EaDpDw4frNX3CPfZu5cBqhtk9Ncm6WCvprpv
53610:t=2023-09-12T02:38:52+0000 lvl=warn msg="could not add wakuv2 filter for peer" peer=16Uiu2HAm1fVVprL9EaDpDw4frNX3CPfZu5cBqhtk9Ncm6WCvprpv
53913:t=2023-09-12T02:38:56+0000 lvl=warn msg="could not add wakuv2 filter for peer" peer=16Uiu2HAm1fVVprL9EaDpDw4frNX3CPfZu5cBqhtk9Ncm6WCvprpv
53917:t=2023-09-12T02:38:56+0000 lvl=warn msg="could not add wakuv2 filter for peer" peer=16Uiu2HAm1fVVprL9EaDpDw4frNX3CPfZu5cBqhtk9Ncm6WCvprpv
54047:t=2023-09-12T02:39:01+0000 lvl=warn msg="could not add wakuv2 filter for peer" peer=16Uiu2HAm1fVVprL9EaDpDw4frNX3CPfZu5cBqhtk9Ncm6WCvprpv

This happens when peer count dropped to zero and full resubscribe is in order. Also at the same time lots of could not unsubscribe from peer:

53419:t=2023-09-12T02:38:52+0000 lvl=eror msg="could not unsubscribe from peer" peerID=16Uiu2HAkyScd7DiwgMwzfw8CFFhznH3wRzciqEUfjDzn7vyimR8c error="failed to dial: failed to dial 16Uiu2HAkyScd7DiwgMwzfw8CFFhznH3wRzciqEUfjDzn7vyimR8c:\n  * [/ip4/134.209.135.195/tcp/30303] dial backoff"
53435:t=2023-09-12T02:38:52+0000 lvl=eror msg="could not unsubscribe from peer" peerID=16Uiu2HAkyScd7DiwgMwzfw8CFFhznH3wRzciqEUfjDzn7vyimR8c error="failed to dial: failed to dial 16Uiu2HAkyScd7DiwgMwzfw8CFFhznH3wRzciqEUfjDzn7vyimR8c:\n  * [/ip4/134.209.135.195/tcp/30303] dial backoff"

Message from UserB sent on 02:41:38:

user_B_geth.log
t=2023-09-12T02:41:38+0000 lvl=dbug msg=calculateSuggestions chatID=0x02bdd8711ce4de6f64cde9349e86df11b49f1ce9e817149e403957f1ac867b4d5ce8ab646d-2d6d-4a61-94ab-71fa65e71b51 fullText="Hurray! unblocked" num of mentionable user=1

Also there are lots of re-subscriptions to the same peer:

65312:t=2023-09-12T02:43:22+0000 lvl=info msg="wakuv2 filter subscription success" peer=16Uiu2HAm1fVVprL9EaDpDw4frNX3CPfZu5cBqhtk9Ncm6WCvprpv pubsubTopic=/waku/2/default-waku/proto contentTopics=[/waku/1/0x88ff4997/rfc26]
65688:t=2023-09-12T02:43:25+0000 lvl=info msg="wakuv2 filter subscription success" peer=16Uiu2HAm1fVVprL9EaDpDw4frNX3CPfZu5cBqhtk9Ncm6WCvprpv pubsubTopic=/waku/2/default-waku/proto contentTopics=[/waku/1/0x6ba82a67/rfc26]
65708:t=2023-09-12T02:43:25+0000 lvl=info msg="wakuv2 filter subscription success" peer=16Uiu2HAm1fVVprL9EaDpDw4frNX3CPfZu5cBqhtk9Ncm6WCvprpv pubsubTopic=/waku/2/default-waku/proto contentTopics=[/waku/1/0xde6e06b5/rfc26]
65844:t=2023-09-12T02:43:32+0000 lvl=info msg="wakuv2 filter subscription success" peer=16Uiu2HAm1fVVprL9EaDpDw4frNX3CPfZu5cBqhtk9Ncm6WCvprpv pubsubTopic=/waku/2/default-waku/proto contentTopics=[/waku/1/0x6ba82a67/rfc26]
66043:t=2023-09-12T02:43:42+0000 lvl=info msg="wakuv2 filter subscription success" peer=16Uiu2HAm1fVVprL9EaDpDw4frNX3CPfZu5cBqhtk9Ncm6WCvprpv pubsubTopic=/waku/2/default-waku/proto contentTopics=[/waku/1/0x6ba82a67/rfc26]
66356:t=2023-09-12T02:43:42+0000 lvl=info msg="wakuv2 filter subscription success" peer=16Uiu2HAm1fVVprL9EaDpDw4frNX3CPfZu5cBqhtk9Ncm6WCvprpv pubsubTopic=/waku/2/default-waku/proto contentTopics=[/waku/1/0x6ba82a67/rfc26]
66357:t=2023-09-12T02:43:42+0000 lvl=info msg="wakuv2 filter subscription success" peer=16Uiu2HAm1fVVprL9EaDpDw4frNX3CPfZu5cBqhtk9Ncm6WCvprpv pubsubTopic=/waku/2/default-waku/proto contentTopics=[/waku/1/0xde6e06b5/rfc26]
66570:t=2023-09-12T02:43:52+0000 lvl=info msg="wakuv2 filter subscription success" peer=16Uiu2HAm1fVVprL9EaDpDw4frNX3CPfZu5cBqhtk9Ncm6WCvprpv pubsubTopic=/waku/2/default-waku/proto contentTopics=[/waku/1/0xde6e06b5/rfc26]
67008:t=2023-09-12T02:43:58+0000 lvl=info msg="wakuv2 filter subscription success" peer=16Uiu2HAm1fVVprL9EaDpDw4frNX3CPfZu5cBqhtk9Ncm6WCvprpv pubsubTopic=/waku/2/default-waku/proto contentTopics=[/waku/1/0x6ba82a67/rfc26]
67025:t=2023-09-12T02:43:59+0000 lvl=info msg="wakuv2 filter subscription success" peer=16Uiu2HAm1fVVprL9EaDpDw4frNX3CPfZu5cBqhtk9Ncm6WCvprpv pubsubTopic=/waku/2/default-waku/proto contentTopics=[/waku/1/0xde6e06b5/rfc26]