MicroRaiden fails to start with geth on Ropsten possibly because of long-running event polling

[andrevmatos]

Trying to make a fresh start of MicroRaiden proxy, over geth, fails on first run with:

DEBUG:filelock:Attempting to acquire lock 140258049727456 on /home/andre/.config/micro-raiden/0xeb244b0502a2d3867e5cab2347c6e1cdeb5e1eef_0x004b52c58863c903ab012537247b963c557929e8.pkl
INFO:filelock:Lock 140258049727456 acquired on /home/andre/.config/micro-raiden/0xeb244b0502a2d3867e5cab2347c6e1cdeb5e1eef_0x004b52c58863c903ab012537247b963c557929e8.pkl
DEBUG:channel_manager:setting up channel manager, receiver=0x004b52c58863c903ab012537247b963c557929e8 channel_contract=0xeb244b0502a2d3867e5cab2347c6e1cdeb5e1eef
INFO:blockchain:starting blockchain polling (frequency 2s)
DEBUG:blockchain:filtering for events u:0-1593423 c:0-1593418 @1593423
Traceback (most recent call last):
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/urllib3/connectionpool.py", line 387, in _make_request
    six.raise_from(e, None)
  File "<string>", line 2, in raise_from
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/urllib3/connectionpool.py", line 383, in _make_request
    httplib_response = conn.getresponse()
  File "/usr/lib64/python3.6/http/client.py", line 1331, in getresponse
    response.begin()
  File "/usr/lib64/python3.6/http/client.py", line 297, in begin
    version, status, reason = self._read_status()
  File "/usr/lib64/python3.6/http/client.py", line 258, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "/usr/lib64/python3.6/socket.py", line 586, in readinto
    return self._sock.recv_into(b)
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/gevent/_socket3.py", line 384, in recv_into
    self._wait(self._read_event)
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/gevent/_socket3.py", line 156, in _wait
    self.hub.wait(watcher)
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/gevent/hub.py", line 651, in wait
    result = waiter.get()
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/gevent/hub.py", line 898, in get
    return self.hub.switch()
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/gevent/hub.py", line 630, in switch
    return RawGreenlet.switch(self)
socket.timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/requests/adapters.py", line 440, in send
    timeout=timeout
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/urllib3/connectionpool.py", line 639, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/urllib3/util/retry.py", line 357, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/urllib3/packages/six.py", line 686, in reraise
    raise value
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/urllib3/connectionpool.py", line 601, in urlopen
    chunked=chunked)
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/urllib3/connectionpool.py", line 389, in _make_request
    self._raise_timeout(err=e, url=url, timeout_value=read_timeout)
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/urllib3/connectionpool.py", line 309, in _raise_timeout
    raise ReadTimeoutError(self, url, "Read timed out. (read timeout=%s)" % timeout_value)
urllib3.exceptions.ReadTimeoutError: HTTPConnectionPool(host='127.0.0.1', port=8545): Read timed out. (read timeout=10)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib64/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/usr/lib64/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/sec/Dev/BrainBot/raiden-micropayment-service/microraiden/microraiden/proxy/__main__.py", line 128, in <module>
    main()
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/click/core.py", line 722, in __call__
    return self.main(*args, **kwargs)
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/click/core.py", line 697, in main
    rv = self.invoke(ctx)
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/click/core.py", line 895, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/click/core.py", line 535, in invoke
    return callback(*args, **kwargs)
  File "/sec/Dev/BrainBot/raiden-micropayment-service/microraiden/microraiden/proxy/__main__.py", line 117, in main
    app.run(debug=True, ssl_context=(ssl_key, ssl_cert))
  File "/sec/Dev/BrainBot/raiden-micropayment-service/microraiden/microraiden/proxy/paywalled_proxy.py", line 109, in run
    self.channel_manager.wait_sync()
  File "/sec/Dev/BrainBot/raiden-micropayment-service/microraiden/microraiden/channel_manager.py", line 545, in wait_sync
    self.blockchain.wait_sync()
  File "/sec/Dev/BrainBot/raiden-micropayment-service/microraiden/microraiden/channel_manager.py", line 79, in wait_sync
    self.wait_sync_event.wait()
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/gevent/event.py", line 219, in wait
    return self._wait(timeout)
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/gevent/event.py", line 129, in _wait
    gotit = self._wait_core(timeout)
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/gevent/event.py", line 106, in _wait_core
    result = self.hub.switch()
  File "/sec/Dev/BrainBot/raiden-micropayment-service/virtualenv3/lib/python3.6/site-packages/gevent/hub.py", line 630, in switch
    return RawGreenlet.switch(self)
requests.exceptions.ReadTimeout: HTTPConnectionPool(host='127.0.0.1', port=8545): Read timed out. (read timeout=10)

I'm pretty sure it's related with geth being way slower than Parity for fetching events. It scans every block on the fromBlock:toBlock range (i.e. the whole blockchain, if these options aren't provided).

In my tests, it takes around 30s to scan the whole blockchain for a given event, on Ropsten (but the problem should be similar on other networks too).

After this exception, every following attempt to run MicroRaiden fails without proper information, printing only to stderr only Aborted! , which refers to a click's exception.
Only way to get it to run again is to remove ~/.config/micro-raiden/.

We must support geth from day-0.

Solution

• To be sure there's an ETH node running on the address, and not hang forever: make a quick health check on micro-raiden start, doing a small request with a timeout (e.g. web3.version.network, 2s timeout), catch any error and handle it correctly, showing informative error message to the user and exiting in a clean way.
• Remove timeouts, and support arbitrarily long running requests (don't trust geth will return quickly). Use gevents/AsyncResult, if needed, but if the request is running on it's own Greenlet, gevent's monkey patch should assure everything keeps smooth.
• Even supporting long running requests, the best for user experience is to avoid it, so a good approach is to hard-code (together with contract addresses) a higher-than-genesis block go be the base for event scanning. I suggest contract-deployment block, but any block before that should also work.
• Above is for first event scan (eth_getFilterLogs and eth_getLogs): it must cache the latest block scanned, and sub-sequent event fetching should make sure it's scanning only newer blocks (filters with latest and using eth_getFilterChanges should handle it automatically).

[andrevmatos]

@jannikluhn 3rd point above was not implemented yet.. o geth, it takes several minutes to start MicroRaiden, because of initial scan. We don't need to scan the whole blockchain, there could be only events after current contract deployment.

[andrevmatos]

Because of the above, and also because of 2nd point of OP, still got 60 seconds timeout on first and second start of MicroRaiden, so this issue is still happening.

[pcppcp]

Make Geth Log Scan Great Again patch has been merged. We can close this now.

ethereum/go-ethereum#15091 (comment)