Endless fetching and hot phone on recovered account with 1:1, group and public chats

annadanchenko commented 5 years ago

Description

Type: Bug

Summary: Recovered account with 9 1:1 chats, 2 groups. Created one new group, added 9 members there and join couple of public chats, installed gfycat extension. At some point I've noticed that fetching indicator constantly moving and phone gets hot.

I've paired this device with another to check if can repro on another phone (I can't) and switched to other mailserver (1st and 2nd in the list) but got popup that "can't connect to mailserver, select another"...

Additional Information

Status version: release build 19 for 0.9.33
Operating System: Android 9, real google pixel xl

Logs

Status.log (7 Mb)

geth.log

annadanchenko commented 5 years ago

@cammellos I could reproduce it on fresh account with group chat of 9 members that send some messages inside it. It also joined 1 public chat and one 1:1 chat

cammellos commented 5 years ago

@annadanchenko do you have logs for that? it should not be related to group chats/1-to-1 etc, it might happen randomly on any fresh account (judging from the previous logs)

annadanchenko commented 5 years ago

@annadanchenko do you have logs for that? it should not be related to group chats/1-to-1 etc, it might happen randomly on any fresh account (judging from the previous logs)

sorry, I don't (had disabled logs on ios)

Serhy commented 5 years ago

I've also got this issue (with similar logs and it's size attached in description). Could not reproduce on 0.9.32 Release. Can reproduce on 0.9.33 Release. Below scenario looks good for me on iOS Release 0.9.33, but 4 of 5 times on Android 7 I've got mailserver round-robin'ing (that 5th "lucky" time got successful connection on 5-6th mailsever request). To keep the steps: 1) Install fresh Status app. 2) Recover an account seedphrase z z z z z z z z z z z z z. It should receive 1 contact request and 2 group chats from offline inbox. 3) Add the account in contacts and join those group chats 4) Create two more new group chats with the contact you've added 5) Close app 6) Open app, login to account. Wait until you successfully connected to mailserver.

cammellos commented 5 years ago

@Serhy could you attach the logs please? thanks!

asemiankevich commented 5 years ago

i saw very long fetching messages (blue line at the top) in develop (nightly) Status-debug-logs.zip

Serhy commented 5 years ago

@cammellos here are logs for 1-4th step (took 3-4 mins to finish sync for me). LogsReleaseAccountrecovered.log I've reopened an app and gathering logs for 5-6 step in https://github.com/status-im/status-react/issues/7436#issuecomment-461082392

cammellos commented 5 years ago

cool, so the issue from all logs seems to be pointed to expired mailserver requests, so nothing new so far, thanks.

Serhy commented 5 years ago

Yes, the same (with constant mailserver.request.expired) after I restarted an app and since 10 minutes it could not connect to any of the mailserver (logs: 2logcat.log

Serhy commented 5 years ago

With the build from https://github.com/status-im/status-react/pull/7439 - it looks good for me. Same scenario, mailsever(s) connected fine.

Serhy commented 5 years ago

With #7439 included in 0.9.33 issue still reproduced for me :( Confirmed for my own account after upgraded from 0.9.32. As well as for scenario in https://github.com/status-im/status-react/issues/7436#issuecomment-461082392

logcat.log after app with account (having 4 1-1 chats and 4 Group chats (two of them created from the previous release build without #7439)

mandrigin commented 5 years ago

it looks like we have some other request that doesn't take limit into account (always 1000): 02-07 11:24:59.442 15810 15868 I ReactNativeJS: INFO [status-im.mailserver.core:575] - mailserver: message request 0xdc32dbd0bc4ae20f57272c071ca2d8bbd3ac072c5b103120d82114e61abfd444 expired for mailserver topic ("0xf8946aac") from 1549445069 to 1549531469 cursor nil limit 1000

cammellos commented 5 years ago

logsAndlAgs.log Condensed logs with only relevant events

Serhy commented 5 years ago

@cammellos In order to exclude items that bring us really long sync I performed these steps and split logs where sync was long enough to show what's going on while particular step executed.

0) Install fresh Release 0.9.33. 1) Start app. Recover account. (valid seedphrase). Wait until syncing bar is finished at top of Home screen… Logs only for this step: AccRecovered.log 2) Close app. Force stop Status app. 3) Open app. Connected to mailserver right away. Enable INFO log level. Close app. Force stop Status app. 4) Open app. Add new contact (iOSContact2 added via scan of his QR code). Create two group chats with this contact. Close app. Logs only for this step: AccAddingNewContactAndTwoGH.log 5) Open app. Wait until sync is finished. Close app. Logs for this step: RestartAfterNewContact.log 6) Open app. Wait until sync is finished. Instantly connected, I didn't wait for sync. Close app. Force stop. 7) Open app. Wait until sync is finished. Instantly connected, I didn't wait for sync. Join unique public chat where no messages to fetch (#newasdueuejdjd). Close app. 8) Open app. Wait until sync is finished. Instantly connected, I didn't wait for sync. 9) Add one more contact (iOSContact3 added via scan of his QR code). Close app. 10) Open app. Wait until sync is finished. Instantly connected (to mail-02.hongkong mailsever). I didn't wait for sync. 11) Create two more Group Chats with Contact3 only. Close app. 12) Open app. Wait until sync is finished. Created2moreGHwithContact3.log

No messages sent at all in above scenario. With above it looks like Group Chats only impacts on sync time.

mandrigin commented 5 years ago

That is no surprise because we are using the same topic for them of everyone at all... I think this issue is only when you recover account, but not if you upgrade, right?

cammellos commented 5 years ago

It is a bit surprising though, as if you join a group chat, we don't fetch any historical message, as there's no reason, because we already are subscribed to that topic. so we don't re-fetch the shared topic. therefore theoretically should not have any impact on it, also just looking at the logs, it seems although it fetched already the shared topic, it re-fetches 24 hours on login/logout, but I need to inspect them more carefully.

cammellos commented 5 years ago

Timeline for the first log: https://hackmd.io/S6YUU0QoSXipp2kokQA_fA?edit

syncing took around ~2 minutes 30s many expired requests, and the process had to start again as it failed 3 times in a row.

Timeline - HackMD

Serhy commented 5 years ago

Scenario without Group Chats:

1) Recover new account (film robot picnic film robot picnic film robot film robot picnic robot) 2) Add new contact (iOScontact) 3) Join #status, #status-chunese, #daaps, #ethereum, #introductions, #pubtosync public chats 4) Messages recevied from public chats fine. 5) Re-open app. Sync finished < 7 sec. Post several text messages in 1-1 chat and in #pubtosync.
5) Re-open app. Sync finished < 7 sec. 5) Re-open app. Sync finished < 7 sec. 6) Delete some of public chats with messages. Clear histroy in #pubtosync and clear history in 1-1 chat. 7) Re-open app. Sync finished < 7 sec. 8) Close app. Enable Airplane mode. Sent to this account by iOSContact1 in 1-1 chat text messages, 'request ETH`, and in #pubtosync chat 20 text messages. Wait 2 mins. 9) Disable Airplane mode. Received PNs for 1-1 chat messages. 10) Tap on PN. Status app opened. Login to account. Sync finished < 7 sec.

With no GroupChats looks good for me.

Serhy commented 5 years ago

But, additionally to https://github.com/status-im/status-react/issues/7436#issuecomment-461420406

Request to 'Fetch 24h history' in 1-1 chat. Sync took ~3mins. Logs: Fetch24hIn1to1.log

cammellos commented 5 years ago

From logs 3 and 4: 1) It re-fetched 24hours of shared topic in both cases 2) quite a few requests failed because are either expired, or 3s limit

Syncing of other topics (public chat & group chat) correctly synced from offline time.

Essentially the issue is that something is resetting the time we fetch messages for the discovery topic, and is re-fetched at each login.

cammellos commented 5 years ago

Ok I have got it, there's some issues with one of the functions, not sure I fully understand what's going on and which assumptions it makes, but basically when you create a group chat it creates a separate topic, which somehow makes this fn reset the discovery topic, so probably too fragile to fix for the release, but I can just disable creating the topic for group chats, as it's not used currently, and it's only for forward compatibility.

0xc1c4da commented 5 years ago

➤ Jarrad Hope commented:

testing

0xc1c4da commented 5 years ago

➤ Hester Bruikman commented:

no signal received that all messages are received;

improve identification of envelops that are relevant recognize last messages to recipient

Dmitry Shulyak can you give an estimate of when this issue will be merged? This week feasible?

Issue needs:

documentation Dmitry Shulyak
Assess required changes React Roman Volosovskyi (likely less than day)

0xc1c4da commented 5 years ago

➤ Dmitry Shulyak commented:

Hester Bruikman there are several possible causes of such issue. application either:

can't download all history in allocated time window, and because of it will re-try again and again
app downloaded all data, but status-go part didn't report that it was downloaded correctly

for the latter we need to update status-go dependency and change how status-react waits for history fetching completion. maybe Roman Volosovskyi can tell how long it will take.

instead of waiting for completion signal, and then waiting for envelope that matches last envelope hash, app should wait for completion signal and after that fetch messages from whisper filters. completion signal kinda guarantees that filters are already filled.

i am not sure what kind of documentation will be useful, as it is not a user facing thing. i can describe why we need to use this exact flow. here for example: https://github.com/status-im/status-go/tree/develop/services/shhext#signals

0xc1c4da commented 5 years ago

➤ Hester Bruikman commented:

Dmitry Shulyak apologies for the delay in responding! It would be great if you could describe why we need this flow indeed. Regardless of whether it's user facing. Seems like it impacts performance if this flow is not followed.

I can't imagine this is the first time this sequence is being discussed; so I want to make sure I'm not missing any reasoning. Roman Volosovskyi can you help me understand:

Does the app currently start fetching after the completion signal?
Does it wait for other events before it starts fetching. If so, why?

0xc1c4da commented 5 years ago

➤ Roman Volosovskyi commented:

instead of waiting for completion signal, and then waiting for envelope that matches last envelope hash, app should wait for completion signal and after that fetch messages from whisper filters. completion signal kinda guarantees that filters are already filled

We do not wait for an envelope which matches lastEnvelopeHash: we treat the request as completed after mailserver.request.completed signal.

We do not trigger fetching of filters in some special way in the app, it is done by regular polling.

Dmitry Shulyak

Is it guaranteed that we will receive lastEnvelopeHash message on the client side, i.e. lastEnvelopeHash belongs to envelop which matches to at least one of sym/asym key specified?
Even if so, can we process this on the server side, so that status-go files mailserver.request.completed when that message with the last envelope is confirmed to be processed (via shhext_confirmMessagesProcessedByID)

Hester Bruikman

Does the app currently start fetching after the completion signal?

no, fetching is started on log in and whenever a new filter (e.g. chat or contact) is added, and it happens periodically with some interval

Does it wait for other events before it starts fetching.

nope

0xc1c4da commented 5 years ago

➤ Dmitry Shulyak commented:

We do not wait for an envelope which matches lastEnvelopeHash: we treat the request as completed after mailserver.request.completed signal.

then we have another issue. previously signal wasn't sent after all envelopes were added to the filters. so there was always a chance that we will be missing envelopes

i changed that in recent status-go update, signal now is sent after messages were added to filters. but if filters are polled concurrently then we have kinda same issue

Is it guaranteed that we will receive lastEnvelopeHash message on the client side, i.e. lastEnvelopeHash belongs to envelop which matches to at least one of sym/asym key specified?

no, there is no such guarantee

Even if so, can we process this on the server side, so that status-go files mailserver.request.completed when that message with the last envelope is confirmed to be processed (via shhext_confirmMessagesProcessedByID)

i dont think that this is possible. again because last envelope hash isn't visible on the react side.

and i am not sure that we can easily add such guarantee without reworking history delivery protocol

flexsurfer commented 4 years ago

@Serhy do you think we can close this?

Serhy commented 4 years ago

Yes, that's an old issue which is fixed in V1. Closing.

status-im / status-mobile