admin.peers() is empty

[dmitryn]

Type: Bug

Description

When app starts it connect to peers for messaging and offline inboxing. Sometimes, usually on next day in the morning , i start app in emulator and see admin.peers() is empty in the logs on app initialize.

Steps to reproduce

• Open Status in the evening
• Close laptop and go sleep
• Open it in the morning
• Check logs

Operating System: Android Genymotion Emulator

Logs

geth.log

WARN [02-08|16:33:59] bad envelope received, peer will be disconnected peer=7ab298cedc4185a8 err="envelope created in the future [91649e95923a5d15ddb904ec7d5e57db627782b4b8c1d4c2c2e9faccd7bd8ef5]"
WARN [02-08|16:33:59] bad envelope received, peer will be disconnected peer=0f7c65277f916ff4 err="envelope created in the future [ee356ff8c480ef8b58881aa19fb0e6853681b31a164839081ad727b8227a9d5d]"
WARN [02-08|16:33:59] bad envelope received, peer will be disconnected peer=fe991752c4ceab8b err="envelope created in the future [bd326ebebae609b6be0915f2ab06ad37cf4cb84ca1c7486f6ce515bf1826f965]"
WARN [02-08|16:33:59] bad envelope received, peer will be disconnected peer=a1ef9ba5550d5fac err="envelope created in the future [0d7d3e402e26ab8194024c8250ac403b355939c9ad222f0caf74c8e31352d4b6]"
WARN [02-08|16:33:59] bad envelope received, peer will be disconnected peer=e2a3587b7b41acfc err="envelope created in the future [12466a20c0385e6b30d9f1f608734921a47c1836bef6e020d30ec29f5921b7d9]"
WARN [02-08|16:33:59] bad envelope received, peer will be disconnected peer=ea37c9724762be7f err="envelope created in the future [f3855d8c927fce369c22558977651d8b65dc1c37c50dd18f8a13c8d62362220d]"
WARN [02-08|16:33:59] bad envelope received, peer will be disconnected peer=ce6854c2c77a8800 err="envelope created in the future [f2f185bb1d9ed11fcb8c059ca0236c71a418853ccf7c62e248508eeb1e3de480]"
WARN [02-08|16:33:59] bad envelope received, peer will be disconnected peer=88c2b24429a6f768 err="envelope created in the future [da450627da01432858e15c8919373f25d79555497f085b8141c6432f6c99653f]"
WARN [02-08|16:33:59] bad envelope received, peer will be disconnected peer=86ebc843aa51669e err="envelope created in the future [f7233246f89126c81ef791fdac9f9100f8644d149307a2c562c6917efaacdfde]"
WARN [02-08|16:33:59] bad envelope received, peer will be disconnected peer=e006f0b2dc98e757 err="envelope created in the future [818476f965baf255820eb4ff9ae4bdcacab6c807eb0db111c3e5306ee4f73343]"

adb logcat

02-08 11:29:44.771 24659 24729 D StatusModule: startNode
02-08 11:29:44.775 24659 24758 D StatusModule: Starting Geth node in folder: /data/user/0/im.status.ethereum/ethereum/testnet
02-08 11:29:44.816 24659 24758 D StatusModule: Attach to geth.log to instabug /storage/emulated/0/Download/geth.log
02-08 11:29:44.819 24659 24758 D StatusModule: Instabug is not initialized!
02-08 11:29:44.819 24659 24758 D ExtDirLog: /storage/emulated/0/Download/geth.log
02-08 11:29:44.819 24659 24758 D StatusModule: UpstreamConfig is not null
02-08 11:29:44.821 24659 24758 D StatusModule: Node config {"DevMode":true,"NetworkId":3,"DataDir":"\/data\/user\/0\/im.status.ethereum\/ethereum\/testnet_rpc","KeyStoreDir":"\/data\/user\/0\/im.status.ethereum\/keystore","NodeKeyFile":"","ListenAddr":":0","Name":"StatusIM","Version":"0.9.9-unstable","APIModules":"db,eth,net,web3,shh,personal,admin","HTTPHost":"localhost","RPCEnabled":false,"HTTPPort":8545,"WSHost":"localhost","WSPort":8546,"WSEnabled":false,"IPCFile":"geth.ipc","IPCEnabled":false,"TLSEnabled":false,"MaxPeers":25,"MaxPendingPeers":0,"LogFile":"\/storage\/emulated\/0\/Download\/geth.log","LogLevel":"INFO","LogToStderr":true,"UpstreamConfig":{"Enabled":true,"URL":"https:\/\/ropsten.infura.io\/z6GCTmjdP3FETEJmMBI4"},"BootClusterConfig":{"Enabled":true,"RootNumber":478,"RootHash":"77eedcf6f940940b3615da49109c1ba57b95c3fff8bcf16f20ac579c3ae24e58","BootNodes":["enode:\/\/7ab298cedc4185a894d21d8a4615262ec6bdce66c9b6783878258e0d5b31013d30c9038932432f70e5b2b6a5cd323bf820554fcb22fbc7b45367889522e9c449@51.15.63.93:30303","enode:\/\/f59e8701f18c79c5cbc7618dc7bb928d44dc2f5405c7d693dad97da2d8585975942ec6fd36d3fe608bfdc7270a34a4dd00f38cfe96b2baa24f7cd0ac28d382a1@51.15.79.88:30303","enode:\/\/e2a3587b7b41acfc49eddea9229281905d252efba0baf565cf6276df17faf04801b7879eead757da8b5be13b05f25e775ab6d857ff264bc53a89c027a657dd10@51.15.45.114:30303","enode:\/\/fe991752c4ceab8b90608fbf16d89a5f7d6d1825647d4981569ebcece1b243b2000420a5db721e214231c7a6da3543fa821185c706cbd9b9be651494ec97f56a@51.15.67.119:30303","enode:\/\/482484b9198530ee2e00db89791823244ca41dcd372242e2e1297dd06f6d8dd357603960c5ad9cc8dc15fcdf0e4edd06b7ad7db590e67a0b54f798c26581ebd7@51.15.75.138:30303","enode:\/\/9e99e183b5c71d51deb16e6b42ac9c26c75cfc95fff9dfae828b871b348354cbecf196dff4dd43567b26c8241b2b979cb4ea9f8dae2d9aacf86649dafe19a39a@51.15.79.176:30303","enode:\/\/12d52c3796700fb5acff2c7d96df7bbb6d7109b67f3442ee3d99ac1c197016cddb4c3568bbeba05d39145c59c990cd64f76bc9b00d4b13f10095c49507dd4cf9@51.15.63.110:30303","enode:\/\/0f7c65277f916ff4379fe520b875082a56e587eb3ce1c1567d9ff94206bdb05ba167c52272f20f634cd1ebdec5d9dfeb393018bfde1595d8e64a717c8b46692f@51.15.54.150:30303","enode:\/\/e006f0b2dc98e757468b67173295519e9b6d5ff4842772acb18fd055c620727ab23766c95b8ee1008dea9e8ef61e83b1515ddb3fb56dbfb9dbf1f463552a7c9f@212.47.237.127:30303","enode:\/\/d40871fc3e11b2649700978e06acd68a24af54e603d4333faecb70926ca7df93baa0b7bf4e927fcad9a7c1c07f9b325b22f6d1730e728314d0e4e6523e5cebc2@51.15.132.235:30303","enode:\/\/ea37c9724762be7f668e15d3dc955562529ab4f01bd7951f0b3c1960b75ecba45e8c3bb3c8ebe6a7504d9a40dd99a562b13629cc8e5e12153451765f9a12a61d@163.172.189.205:30303","enode:\/\/88c2b24429a6f7683fbfd06874ae3f1e7c8b4a5ffb846e77c705ba02e2543789d66fc032b6606a8d8888eb6239a2abe5897ce83f78dcdcfcb027d6ea69aa6fe9@163.172.157.61:30303","enode:\/\/ce6854c2c77a8800fcc12600206c344b8053bb90ee3ba280e6c4f18f3141cdc5ee80bcc3bdb24cbc0e96dffd4b38d7b57546ed528c00af6cd604ab65c4d528f6@163.172.153.124:30303","enode:\/\/00ae60771d9815daba35766d463a82a7b360b3a80e35ab2e0daa25bdc6ca6213ff4c8348025e7e1a908a8f58411a364fe02a0fb3c2aa32008304f063d8aaf1a2@163.172.132.85:30303","enode:\/\/86ebc843aa51669e08e27400e435f957918e39dc540b021a2f3291ab776c88bbda3d97631639219b6e77e375ab7944222c47713bdeb3251b25779ce743a39d70@212.47.254.155:30303","enode:\/\/a1ef9ba5550d5fac27f7cbd4e8d20a643ad75596f307c91cd6e7f85b548b8a6bf215cca436d6ee436d6135f9fe51398f8dd4c0bd6c6a0c332ccb41880f33ec12@51.15.218.125:30303"]},"LightEthConfig":{"Enabled":true,"Genesis":"{\"config\":{\"chainId\":3,\"homesteadBlock\":0,\"daoForkSupport\":true,\"eip150Block\":0,\"eip150Hash\":\"0x41941023680923e0fe4d74a34bdac8141f2540e3ae90623718e47d66d1ca4a2d\",\"eip155Block\":10,\"eip158Block\":10,\"byzantiumBlock\":1700000,\"ethash\":{}},\"nonce\":\"0x42\",\"timestamp\":\"0x0\",\"extraData\":\"0x3535353535353535353535353535353535353535353535353535353535353535\",\"gasLimit\":\"0x1000000\",\"difficulty\":\"0x100000\",\"mixHash\":\"0x0000000000000000000000000000000000000000000000000000000000000000\",\"coinbase\":\"0x0000000000000000000000000000000000000000\",\"alloc\":{\"000
02-08 11:29:44.839 24659 24758 D StatusModule: StartNode result: {"error":""}
02-08 11:29:44.839 24659 24758 D StatusModule: Geth node started
02-08 11:29:44.839 24659 24758 D ServiceConnector: Sending message to service:
02-08 11:29:44.866 24659 24727 D StatusService: Signal event: {"type":"node.started","event":{}}
02-08 11:29:44.879 24659 24761 D StatusService: Signal event: {"type":"node.ready","event":{}}
02-08 11:29:44.888 24659 24659 D StatusService: Received service message.{ when=-47ms what=0 target=im.status.ethereum.module.StatusService$IncomingHandler }
02-08 11:29:44.892 24659 24727 D StatusService: before sendReply true
02-08 11:29:44.892 24659 24732 D StatusModule: Received message: { when=0 what=0 target=im.status.ethereum.module.ServiceConnector$IncomingHandler }
02-08 11:29:44.892 24659 24732 D StatusModule: Signal event: {"type":"node.started","event":{}}
02-08 11:29:44.893 24659 24761 D StatusService: before sendReply true
02-08 11:29:44.894 24659 24732 D StatusModule: Received message: { when=0 what=0 target=im.status.ethereum.module.ServiceConnector$IncomingHandler }
02-08 11:29:44.894 24659 24732 D StatusModule: Signal event: {"type":"node.ready","event":{}}
...
02-08 11:30:43.454 24659 24728 I ReactNativeJS: INFO [status-im.protocol.handlers:301] - offline inbox: fetch-peers response []
02-08 11:30:43.455 24659 24728 I ReactNativeJS: INFO [status-im.protocol.handlers:307] - Peer enode://08d8eb6177b187049f6c97ed3f6c74fbbefb94c7ad10bafcaf4b65ce89c314dcfee0a8bc4e7a5b824dfa08b45b360cc78f34f0aff981f8386caa07652d2e601b@163.172.177.138:40404 is not registered. Retrying fetch peers.
02-08 11:30:43.766 24659 24728 D ReactNativeJS: DEBUG [status-im.utils.handlers:29] - Handling re-frame event:  :status-im.protocol.handlers/fetch-peers-success
02-08 11:30:43.769 24659 24728 I ReactNativeJS: INFO [status-im.protocol.handlers:301] - offline inbox: fetch-peers response []
02-08 11:30:43.771 24659 24728 I ReactNativeJS: INFO [status-im.protocol.handlers:307] - Peer enode://08d8eb6177b187049f6c97ed3f6c74fbbefb94c7ad10bafcaf4b65ce89c314dcfee0a8bc4e7a5b824dfa08b45b360cc78f34f0aff981f8386caa07652d2e601b@163.172.177.138:40404 is not registered. Retrying fetch peers.
02-08 11:30:44.785 24659 24728 D ReactNativeJS: DEBUG [status-im.utils.handlers:29] - Handling re-frame event:  :status-im.protocol.handlers/fetch-peers-success
02-08 11:30:44.788 24659 24728 I ReactNativeJS: INFO [status-im.protocol.handlers:301] - offline inbox: fetch-peers response []
02-08 11:30:44.789 24659 24728 I ReactNativeJS: INFO [status-im.protocol.handlers:307] - Peer enode://08d8eb6177b187049f6c97ed3f6c74fbbefb94c7ad10bafcaf4b65ce89c314dcfee0a8bc4e7a5b824dfa08b45b360cc78f34f0aff981f8386caa07652d2e601b@163.172.177.138:40404 is not registered. Retrying fetch peers.
02-08 11:30:45.803 24659 24728 D ReactNativeJS: DEBUG [status-im.utils.handlers:29] - Handling re-frame event:  :status-im.protocol.handlers/fetch-peers-success
02-08 11:30:45.806 24659 24728 I ReactNativeJS: INFO [status-im.protocol.handlers:301] - offline inbox: fetch-peers response []
02-08 11:30:45.807 24659 24728 I ReactNativeJS: INFO [status-im.protocol.handlers:307] - Peer enode://08d8eb6177b187049f6c97ed3f6c74fbbefb94c7ad10bafcaf4b65ce89c314dcfee0a8bc4e7a5b824dfa08b45b360cc78f34f0aff981f8386caa07652d2e601b@163.172.177.138:40404 is not registered. Retrying fetch peers.
02-08 11:30:46.820 24659 24728 D ReactNativeJS: DEBUG [status-im.utils.handlers:29] - Handling re-frame event:  :status-im.protocol.handlers/fetch-peers-success
02-08 11:30:46.822 24659 24728 I ReactNativeJS: INFO [status-im.protocol.handlers:301] - offline inbox: fetch-peers response [{:id "0f7c65277f916ff4379fe520b875082a56e587eb3ce1c1567d9ff94206bdb05ba167c52272f20f634cd1ebdec5d9dfeb393018bfde1595d8e64a717c8b46692f", :name "Geth/v1.7.3-stable/linux-amd64/go1.9.2", :caps ["eth/62" "eth/63" "les/1" "les/2" "shh/5"], :network {:localAddress "10.0.3.15:37578", :remoteAddress "51.15.54.150:30303"}, :protocols {:shh "unknown"}} {:id "88c2b24429a6f7683fbfd06874ae3f1e7c8b4a5ffb846e77c705ba02e2543789d66fc032b6606a8d8888eb6239a2abe5897ce83f78dcdcfcb027d6ea69aa6fe9", :name "Geth/v1.7.3-stable/linux-amd64/go1.9.2", :caps ["eth/62" "eth/63" "les/1" "les/2" "shh/5"], :network {:localAddress "10.0.3.15:51960", :remoteAddress "163.172.157.61:30303"}, :protocols {:shh "unknown"}} {:id "fe991752c4ceab8b90608fbf16d89a5f7d6d1825647d4981569ebcece1b243b2000420a5db721e214231c7a6da3543fa821185c706cbd9b9be651494ec97f56a", :name "Geth/v1.7.3-stable/linux-amd64/go1.9.2", :caps ["eth/62" "eth/63" "les/1" "les/2" "shh/5"], :network {:localAddress "10.0.3.15:50296", :remoteAddress "51.15.67.119:30303"}, :protocols {:shh "unknown"}}]
02-08 11:30:46.824 24659 24728 I ReactNativeJS: INFO [status-im.protocol.handlers:307] - Peer enode://08d8eb6177b187049f6c97ed3f6c74fbbefb94c7ad10bafcaf4b65ce89c314dcfee0a8bc4e7a5b824dfa08b45b360cc78f34f0aff981f8386caa07652d2e601b@163.172.177.138:40404 is not registered. Retrying fetch peers.
02-08 11:30:47.834 24659 24728 D ReactNativeJS: DEBUG [status-im.utils.handlers:29] - Handling re-frame event:  :status-im.protocol.handlers/fetch-peers-success
02-08 11:30:47.835 24659 24728 I ReactNativeJS: INFO [status-im.protocol.handlers:301] - offline inbox: fetch-peers response []
02-08 11:30:47.837 24659 24728 I ReactNativeJS: INFO [status-im.protocol.handlers:307] - Peer enode://08d8eb6177b187049f6c97ed3f6c74fbbefb94c7ad10bafcaf4b65ce89c314dcfee0a8bc4e7a5b824dfa08b45b360cc78f34f0aff981f8386caa07652d2e601b@163.172.177.138:40404 is not registered. Retrying fetch peers.
...

Notes

Notice that time in logcat and geth.log is out of sync.

Part of status-im/swarms#71

[dmitryn]

Just did one more run – admin.peers() were empty in the beginning, but ~90 seconds later after polling, one peer appeared:

02-08 12:38:47.504 29458 29507 I ReactNativeJS: INFO [status-im.protocol.handlers:304] - offline inbox: fetch-peers response [{:id "08d8eb6177b187049f6c97ed3f6c74fbbefb94c7ad10bafcaf4b65ce89c314dcfee0a8bc4e7a5b824dfa08b45b360cc78f34f0aff981f8386caa07652d2e601b", :name "StatusIM/v0.9.9-unstable/linux-amd64/go1.9.2", :caps ["shh/5"], :network {:localAddress "10.0.3.15:57340", :remoteAddress "163.172.177.138:40404"}, :protocols {:shh "unknown"}}]

And after that, app was able to request messages from that peer just fine.

[adambabik]

It looks like the time reported by the emulator is different than the time on the server. The app thinks it got a message from the future and, following the Whisper protocol, it disconnects the peers immediately. Not sure how your OS works or how the emulator works, but it looks like when the laptop goes to sleep, it stops syncing the clock (or, more likely, the emulator stops doing that) and when it gets awaken, the app receives messages before emulator's clock is synced.

I assume both logs were written at the same time. On the first one, it's 02-08|16:33:59 while on the second one it's 02-08 11:29:44.

I believe @flexsurfer reported the similar problem with the clock.

Overall, the behavior of Whisper is not really what we expect I believe. Desynchronisation of the clock on mobile devices can happen in many situations and it's not as stable as on a desktop. I see two possible solutions:

1. Try to use real bootservers, not just static peers which can be disconnected and there is no reconnecting mechanism,
2. Patch Whisper to not disconnect immediately (I don't like it),
3. Or add a reconnect mechanism for static peers in status-go.

I would try (1) and if it does not work try (3).

[adambabik]

Just did one more run – admin.peers() were empty in the beginning, but ~90 seconds later after polling, one peer appeared:

Oh, that would suggest that there is a reconnecting mechanism. It just probably does it every N minutes. Can you please upload the whole geth.log?

[dmitryn]

@adambabik
geth.log

[JekaMas]

@dmitryn @yenda I've tried to run such bash script on local machine and it looks like it solves the issue with Genymotion Emulator:
while true; do t=$(date +%s.%N); adb wait-for-device shell '[[ $(date -u @'$t') ]]'; sleep 1; done
It just sync time between local machine and emulator. Could you check it at your side?

[dmitryn]

@JekaMas i'm having error:

$ while true; do t=$(date +%s.%N); adb wait-for-device shell '[[ $(date -u @'$t') ]]'; sleep 1; done
date: bad date '@1519050857.N'
date: bad date '@1519050858.N'
date: bad date '@1519050859.N'
date: bad date '@1519050860.N'
date: bad date '@1519050861.N'
date: bad date '@1519050862.N'

[JekaMas]

@dmitryn Do you use Mac?
Is so you can try while true; do t=$(date +%s); adb wait-for-device shell '[[ $(date -u @'$t') ]]'; sleep 1; done

[dmitryn]

@JekaMas i have INFO [02-19|17:09:15] in geth.log
and 02-19 12:09:15.998 in simulator

Looks like geth.log time is UTC and simulator is UTC -5

[dmitryn]

After debugging session with @JekaMas we found out that this script helps to sync time in android emulator (works on OSX):

while true; do t=$(date +%s); adb wait-for-device shell '[[ $(date -u @'$t') ]]'; sleep 1; done

Issue regarding empty admin.peers() still persist when you try to connect to 163.172.177.138:40404. But it doesn't reproduce when you try different port 163.172.177.138:30353 (node that marked as "mailserver (test)" in the app).

@adambabik do you know what ports should we use to connect? And what mailserver node should be used as default?

[dshulyak]

One thing to keep in mind is that after each network connectivity loss admin.peers will be 0 for ~30s or so. More information about this here: status-im/status-go#646 . We will be able to fix it once approach described in status-im/status-go#649 will be fully implemented.

[dmitryn]

One thing to keep in mind is that after each network connectivity loss admin.peers will be 0 for ~30s or so

@dshulyak thanks, good to know. Should not be a problem as we only need it during startup, and if it's empty we do ~100 retries for ~6 minutes.