Dockerized testrpc throws `Invalid JSON RPC response: ""`

anoff commented 6 years ago

Running the pre-deployed Sonar contract via the openmined/sonar-testrpc:edge docker image this error keeps showing up on several peoples machines. It works for some time but then suddenly the testrpc process does not respond anymore.

Things to help debug this problem:

curl -X POST -H "Content-Type: application/json" --data '{"jsonrpc":"2.0","method":"eth_gasPrice","params":[],"id":73}' localhost:8545
- should return a JSON response e.g. {"id":73,"jsonrpc":"2.0","result":"0x4A817C800"}
- returns curl: (52) Empty reply from server if the container is misbehaving

System:

macOS 10.12.6
docker 17.06.0-ce-mac18 (18433)

carrollgt91 commented 6 years ago

One thing that could prove useful in figuring out the root cause of the issue would be to add the debug flag when running testrpc. I'm getting on that now.

carrollgt91 commented 6 years ago

As far as I can tell, after some (admittedly unscientific) investigation, it is not always calls to testrpc that are causing these errors, but calls to ipfs.

Here's a couple of stacktraces which demonstrate:

> mine.js@0.0.2 start /Users/graysoncarroll/src/openmined/mine.js
> node ./bin/cli.js train "--mine-address=0xe8cd631a35daea6c76cf9a8c04c1a326fe69f9a9" "--contract-address=0x249c008fc4f9c01248f557985f5b5b1aed8eb98f"

🔎️  Looking for models to train at 0x249c008fc4f9c01248f557985f5b5b1aed8eb98f for mine 0xe8cd631a35daea6c76cf9a8c04c1a326fe69f9a9
(node:67616) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 1): Error: Invalid JSON RPC response: ""
(node:67616) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

> mine.js@0.0.2 start /Users/graysoncarroll/src/openmined/mine.js
> node ./bin/cli.js train "--mine-address=0xe8cd631a35daea6c76cf9a8c04c1a326fe69f9a9" "--contract-address=0x249c008fc4f9c01248f557985f5b5b1aed8eb98f"

🔎️  Looking for models to train at 0x249c008fc4f9c01248f557985f5b5b1aed8eb98f for mine 0xe8cd631a35daea6c76cf9a8c04c1a326fe69f9a9
💃  1 models found
 💃  model#0 with 2 gradients at IPFS:QmajUCN3AJGTGr8AsNNmNRbe9rEjF9wisojzseLpoq2faX
  ⬇️  Downloading latest model
  🏋️  Training the model latest model
  ⬆️  Uploading new gradients to IPFS
{ Error: read ECONNRESET
    at _errnoException (util.js:1041:11)
    at TCP.onread (net.js:606:25) code: 'ECONNRESET', errno: 'ECONNRESET', syscall: 'read' }
{ Error: read ECONNRESET
    at _errnoException (util.js:1041:11)
    at TCP.onread (net.js:606:25) code: 'ECONNRESET', errno: 'ECONNRESET', syscall: 'read' }
Unhandled rejection Error: Invalid JSON RPC response: ""
    at Object.InvalidResponse (/Users/graysoncarroll/src/openmined/mine.js/node_modules/web3/packages/web3-core-helpers/src/errors.js:42:16)
    at XMLHttpRequest.request.onreadystatechange (/Users/graysoncarroll/src/openmined/mine.js/node_modules/web3/packages/web3-providers-http/src/index.js:60:32)
    at XMLHttpRequestEventTarget.dispatchEvent (/Users/graysoncarroll/src/openmined/mine.js/node_modules/web3/packages/web3-providers-http/node_modules/xhr2/lib/xhr2.js:64:18)
    at XMLHttpRequest._setReadyState (/Users/graysoncarroll/src/openmined/mine.js/node_modules/web3/packages/web3-providers-http/node_modules/xhr2/lib/xhr2.js:354:12)
    at XMLHttpRequest._onHttpRequestError (/Users/graysoncarroll/src/openmined/mine.js/node_modules/web3/packages/web3-providers-http/node_modules/xhr2/lib/xhr2.js:544:12)
    at ClientRequest.<anonymous> (/Users/graysoncarroll/src/openmined/mine.js/node_modules/web3/packages/web3-providers-http/node_modules/xhr2/lib/xhr2.js:414:24)
    at emitOne (events.js:115:13)
    at ClientRequest.emit (events.js:210:7)
    at Socket.socketOnEnd (_http_client.js:437:9)
    at emitNone (events.js:110:20)
    at Socket.emit (events.js:207:7)
    at endReadableNT (_stream_readable.js:1059:12)
    at _combinedTickCallback (internal/process/next_tick.js:138:11)
    at process._tickCallback (internal/process/next_tick.js:180:9)

(node:67578) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 1): Error: Invalid JSON RPC response: ""
(node:67578) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

carrollgt91 commented 6 years ago

That being said, when I receive these errors and make that curl call, it seems to behave as you describe, @anoff. Definitely something bizarre going on here. I'm going to see if we see similar results when running mine.js in the same docker-compose setup.

carrollgt91 commented 6 years ago

Another potentially useful stack trace (this time, from the third input block in https://github.com/OpenMined/PySonar/blob/master/notebooks/Sonar%20-%20Decentralized%20Model%20Training%20Simulation%20(local%20blockchain).ipynb)

To reproduce: Simply execute this cell ~5 times in quick succession when running the notebook locally and pointing to ipfs and testrpc running in docker.

---------------------------------------------------------------------------
BrokenPipeError                           Traceback (most recent call last)
/usr/local/lib/python3.6/site-packages/requests/adapters.py in send(self, request, stream, timeout, verify, cert, proxies)
    461                         low_conn.send(hex(len(i))[2:].encode('utf-8'))
--> 462                         low_conn.send(b'\r\n')
    463                         low_conn.send(i)

/usr/local/Cellar/python3/3.6.2/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py in send(self, data)
    985         try:
--> 986             self.sock.sendall(data)
    987         except TypeError:

BrokenPipeError: [Errno 32] Broken pipe

During handling of the above exception, another exception occurred:

ConnectionError                           Traceback (most recent call last)
/usr/local/lib/python3.6/site-packages/ipfsapi/http.py in _do_request(self, *args, **kwargs)
     74             else:
---> 75                 return requests.request(*args, **kwargs)
     76         except requests.ConnectionError as error:

/usr/local/lib/python3.6/site-packages/requests/api.py in request(method, url, **kwargs)
     57     with sessions.Session() as session:
---> 58         return session.request(method=method, url=url, **kwargs)
     59 

/usr/local/lib/python3.6/site-packages/requests/sessions.py in request(self, method, url, params, data, headers, cookies, files, auth, timeout, allow_redirects, proxies, hooks, stream, verify, cert, json)
    507         send_kwargs.update(settings)
--> 508         resp = self.send(prep, **send_kwargs)
    509 

/usr/local/lib/python3.6/site-packages/requests/sessions.py in send(self, request, **kwargs)
    617         # Send the request
--> 618         r = adapter.send(request, **kwargs)
    619 

/usr/local/lib/python3.6/site-packages/requests/adapters.py in send(self, request, stream, timeout, verify, cert, proxies)
    489         except (ProtocolError, socket.error) as err:
--> 490             raise ConnectionError(err, request=request)
    491 

ConnectionError: [Errno 32] Broken pipe

The above exception was the direct cause of the following exception:

ConnectionError                           Traceback (most recent call last)
<ipython-input-32-7ed45cbeb00d> in <module>()
     10                        target_error = 10000
     11                       )
---> 12 model_id = repo.submit_model(diabetes_model)

/usr/local/lib/python3.6/site-packages/sonar-0.1.0-py3.6.egg/sonar/contracts.py in submit_model(self, model)
    151         """
    152 
--> 153         ipfs_address = self.ipfs.add_pyobj(model.syft_obj)
    154         deploy_trans = self.get_transaction(model.owner,value=self.web3.toWei(model.bounty,'ether')).addModel([ipfs_address[0:32],ipfs_address[32:]],model.initial_error,model.target_error)
    155         return self.call.getNumModels()-1

/usr/local/lib/python3.6/site-packages/ipfsapi/client.py in add_pyobj(self, py_obj, **kwargs)
   2176         warnings.warn("Using `*_pyobj` on untrusted data is a security risk",
   2177                       DeprecationWarning)
-> 2178         return self.add_bytes(encoding.Pickle().encode(py_obj), **kwargs)
   2179 
   2180     def get_pyobj(self, multihash, **kwargs):

/usr/local/lib/python3.6/site-packages/ipfsapi/utils.py in wrapper(*args, **kwargs)
    148                 Named parameter to pass to the wrapped callable
    149             """
--> 150             res = cmd(*args, **kwargs)
    151             return res[self.field]
    152         return wrapper

/usr/local/lib/python3.6/site-packages/ipfsapi/client.py in add_bytes(self, data, **kwargs)
   2085         body, headers = multipart.stream_bytes(data, self.chunk_size)
   2086         return self._client.request('/add', decoder='json',
-> 2087                                     data=body, headers=headers, **kwargs)
   2088 
   2089     @utils.return_field('Hash')

/usr/local/lib/python3.6/site-packages/ipfsapi/http.py in wrapper(self, *args, **kwargs)
     35         merged.update(self.defaults)
     36         merged.update(kwargs)
---> 37         return func(self, *args, **merged)
     38     return wrapper
     39 

/usr/local/lib/python3.6/site-packages/ipfsapi/http.py in request(self, path, args, files, opts, stream, decoder, headers, data)
    168 
    169         return self._request(method, url, params, parser, stream,
--> 170                              files, headers, data)
    171 
    172     @pass_defaults

/usr/local/lib/python3.6/site-packages/ipfsapi/http.py in _request(self, method, url, params, parser, stream, files, headers, data)
     98         # Do HTTP request (synchronously)
     99         res = self._do_request(method, url, params=params, stream=stream,
--> 100                                files=files, headers=headers, data=data)
    101 
    102         if stream:

/usr/local/lib/python3.6/site-packages/ipfsapi/http.py in _do_request(self, *args, **kwargs)
     75                 return requests.request(*args, **kwargs)
     76         except requests.ConnectionError as error:
---> 77             six.raise_from(exceptions.ConnectionError(error), error)
     78         except http_client.HTTPException as error:
     79             six.raise_from(exceptions.ProtocolError(error), error)

/usr/local/lib/python3.6/site-packages/six.py in raise_from(value, from_value)

ConnectionError: ConnectionError: [Errno 32] Broken pipe

anoff commented 6 years ago

Thanks for collecting all those logs. Piecing together those chunks hopefully brings us closer to the solution.

I think IPFS and testrpc might both have an issue there. The first stacktrace shows web3 which is the ethereum library (so should be linked to testrpc), the second one has IPFS.

Should we open a second ticket for the IPFS issue?

carrollgt91 commented 6 years ago

Alright, I have some more insight! If you follow the instructions to get PySonar up and running in docker-compose in the branch referenced in this PR, then you'll see that you won't run into the broken pipe errors seen in my previous comment. I even went so far as to duplicate the code in the cell that was causing the problem in order to run it back to back, and it did not have any errors.

This supports my hunch that the issues we're seeing here are networking issues between your local machine and the Docker host on your machine. I've noticed these problems when developing at my day job, but wanted to have a repeatable case where they were solved by moving all components requiring network communication to testrpc or ipfs into docker before firmly stating that conclusion.

tl,dr: Run this version of PySonar, try and run input cell 3 a bunch, see no errors. Run PySonar locally, try and run input cell 3 a bunch, see broken pipe errors. I believe moving all applications needing to communicate with ipfs and testrpc into docker will solve these weird issues.