Got "Connecting to peers" or "Offline" and couldn't send new messages after going back from sleep mode

[churik]

Description

Type: Bug
Summary: can reproduce it constantly on Mac OSx VM 10.13.6, but cannot find exact action on the local computer.
When VM came back from sleep mode, app doesn't detect online mode and all messages, sent from this state will be never received.

Expected behavior

can send\receive messages

Actual behavior

"Connecting to peers", messages are displayed as sent, but they are not sent.

Reproduction

• Open Status
• Log in
• Join public channel
• Go to sleep mode for ~5 mins
• Go back from sleep mode

NOTE: issue is gone after app restarting

Additional Information

• Status version: desktop nightly 18/10/18
• Operating System: Mac OSx 10.13.6 (used VM in Parallels)

Logs

https://drive.google.com/open?id=1R9nhxD83qYycpUYNeUHdnYJR57WU4HLy

Meet Google Drive – One place for all your files

Google Drive is a free way to keep your files backed up and easy to reach from any phone, tablet, or computer. Start with 15GB of Google storage – free.

[chadyj]

@goranjovic Did you have this issue on Linux too?

[goranjovic]

@chadyj No, but I do constantly have it on Mac

[churik]

Can be reproducible on mobile as well, only restarting app helps (faced with this on IOS and on Android 7.0 (Genymotion emulator, Samsung Galaxy S7))

[goranjovic]

Also two hackaton participants mentioned that they had this problem on genymotion run within osx. Restarting the app helped.

[churik]

See: #6284 (comment) for more info

[cammellos]

@churik can you still replicate? I can't replicate on my local machine or android. If you do, it would be helpful to get the Status.log.

So far what I have:

1. it seems the reason is that NetInfo is not notifying us of a network change, when switching from online->offline (here are some logs, https://pastebin.com/jACzPFSW , no connection-status-change event is fired). getSyncing is probably not the culprit (it might also be a cause of the Offline banner) as people have reported having the send button disabled, which is disabled only when network-status is offline

2. On desktop at least, it connects to http://google.com to know that it is connected to the network, so that might also be another source for the problem, although I saw it happening on mobile as well, so unlikely.

A potential band-aid would be to poll net-info periodically, but that would only help if we were not notified, but the internal state is otherwise ok (i.e react-native knows that is online, but for whatever reason the event was not fired/ the listener was not attached correctly).

Other people seems to have similar issues facebook/react-native#8615 , and some rolled out their own connection checks, which is a solution, although heavy-handed.

If anyone can replicate, please send logs!

Pastebin

17:16:14.387 - D - [RCTStatus] - ::onStatusGoEvent call - event: {"type":"disco - Pastebin.com

[churik]

@cammellos yes, I can still reproduce it (Mac OSx, go offline ~5 min, go back online. Reproducibility ~20%)
There are logs:

t=2018-11-29T10:56:22+0100 lvl=info msg="LES protocol is disabled" package=status-go/node
t=2018-11-29T10:56:22+0100 lvl=info msg="SHH protocol is disabled" package=status-go/node
t=2018-11-29T10:56:22+0100 lvl=info msg="Status service api is disabled" package=status-go/node
t=2018-11-29T10:56:22+0100 lvl=info msg="Starting peer-to-peer node"     instance=StatusIM/darwin-amd64/go1.10.3
t=2018-11-29T10:56:22+0100 lvl=info msg="Starting P2P networking"
t=2018-11-29T10:56:22+0100 lvl=info msg="RLPx listener up"               self="enode://c3a3e90d1512b469d67373b2bd0ae5366cd4bc440dcd43d538b5567b868b51bf9cbecbd8d625e9603da75ea93c12133dedac8bfd4fb4e0584bf84a407145066e@[::]:52021?discport=0"
t=2018-11-29T10:56:22+0100 lvl=info msg="Handlers registered"            package=status-go/api.StatusBackend
t=2018-11-29T10:56:22+0100 lvl=info msg="Account reselected"             package=status-go/api.StatusBackend
t=2018-11-29T10:56:28+0100 lvl=info msg="LES protocol is disabled"       package=status-go/node
t=2018-11-29T10:56:28+0100 lvl=info msg="Status service api is disabled" package=status-go/node
t=2018-11-29T10:56:28+0100 lvl=info msg="Starting peer-to-peer node"     instance=StatusIM/darwin-amd64/go1.10.3
t=2018-11-29T10:56:28+0100 lvl=info msg="Starting P2P networking"
t=2018-11-29T10:56:28+0100 lvl=info msg="started whisper v.6.0"
t=2018-11-29T10:56:28+0100 lvl=info msg="RLPx listener up"               self="enode://c3a3e90d1512b469d67373b2bd0ae5366cd4bc440dcd43d538b5567b868b51bf9cbecbd8d625e9603da75ea93c12133dedac8bfd4fb4e0584bf84a407145066e@[::]:52030?discport=0"
t=2018-11-29T10:56:28+0100 lvl=info msg="UDP listener up"                net=enode://c3a3e90d1512b469d67373b2bd0ae5366cd4bc440dcd43d538b5567b868b51bf9cbecbd8d625e9603da75ea93c12133dedac8bfd4fb4e0584bf84a407145066e@[::]:57730
t=2018-11-29T10:56:28+0100 lvl=info msg="Handlers registered"            package=status-go/api.StatusBackend
t=2018-11-29T10:56:28+0100 lvl=info msg="Account reselected"             package=status-go/api.StatusBackend
t=2018-11-29T10:56:28+0100 lvl=info msg="Whisper identity selected"      id=4b45fe464b373e196d7a98ba9df5c76cbc82d763945519b89f82afb9d6d576f3 key=0x048c19861f5ebd87a24b5582a55322bf602673f18a21ed10dd728346df2aae3cd141d9a43bdaa922c29df3eef11456d28a3cf3f15e9cb4d0e6f16ab8bc5a70901c
t=2018-11-29T10:56:28+0100 lvl=info msg="Initialized encryption service" package=status-go/services/sshext.chat installationID=7a6b5420-5f2c-5d85-92eb-fd7d746937e3
t=2018-11-29T10:56:30+0100 lvl=info msg="Difference with ntp servers"    offset=-5.836653414s
t=2018-11-29T10:56:31+0100 lvl=info msg=RequestMessages                  package=status-go/services/sshext.PublicAPI request="{MailServerPeer:enode://da61e9eff86a56633b635f887d8b91e0ff5236bbc05b8169834292e92afb92929dcf6efdbf373a37903da8fe0384d5a0a8247e83f1ce211aa429200b6d28c548@47.91.156.93:30504 From:1543484747 To:1543485391 Limit:0 Cursor: Topic:[0 0 0 0] Topics:[[205 66 55 96] [248 148 106 172]] SymKeyID:e7c473af0f988d0f3fcd6f0509e973b0c23a19342bf0ff1851ca8ee6dcc900fa Timeout:30ns}"
t=2018-11-29T10:56:47+0100 lvl=info msg=RequestMessages                  package=status-go/services/sshext.PublicAPI request="{MailServerPeer:enode://da61e9eff86a56633b635f887d8b91e0ff5236bbc05b8169834292e92afb92929dcf6efdbf373a37903da8fe0384d5a0a8247e83f1ce211aa429200b6d28c548@47.91.156.93:30504 From:1543484747 To:1543485407 Limit:0 Cursor: Topic:[0 0 0 0] Topics:[[205 66 55 96] [248 148 106 172]] SymKeyID:e7c473af0f988d0f3fcd6f0509e973b0c23a19342bf0ff1851ca8ee6dcc900fa Timeout:30ns}"
t=2018-11-29T10:56:47+0100 lvl=info msg="message loop"                   peer=da61e9eff86a56633b635f887d8b91e0ff5236bbc05b8169834292e92afb92929dcf6efdbf373a37903da8fe0384d5a0a8247e83f1ce211aa429200b6d28c548 err=EOF
t=2018-11-29T10:56:51+0100 lvl=info msg="message loop"                   peer=03f21684e777341df7f1b93888c9ba13a4d15130bb3c2d4fb13e817035b6cd6f3ed3dad1cd6c48dc995b17a2f4005188bae6d74d19d361a789c0f7085675a7f2 err=EOF
t=2018-11-29T10:56:51+0100 lvl=info msg="UDP listener up"                net=enode://c3a3e90d1512b469d67373b2bd0ae5366cd4bc440dcd43d538b5567b868b51bf9cbecbd8d625e9603da75ea93c12133dedac8bfd4fb4e0584bf84a407145066e@[::]:50234
t=2018-11-29T10:56:51+0100 lvl=info msg="message loop"                   peer=c7e00e5a333527c009a9b8f75659d9e40af8d8d896ebaa5dbdd46f2c58fc010e4583813bc7fc6da98fcf4f9ca7687d37ced8390330ef570d30b5793692875083 err=EOF
t=2018-11-29T10:57:01+0100 lvl=info msg=RequestMessages                  package=status-go/services/sshext.PublicAPI request="{MailServerPeer:enode://da61e9eff86a56633b635f887d8b91e0ff5236bbc05b8169834292e92afb92929dcf6efdbf373a37903da8fe0384d5a0a8247e83f1ce211aa429200b6d28c548@47.91.156.93:30504 From:1543484747 To:1543485421 Limit:0 Cursor: Topic:[0 0 0 0] Topics:[[205 66 55 96] [248 148 106 172]] SymKeyID:e7c473af0f988d0f3fcd6f0509e973b0c23a19342bf0ff1851ca8ee6dcc900fa Timeout:30ns}"
t=2018-11-29T10:57:16+0100 lvl=info msg="message loop"                   peer=da61e9eff86a56633b635f887d8b91e0ff5236bbc05b8169834292e92afb92929dcf6efdbf373a37903da8fe0384d5a0a8247e83f1ce211aa429200b6d28c548 err=EOF
t=2018-11-29T10:57:16+0100 lvl=info msg=RequestMessages                  package=status-go/services/sshext.PublicAPI request="{MailServerPeer:enode://531e252ec966b7e83f5538c19bf1cde7381cc7949026a6e499b6e998e695751aadf26d4c98d5a4eabfb7cefd31c3c88d600a775f14ed5781520a88ecd25da3c6@35.225.227.79:30504 From:1543485421 To:1543485436 Limit:0 Cursor: Topic:[0 0 0 0] Topics:[[205 66 55 96] [248 148 106 172]] SymKeyID:be04eb4ac73e767f0418258a46eea6d4de317e9af0b92561cd10dc7af7207b3c Timeout:30ns}"
t=2018-11-29T10:57:17+0100 lvl=info msg=RequestMessages                  package=status-go/services/sshext.PublicAPI request="{MailServerPeer:enode://531e252ec966b7e83f5538c19bf1cde7381cc7949026a6e499b6e998e695751aadf26d4c98d5a4eabfb7cefd31c3c88d600a775f14ed5781520a88ecd25da3c6@35.225.227.79:30504 From:1543485421 To:1543485436 Limit:0 Cursor: Topic:[0 0 0 0] Topics:[[205 66 55 96] [248 148 106 172]] SymKeyID:be04eb4ac73e767f0418258a46eea6d4de317e9af0b92561cd10dc7af7207b3c Timeout:30ns}"
t=2018-11-29T10:57:19+0100 lvl=info msg="message loop"                   peer=531e252ec966b7e83f5538c19bf1cde7381cc7949026a6e499b6e998e695751aadf26d4c98d5a4eabfb7cefd31c3c88d600a775f14ed5781520a88ecd25da3c6 err=EOF
t=2018-11-29T10:57:20+0100 lvl=info msg=RequestMessages                  package=status-go/services/sshext.PublicAPI request="{MailServerPeer:enode://8a64b3c349a2e0ef4a32ea49609ed6eb3364be1110253c20adc17a3cebbc39a219e5d3e13b151c0eee5d8e0f9a8ba2cd026014e67b41a4ab7d1d5dd67ca27427@206.189.243.168:30504 From:1543485436 To:1543485439 Limit:0 Cursor: Topic:[0 0 0 0] Topics:[[205 66 55 96] [248 148 106 172]] SymKeyID:b340528d164082f1cb783e488163b2abc4f2ff5341a7bef62ee44689a578117a Timeout:30ns}"
t=2018-11-29T10:57:22+0100 lvl=info msg="message loop"                   peer=8a64b3c349a2e0ef4a32ea49609ed6eb3364be1110253c20adc17a3cebbc39a219e5d3e13b151c0eee5d8e0f9a8ba2cd026014e67b41a4ab7d1d5dd67ca27427 err=EOF
t=2018-11-29T10:57:22+0100 lvl=info msg=RequestMessages                  package=status-go/services/sshext.PublicAPI request="{MailServerPeer:enode://c42f368a23fa98ee546fd247220759062323249ef657d26d357a777443aec04db1b29a3a22ef3e7c548e18493ddaf51a31b0aed6079bd6ebe5ae838fcfaf3a49@206.189.243.162:30504 From:1543485439 To:1543485442 Limit:0 Cursor: Topic:[0 0 0 0] Topics:[[205 66 55 96] [248 148 106 172]] SymKeyID:1f83a6d44490efc2206cdd155d4f1358c6b55a3a924cea12268b6b7dc4246f23 Timeout:30ns}"
t=2018-11-29T10:57:37+0100 lvl=info msg="message loop"                   peer=c7e00e5a333527c009a9b8f75659d9e40af8d8d896ebaa5dbdd46f2c58fc010e4583813bc7fc6da98fcf4f9ca7687d37ced8390330ef570d30b5793692875083 err=EOF
t=2018-11-29T10:57:37+0100 lvl=info msg="message loop"                   peer=2af8f4f7a0b5aabaf49eb72b9b59474b1b4a576f99a869e00f8455928fa242725864c86bdff95638a8b17657040b21771a7588d18b0f351377875f5b46426594 err=EOF
t=2018-11-29T10:57:37+0100 lvl=info msg="UDP listener up"                net=enode://c3a3e90d1512b469d67373b2bd0ae5366cd4bc440dcd43d538b5567b868b51bf9cbecbd8d625e9603da75ea93c12133dedac8bfd4fb4e0584bf84a407145066e@[::]:54903
t=2018-11-29T10:57:37+0100 lvl=info msg="message loop"                   peer=207e53d9bf66be7441e3daba36f53bfbda0b6099dba9a865afc6260a2d253fb8a56a72a48598a4f7ba271792c2e4a8e1a43aaef7f34857f520c8c820f63b44c8 err=EOF
t=2018-11-29T10:57:38+0100 lvl=info msg="message loop"                   peer=c42f368a23fa98ee546fd247220759062323249ef657d26d357a777443aec04db1b29a3a22ef3e7c548e18493ddaf51a31b0aed6079bd6ebe5ae838fcfaf3a49 err=EOF
t=2018-11-29T10:58:23+0100 lvl=info msg=RequestMessages                  package=status-go/services/sshext.PublicAPI request="{MailServerPeer:enode://c42f368a23fa98ee546fd247220759062323249ef657d26d357a777443aec04db1b29a3a22ef3e7c548e18493ddaf51a31b0aed6079bd6ebe5ae838fcfaf3a49@206.189.243.162:30504 From:1543485442 To:1543485503 Limit:0 Cursor: Topic:[0 0 0 0] Topics:[[205 66 55 96] [248 148 106 172]] SymKeyID:1f83a6d44490efc2206cdd155d4f1358c6b55a3a924cea12268b6b7dc4246f23 Timeout:30ns}"
t=2018-11-29T11:00:15+0100 lvl=info msg="message loop"                   peer=0d9d65fcd5592df33ed4507ce862b9c748b6dbd1ea3a1deb94e3750052760b4850aa527265bbaf357021d64d5cc53c02b410458e732fafc5b53f257944247760 err=EOF
t=2018-11-29T11:00:15+0100 lvl=info msg="UDP listener up"                net=enode://c3a3e90d1512b469d67373b2bd0ae5366cd4bc440dcd43d538b5567b868b51bf9cbecbd8d625e9603da75ea93c12133dedac8bfd4fb4e0584bf84a407145066e@[::]:57265
t=2018-11-29T11:00:22+0100 lvl=info msg="message loop"                   peer=c42f368a23fa98ee546fd247220759062323249ef657d26d357a777443aec04db1b29a3a22ef3e7c548e18493ddaf51a31b0aed6079bd6ebe5ae838fcfaf3a49 err=EOF
t=2018-11-29T11:00:42+0100 lvl=info msg="message loop"                   peer=a1a8e2416266020e168a2257851cdb59cd951e822655730dc1bbd50adb892a6444987d3baece727ae83600e1db8db49a707012b7ebe6fd4eb3e350166fe55579 err=EOF
t=2018-11-29T11:00:42+0100 lvl=info msg="UDP listener up"                net=enode://c3a3e90d1512b469d67373b2bd0ae5366cd4bc440dcd43d538b5567b868b51bf9cbecbd8d625e9603da75ea93c12133dedac8bfd4fb4e0584bf84a407145066e@[::]:60233
t=2018-11-29T11:01:07+0100 lvl=info msg=RequestMessages                  package=status-go/services/sshext.PublicAPI request="{MailServerPeer:enode://c42f368a23fa98ee546fd247220759062323249ef657d26d357a777443aec04db1b29a3a22ef3e7c548e18493ddaf51a31b0aed6079bd6ebe5ae838fcfaf3a49@206.189.243.162:30504 From:1543485503 To:1543485667 Limit:0 Cursor: Topic:[0 0 0 0] Topics:[[205 66 55 96] [248 148 106 172]] SymKeyID:1f83a6d44490efc2206cdd155d4f1358c6b55a3a924cea12268b6b7dc4246f23 Timeout:30ns}"
t=2018-11-29T11:01:08+0100 lvl=info msg="message loop"                   peer=69c89c2b3b69d6e24b40b32f98eb5d32ea59c39306a8240c7d6bcf1a687de646e32cc3a1aefd0c974faa02cf04119a174cb05febbd12cdd6b497c9900959b976 err=EOF
t=2018-11-29T11:01:40+0100 lvl=info msg=RequestMessages                  package=status-go/services/sshext.PublicAPI request="{MailServerPeer:enode://c42f368a23fa98ee546fd247220759062323249ef657d26d357a777443aec04db1b29a3a22ef3e7c548e18493ddaf51a31b0aed6079bd6ebe5ae838fcfaf3a49@206.189.243.162:30504 From:1543485503 To:1543485667 Limit:0 Cursor: Topic:[0 0 0 0] Topics:[[205 66 55 96] [248 148 106 172]] SymKeyID:1f83a6d44490efc2206cdd155d4f1358c6b55a3a924cea12268b6b7dc4246f23 Timeout:30ns}"
t=2018-11-29T11:01:57+0100 lvl=info msg="message loop"                   peer=4c4ee27f706a35ad60f17f1e76c3844c8e00b5322829f4fc4e38f00b9073aa06364751850293dffba9a0657703fa885238f62e413666f93b0ae4677b8c419d0a err=EOF
t=2018-11-29T11:01:57+0100 lvl=info msg="UDP listener up"                net=enode://c3a3e90d1512b469d67373b2bd0ae5366cd4bc440dcd43d538b5567b868b51bf9cbecbd8d625e9603da75ea93c12133dedac8bfd4fb4e0584bf84a407145066e@[::]:57723
t=2018-11-29T11:02:00+0100 lvl=info msg="message loop"                   peer=4b2530d045b1d9e0e45afa7c008292744fe77675462090b4001f85faf03b87aa79259c8a3d6d64f815520ac76944e795cbf32ff9e2ce9ba38f57af00d1cc0568 err=EOF
t=2018-11-29T11:02:54+0100 lvl=info msg="message loop"                   peer=69c89c2b3b69d6e24b40b32f98eb5d32ea59c39306a8240c7d6bcf1a687de646e32cc3a1aefd0c974faa02cf04119a174cb05febbd12cdd6b497c9900959b976 err=EOF
t=2018-11-29T11:03:10+0100 lvl=info msg="message loop"                   peer=4c4ee27f706a35ad60f17f1e76c3844c8e00b5322829f4fc4e38f00b9073aa06364751850293dffba9a0657703fa885238f62e413666f93b0ae4677b8c419d0a err=EOF
t=2018-11-29T11:03:29+0100 lvl=info msg="message loop"                   peer=c42f368a23fa98ee546fd247220759062323249ef657d26d357a777443aec04db1b29a3a22ef3e7c548e18493ddaf51a31b0aed6079bd6ebe5ae838fcfaf3a49 err=EOF
t=2018-11-29T11:03:34+0100 lvl=info msg=RequestMessages                  package=status-go/services/sshext.PublicAPI request="{MailServerPeer:enode://c42f368a23fa98ee546fd247220759062323249ef657d26d357a777443aec04db1b29a3a22ef3e7c548e18493ddaf51a31b0aed6079bd6ebe5ae838fcfaf3a49@206.189.243.162:30504 From:1543485667 To:1543485814 Limit:0 Cursor: Topic:[0 0 0 0] Topics:[[205 66 55 96] [248 148 106 172]] SymKeyID:1f83a6d44490efc2206cdd155d4f1358c6b55a3a924cea12268b6b7dc4246f23 Timeout:30ns}"
t=2018-11-29T11:03:45+0100 lvl=info msg="message loop"                   peer=c42f368a23fa98ee546fd247220759062323249ef657d26d357a777443aec04db1b29a3a22ef3e7c548e18493ddaf51a31b0aed6079bd6ebe5ae838fcfaf3a49 err=EOF
t=2018-11-29T11:04:44+0100 lvl=info msg="message loop"                   peer=887cbd92d95afc2c5f1e227356314a53d3d18855880ac0509e0c0870362aee03939d4074e6ad31365915af41d34320b5094bfcc12a67c381788cd7298d06c875 err=EOF
t=2018-11-29T11:04:44+0100 lvl=info msg="UDP listener up"                net=enode://c3a3e90d1512b469d67373b2bd0ae5366cd4bc440dcd43d538b5567b868b51bf9cbecbd8d625e9603da75ea93c12133dedac8bfd4fb4e0584bf84a407145066e@[::]:61181
t=2018-11-29T11:04:45+0100 lvl=info msg="message loop"                   peer=ce559a37a9c344d7109bd4907802dd690008381d51f658c43056ec36ac043338bd92f1ac6043e645b64953b06f27202d679756a9c7cf62fdefa01b2e6ac5098e err=EOF
t=2018-11-29T11:05:13+0100 lvl=info msg=RequestMessages                  package=status-go/services/sshext.PublicAPI request="{MailServerPeer:enode://c42f368a23fa98ee546fd247220759062323249ef657d26d357a777443aec04db1b29a3a22ef3e7c548e18493ddaf51a31b0aed6079bd6ebe5ae838fcfaf3a49@206.189.243.162:30504 From:1543485814 To:1543485913 Limit:0 Cursor: Topic:[0 0 0 0] Topics:[[205 66 55 96] [248 148 106 172]] SymKeyID:1f83a6d44490efc2206cdd155d4f1358c6b55a3a924cea12268b6b7dc4246f23 Timeout:30ns}"

Within #6865 I can see that app is actually connected to 3 peers but Offline is still shown (Video: http://take.ms/GRopV)

[chadyj]

@cammellos Would be great if you can grab this to get it included in the 0.9.0 desktop release next week (if you still have context and bandwidth)

[cammellos]

@chadyj I will take tomorrow to work on this, we can use the peer count to check if online/offline #6961 , and it would be good to include #6877 so that in case we just disconnected we get some feedback when sending messages.

@siphiuel are you working on #6961 or I can take over?

[vitvly]

@cammellos Planned on working on #6961 this week, but not started yet. So please take over :)

[chadyj]

@cammellos I know you have your plate full but we are hoping to include this in the desktop release next week.

[cammellos]

@chadyj PR is out #7012 should fix the offline problem + add cconfirmations from the mailserver , is ready to be tested, but depends on #6877.

Confirmations are not enabled by default in release (only in nightlies/dev) as if mailservers are down or unreachable the user will see their messages as not-sent (they will be sent though), but in most cases will provide better guarantees of delivery.

[vkjr]

@annadanchenko, can we close this now, when #7012 merged?

[churik]

It can be closed, yes