Trying to sync on testnet doesn't work, seems like connecting to peers is failing repeatedly

[delbonis]

It does connect to some bitcoin p2p peers, but the problem seems to be with dropping the connections to electrum peers.

The log just looks like this forever, even after waiting for some time:

2019-09-14 17:04:21,947 - electrum - DEBUG - Exception connecting to tn.not.fyi ()
2019-09-14 17:04:22,035 - electrum - DEBUG - ConnectionPool: connect, needed: 1
2019-09-14 17:04:22,037 - electrum - DEBUG - Connecting to peers (1)
2019-09-14 17:04:22,038 - electrum - DEBUG - Created client instance: testnet1.bauerj.eu
2019-09-14 17:04:22,039 - spruned.dependencies.connectrum - DEBUG - Connecting to: <ServerInfo testnet1.bauerj.eu nick=2c783916ec3b11a4 ports="['s50002']" v=1.4 prune=0>
2019-09-14 17:04:22,354 - spruned.dependencies.connectrum - DEBUG - Transport connected ok
2019-09-14 17:04:22,564 - spruned.dependencies.connectrum - DEBUG - Connected to: <ServerInfo testnet1.bauerj.eu nick=2c783916ec3b11a4 ports="['s50002']" v=1.4 prune=0>
2019-09-14 17:04:22,565 - electrum - INFO - Connected to peer testnet1.bauerj.eu:50002 (ElectrumX 1.12)
2019-09-14 17:04:22,566 - electrum - DEBUG - Peer raw response: ['ElectrumX 1.12', '1.4']
2019-09-14 17:04:22,887 - electrum - DEBUG - 1415135 headers behind, downloading
2019-09-14 17:04:23,422 - asyncio - ERROR - Task exception was never retrieved
future: <Task finished coro=<async_delayed_task() done, defined at /usr/local/site-packages/spruned/application/tools.py:71> exception=TypeError("'NoneType' object is not subscriptable (key 0)",)>
Traceback (most recent call last):
  File "/usr/local/lib-python/3/asyncio/tasks.py", line 179, in _step
    result = coro.send(None)
  File "/usr/local/site-packages/spruned/application/tools.py", line 75, in async_delayed_task
    return await task
  File "/usr/local/site-packages/spruned/daemon/electrod/electrod_interface.py", line 78, in parse_and_go
    return await callback(peer, header)
  File "/usr/local/site-packages/spruned/daemon/tasks/headers_reactor.py", line 163, in on_new_header
    await self.on_local_headers_behind(local_best_header, network_best_header)
  File "/usr/local/site-packages/spruned/daemon/tasks/headers_reactor.py", line 253, in on_local_headers_behind
    await self._fetch_headers_chunks(chunks_at_time, local_best_header, network_best_header)
  File "/usr/local/site-packages/spruned/daemon/tasks/headers_reactor.py", line 320, in _fetch_headers_chunks
    res = await self.interface.get_headers_in_range_from_chunks(_from, _to, get_peer=True)
  File "/usr/local/site-packages/spruned/daemon/electrod/electrod_interface.py", line 155, in get_headers_in_range_from_chunks
    peer = response[0]
TypeError: 'NoneType' object is not subscriptable (key 0)
2019-09-14 17:04:23,433 - asyncio - ERROR - Task exception was never retrieved
future: <Task finished coro=<async_delayed_task() done, defined at /usr/local/site-packages/spruned/application/tools.py:71> exception=TypeError("'NoneType' object is not subscriptable (key 0)",)>
Traceback (most recent call last):
  File "/usr/local/lib-python/3/asyncio/tasks.py", line 179, in _step
    result = coro.send(None)
  File "/usr/local/site-packages/spruned/application/tools.py", line 75, in async_delayed_task
    return await task
  File "/usr/local/site-packages/spruned/daemon/electrod/electrod_interface.py", line 78, in parse_and_go
    return await callback(peer, header)
  File "/usr/local/site-packages/spruned/daemon/tasks/headers_reactor.py", line 163, in on_new_header
    await self.on_local_headers_behind(local_best_header, network_best_header)
  File "/usr/local/site-packages/spruned/daemon/tasks/headers_reactor.py", line 253, in on_local_headers_behind
    await self._fetch_headers_chunks(chunks_at_time, local_best_header, network_best_header)
  File "/usr/local/site-packages/spruned/daemon/tasks/headers_reactor.py", line 320, in _fetch_headers_chunks
    res = await self.interface.get_headers_in_range_from_chunks(_from, _to, get_peer=True)
  File "/usr/local/site-packages/spruned/daemon/electrod/electrod_interface.py", line 155, in get_headers_in_range_from_chunks
    peer = response[0]
TypeError: 'NoneType' object is not subscriptable (key 0)
2019-09-14 17:04:23,462 - electrum - DEBUG - Fetched 2016 headers (chunk 80/81), tot. 0
2019-09-14 17:04:23,463 - electrum - DEBUG - 1415135 headers behind, downloading
2019-09-14 17:04:23,566 - spruned.dependencies.connectrum - DEBUG - Error response: '{'code': -101, 'message': 'excessive resource usage'}'
2019-09-14 17:04:23,568 - spruned.dependencies.connectrum - WARNING - Electrum server connection lost

This might be part of the issue:

2019-09-14 17:04:23,566 - spruned.dependencies.connectrum - DEBUG - Error response: '{'code': -101, 'message': 'excessive resource usage'}'

As well as that big scary exception.

On version 0.0.10. Mainnet works fine on my machine.

[delbonis]

Correction, just started from a clean data dir again to verify:

It syncs up to 000000002329351dd70c24da2eea5ac19f65b6053c4611aa4eb93bcc2783c57e at height 193535 before encountering the error above.

[gdassori]

Yeah the whole Electrum interface need to be renewed. I'm back on the project and I'll work on this issues. Thanks for reporting.

[gdassori]

112