Concordium/Testnet4-Challenges

Error connecting to peers on Windows

ZloyMyshok opened this issue · 8 comments

2021-01-24T11:00:44.067940600Z: INFO: Attempting to bootstrap
2021-01-24T11:01:16.957661800Z: INFO: Using bootstrapper 54.77.133.220:8888
2021-01-24T11:01:16.957712600Z: INFO: Using bootstrapper 52.17.42.154:8888
2021-01-24T11:01:17.058572000Z: ERROR: Can't connect to the desired address: Already connected to 54.77.133.220:8888
2021-01-24T11:01:17.058617800Z: ERROR: Can't connect to the desired address: Already connected to 52.17.42.154:8888
2021-01-24T11:01:17.059067600Z: INFO: Attempting to bootstrap
2021-01-24T11:01:49.817426000Z: INFO: Using bootstrapper 54.77.133.220:8888
2021-01-24T11:01:49.817476300Z: INFO: Using bootstrapper 52.17.42.154:8888
2021-01-24T11:01:49.817495000Z: INFO: No peers at all - retrying bootstrapping

Noda is catching up with the network block by block, and that's all. Although your node is visible in the dashboard.

Hi ZloyMyshok

Did this happen on starting the node, or after a loss of connectivity?
If it happened after a loss of connectivity, try to restart your node and Docker.

If not, we might need to see the full log (the log can be generated using the tool concordium-node-retrieve-logs.exe).

Kind regards,
Emil, Concordium Support

Communication is not lost. Reboot doesn't help. The error in the testnet -support branch has appeared more than once, but everyone ignores it.

concordium-testnet-node-9f2acc5bee0a5efcdc7625de819ff9824927c2d374c3e580c753ef0d6d8b8544.log

bash: /usr/local/bin/concordium-client: No such file or directory
bash: /usr/local/bin/concordium-client: No such file or directory
2021-01-23 15:07:59,126 INFO Included extra file "/etc/supervisor/conf.d/concordium.conf" during parsing
2021-01-23 15:07:59,126 INFO Set uid to user 0 succeeded
2021-01-23 15:07:59,131 INFO RPC interface 'supervisor' initialized
2021-01-23 15:07:59,131 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2021-01-23 15:07:59,131 INFO supervisord started with pid 28
2021-01-23 15:08:00,134 INFO spawned: 'collector' with pid 30
2021-01-23 15:08:00,135 INFO spawned: 'p2p-client' with pid 31
2021-01-23T15:08:00.186181600Z: INFO: Starting up p2p_client version 0.4.8!
2021-01-23T15:08:00.186212900Z: INFO: Application data directory: "/var/lib/concordium/data"
2021-01-23T15:08:00.186218700Z: INFO: Application config directory: "/var/lib/concordium/config"
2021-01-23T15:08:00.186221000Z: INFO: Network: enabled
2021-01-23T15:08:00.186222400Z: INFO: Log level: info
2021-01-23T15:08:00.189769100Z: INFO: My Node ID is 5a1783a16076129c
2021-01-23T15:08:00.227180700Z: INFO: Starting consensus layer
2021-01-23T15:08:00.227236700Z: INFO: Starting up the consensus thread
2021-01-23T15:08:00.227909400Z: INFO: Starting up the consensus layer
2021-01-23T15:08:00.576780300Z: INFO: Consensus layer started
2021-01-23T15:08:00.576869800Z: INFO: RPC server started
2021-01-23T15:08:00.576873500Z: INFO: Starting out of band catch-up
2021-01-23T15:08:00.580672300Z: INFO: Skov: Receive statistics: blocksReceivedCount=1 blockLastReceived=1.61141448057881e9 blockReceiveLatencyEMA=87887.432881 blockReceiveLatencyEMSD=263662.298643 blockReceivePeriodEMA=Nothing blockReceivePeriodEMSD=Nothing
2021-01-23T15:08:00.582968100Z: INFO: Skov: Block b0ee79c69c048db10076ce858250ec38c868c60ff1b82f0943e048ea55b4f0ea (8) arrived
2021-01-23T15:08:00.585837000Z: INFO: Skov: Arrive statistics: blocksVerifiedCount=1 blockLastArrive=1.6114144805828986e9 blockArriveLatencyEMA=87887.43328987001 blockArriveLatencyEMSD=263662.29986961005 blockArrivePeriodEMA=Nothing blockArrivePeriodEMSD=Nothing transactionsPerBlockEMA=0.0 transactionsPerBlockEMSD=0.0
2021-01-23T15:08:00.587209400Z: INFO: Skov: Receive statistics: blocksReceivedCount=2 blockLastReceived=1.61141448057881e9 blockReceiveLatencyEMA=166985.69747389999 blockReceiveLatencyEMSD=344782.3169880022 blockReceivePeriodEMA=Just 0.0 blockReceivePeriodEMSD=Just 0.0
2021-01-23T15:08:00.591268600Z: INFO: Skov: Block b0ee79c69c048db10076ce858250ec38c868c60ff1b82f0943e048ea55b4f0ea is finalized at height 1 with finalization delta=0
2021-01-23T15:08:00.591414300Z: INFO: Skov: Finalization statistics: finalizationCount=1 lastFinalizedTime=1.6114144805912983e9 finalizationPeriodEMA=Nothing finalizationPeriodEMSD=Nothing
2021-01-23T15:08:00.604886800Z: INFO: Skov: Block efdfca7f5320446553d922332762388946db6c0041a21cdbf90965b6155aaef5 (8) arrived
2021-01-23T15:08:00.605329400Z: INFO: Skov: Arrive statistics: blocksVerifiedCount=2 blockLastArrive=1.6114144806048362e9 blockArriveLatencyEMA=166985.700444513 blockArriveLatencyEMSD=344782.32312153775 blockArrivePeriodEMA=Just 2.19376e-2 blockArrivePeriodEMSD=Just 0.0 transactionsPerBlockEMA=0.0 transactionsPerBlockEMSD=0.0
.
.
.
.
.
.
2021-01-23T15:38:25.066915900Z: INFO: Skov: Block 46299845e6fb45c1534b79ad0b96ea0e57a310a1a747da1f9828e180f4a23536 is finalized at height 78521 with finalization delta=0
2021-01-23T15:38:25.067523300Z: INFO: Skov: Finalization statistics: finalizationCount=76484 lastFinalizedTime=1.611416305066972e9 finalizationPeriodEMA=Just 2.4854241372546406e-2 finalizationPeriodEMSD=Just 4.8532849181791736e-3
2021-01-23T15:38:25.084342400Z: INFO: Skov: Block 89f613cc3cdd0bca72c13206d14ddd3a99ca0aba62914bf5d3a008d9b73c7270 (90) arrived
2021-01-23T15:38:25.085097400Z: INFO: Skov: Arrive statistics: blocksVerifiedCount=78522 blockLastArrive=1.6114163050842936e9 blockArriveLatencyEMA=56363.73109697807 blockArriveLatencyEMSD=96.7940942348852 blockArrivePeriodEMA=Just 2.35268062444419e-2 blockArrivePeriodEMSD=Just 6.456526855672875e-3 transactionsPerBlockEMA=3.824303793518696e-2 transactionsPerBlockEMSD=0.19178244962632798
2021-01-23T15:38:25.085202500Z: INFO: Completed out of band catch-up
2021-01-23T15:38:25.085381900Z: INFO: Starting the P2P layer
2021-01-23T15:38:25.085385700Z: INFO: Attempting to bootstrap
2021-01-23T15:38:55.160711700Z: INFO: Attempting to bootstrap
2021-01-23T15:38:58.926225600Z: INFO: Using bootstrapper 54.77.133.220:8888
2021-01-23T15:38:58.926257600Z: INFO: Using bootstrapper 52.17.42.154:8888
2021-01-23T15:39:28.513572500Z: INFO: Using bootstrapper 54.77.133.220:8888
2021-01-23T15:39:28.513622900Z: INFO: Using bootstrapper 52.17.42.154:8888
2021-01-23T15:39:28.513647300Z: INFO: No peers at all - retrying bootstrapping
2021-01-23T15:39:28.513649400Z: INFO: Attempting to bootstrap
2021-01-23T15:40:01.744971200Z: INFO: Using bootstrapper 54.77.133.220:8888
2021-01-23T15:40:01.745014900Z: INFO: Using bootstrapper 52.17.42.154:8888
2021-01-23T15:40:01.846318300Z: ERROR: Can't connect to the desired address: Already connected to 54.77.133.220:8888
2021-01-23T15:40:01.846360900Z: ERROR: Can't connect to the desired address: Already connected to 52.17.42.154:8888
2021-01-23T15:40:01.846366900Z: ERROR: Can't connect to the desired address: Already connected to 54.77.133.220:8888
2021-01-23T15:40:01.846369100Z: ERROR: Can't connect to the desired address: Already connected to 52.17.42.154:8888
2021-01-23T15:40:01.846556600Z: INFO: Attempting to bootstrap
2021-01-23T15:40:35.267580900Z: INFO: Using bootstrapper 54.77.133.220:8888
2021-01-23T15:40:35.267613100Z: INFO: Using bootstrapper 52.17.42.154:8888
2021-01-23T15:40:35.267618500Z: INFO: No peers at all - retrying bootstrapping
2021-01-23T15:40:35.267620300Z: INFO: Attempting to bootstrap
2021-01-23T15:41:08.588566500Z: INFO: Using bootstrapper 54.77.133.220:8888
2021-01-23T15:41:08.588618200Z: INFO: Using bootstrapper 52.17.42.154:8888
2021-01-23T15:41:08.588634400Z: ERROR: Can't connect to the desired address: Already connected to 54.77.133.220:8888
2021-01-23T15:41:08.588637500Z: ERROR: Can't connect to the desired address: Already connected to 52.17.42.154:8888
2021-01-23T15:41:08.588639400Z: ERROR: Can't connect to the desired address: Already connected to 54.77.133.220:8888
2021-01-23T15:41:08.588641100Z: ERROR: Can't connect to the desired address: Already connected to 52.17.42.154:8888
2021-01-23T15:41:08.589022300Z: INFO: Attempting to bootstrap
2021-01-23T15:41:41.964854200Z: INFO: Using bootstrapper 54.77.133.220:8888
2021-01-23T15:41:41.964906500Z: INFO: Using bootstrapper 52.17.42.154:8888
2021-01-23T15:41:41.964912700Z: INFO: No peers at all - retrying bootstrapping
2021-01-23T15:41:41.964914500Z: INFO: Attempting to bootstrap
2021-01-23T15:42:15.290642100Z: INFO: Using bootstrapper 54.77.133.220:8888
2021-01-23T15:42:15.290675500Z: INFO: Using bootstrapper 52.17.42.154:8888
2021-01-23T15:42:15.391592500Z: ERROR: Can't connect to the desired address: Already connected to 54.77.133.220:8888
2021-01-23T15:42:15.391622000Z: ERROR: Can't connect to the desired address: Already connected to 52.17.42.154:8888
2021-01-23T15:42:15.392056700Z: INFO: Attempting to bootstrap
2021-01-23T15:42:48.920555300Z: INFO: Using bootstrapper 54.77.133.220:8888
2021-01-23T15:42:48.920586600Z: INFO: Using bootstrapper 52.17.42.154:8888
2021-01-23T15:42:48.920592700Z: INFO: No peers at all - retrying bootstrapping
2021-01-23T15:42:48.920594700Z: INFO: Attempting to bootstrap
2021-01-23T15:43:22.478123300Z: INFO: Using bootstrapper 54.77.133.220:8888
2021-01-23T15:43:22.478153300Z: INFO: Using bootstrapper 52.17.42.154:8888
2021-01-23T15:43:22.478169400Z: ERROR: Can't connect to the desired address: Already connected to 54.77.133.220:8888
2021-01-23T15:43:22.478172500Z: ERROR: Can't connect to the desired address: Already connected to 52.17.42.154:8888
2021-01-23T15:43:22.478174300Z: ERROR: Can't connect to the desired address: Already connected to 54.77.133.220:8888
2021-01-23T15:43:22.478175900Z: ERROR: Can't connect to the desired address: Already connected to 52.17.42.154:8888
2021-01-23T15:43:22.478757900Z: INFO: Attempting to bootstrap
2021-01-23T15:43:55.794873400Z: INFO: Using bootstrapper 54.77.133.220:8888
2021-01-23T15:43:55.794905100Z: INFO: Using bootstrapper 52.17.42.154:8888
2021-01-23T15:43:55.794910900Z: INFO: No peers at all - retrying bootstrapping
2021-01-23T15:43:55.794912700Z: INFO: Attempting to bootstrap
groupadd: group 'docker' already exists
useradd: user 'docker' already exists
bash: /usr/local/bin/concordium-client: No such file or directory
bash: /usr/local/bin/concordium-client: No such file or directory
2021-01-23 15:44:40,698 INFO Included extra file "/etc/supervisor/conf.d/concordium.conf" during parsing
2021-01-23 15:44:40,699 INFO Set uid to user 0 succeeded
Unlinking stale socket /var/run/supervisor.sock
2021-01-23 15:44:41,003 INFO RPC interface 'supervisor' initialized
2021-01-23 15:44:41,003 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2021-01-23 15:44:41,004 INFO supervisord started with pid 16
2021-01-23 15:44:42,007 INFO spawned: 'collector' with pid 18
2021-01-23 15:44:42,008 INFO spawned: 'p2p-client' with pid 19
2021-01-23T15:44:42.050000400Z: INFO: Starting up p2p_client version 0.4.8!
2021-01-23T15:44:42.050032200Z: INFO: Application data directory: "/var/lib/concordium/data"
2021-01-23T15:44:42.050037900Z: INFO: Application config directory: "/var/lib/concordium/config"
2021-01-23T15:44:42.050040300Z: INFO: Network: enabled
2021-01-23T15:44:42.050041900Z: INFO: Log level: info
2021-01-23T15:44:42.053778000Z: INFO: My Node ID is 5a1783a16076129c
2021-01-23T15:44:42.078803400Z: INFO: Starting consensus layer
2021-01-23T15:44:42.078833100Z: INFO: Starting up the consensus thread
2021-01-23T15:44:42.079710000Z: INFO: Starting up the consensus layer
2021-01-23 15:44:43,081 INFO success: collector entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2021-01-23 15:44:43,081 INFO success: p2p-client entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2021-01-23T15:45:12.932680900Z: INFO: Consensus layer started
2021-01-23T15:45:12.932768100Z: INFO: RPC server started
2021-01-23T15:45:12.932771900Z: INFO: Starting out of band catch-up
2021-01-23T15:45:12.936765400Z: ERROR: External: Error importing block: OtherError ResultDuplicate
2021-01-23T15:45:12.936795500Z: INFO: Completed out of band catch-up
2021-01-23T15:45:12.937061100Z: INFO: Starting the P2P layer
2021-01-23T15:45:12.937066300Z: INFO: Attempting to bootstrap

Hi @ZloyMyshok, thanks for the log snippet.

Just FYI, we are not ignoring it, as you stated. We've collected several reports from different channels and asked users to provide us with more info like log files and scenario descriptions. We could not reproduce the issue internally on our own nodes in our first trials. But we are still investigating.

a lot of people have the same problem. What is the solution

We figured it out now. I have described it in #70. Please have a look @ZloyMyshok and let me know, if it works for you.

And since you asked so nicely, please have a look there as well @buivando130898.

Hi ZloyMyshok

Did this happen on starting the node, or after a loss of connectivity?
If it happened after a loss of connectivity, try to restart your node and Docker.

If not, we might need to see the full log (the log can be generated using the tool concordium-node-retrieve-logs.exe).

Kind regards,
Emil, Concordium Support

the concordium-node-retrieve-logs.exe tool outputs a file that is too large in memory and cannot be uploaded. if only concordium-node-retrieve-minified_logs.exe but it is uninformative.

Yes it really works! But I think that this is not correct. Node cannot support the latest Docker updates on Windows !!!

It would have been really helpful for the website to point this out.