ethereumjs-client icon indicating copy to clipboard operation
ethereumjs-client copied to clipboard

Published 20 hours ago • verified publisher icon ethereumjs

Add basic client/cli test

Open ryanio opened this issue 5 years ago • 8 comments

This PR adds a simple client/cli test that spins up the client and waits to successfully download a block.

Sample output:

TAP version 13
# [CLI]
# should begin downloading blocks

INFO [11-03|12:38:29] Data directory: /Users/rg/Library/Ethereum/ethereumjs/chaindata
INFO [11-03|12:38:29] Initializing Ethereumjs client...
INFO [11-03|12:38:29] Fast sync mode
INFO [11-03|12:38:29] Connecting to network: mainnet
INFO [11-03|12:38:29] Latest local block: number=0 td=17179869184 hash=d4e56740...
INFO [11-03|12:38:29] Synchronizing blockchain...
INFO [11-03|12:38:29] Started rlpx server.
INFO [11-03|12:38:29] Started libp2p server.
INFO [11-03|12:38:29] Listener up transport=rlpx url=enode://3c2590d59c49c05f167ce1a34fb1d934b55f65a45625cfa869507fe46504d72507734ac4e83d6b1c1f561bcff25ccea0cc72b51a68441d79e4de191a331c0475@[::]:30303
INFO [11-03|12:38:29] Listener up transport=libp2p url=/p2p-circuit/ipfs/QmWTZWwQGudKtkJFNvKiPt7E9bnt3YwVTqG1mytiRcF25v
INFO [11-03|12:38:29] Listener up transport=libp2p url=/p2p-circuit/ip4/127.0.0.1/tcp/50580/ws/ipfs/QmWTZWwQGudKtkJFNvKiPt7E9bnt3YwVTqG1mytiRcF25v
INFO [11-03|12:38:29] Listener up transport=libp2p url=/ip4/127.0.0.1/tcp/50580/ws/ipfs/QmWTZWwQGudKtkJFNvKiPt7E9bnt3YwVTqG1mytiRcF25v
INFO [11-03|12:38:29] Started eth service.
INFO [11-03|12:38:49] Looking for suited peers...
ok 1 (successfully imported blocks)
INFO [11-03|12:39:07] Imported blocks count=128 number=1 hash=88e96d45... peers=1
INFO [11-03|12:39:07] Caught interrupt signal. Shutting down...
INFO [11-03|12:39:07] Synchronized
INFO [11-03|12:39:08] Stopped eth service.
INFO [11-03|12:39:08] Stopped rlpx server.
INFO [11-03|12:39:08] Stopped libp2p server.
INFO [11-03|12:39:08] Exiting.

1..1
# tests 1
# pass  1

# ok

ryanio avatar Nov 03 '20 20:11 ryanio

Codecov Report

Merging #176 (3a4624c) into master (e964276) will decrease coverage by 0.06%. The diff coverage is n/a.

Impacted file tree graph

@@            Coverage Diff             @@
##           master     #176      +/-   ##
==========================================
- Coverage   87.41%   87.34%   -0.07%     
==========================================
  Files          45       45              
  Lines        1486     1486              
  Branches      229      229              
==========================================
- Hits         1299     1298       -1     
- Misses        103      104       +1     
  Partials       84       84
Impacted Files Coverage Δ
lib/net/protocol/protocol.ts 88.88% <0.00%> (-8.34%) :arrow_down:
lib/sync/fetcher/fetcher.ts 78.84% <0.00%> (+1.92%) :arrow_up:

Continue to review full report at Codecov.

Legend - Click here to learn more Δ = absolute <relative> (impact), ø = not affected, ? = missing data Powered by Codecov. Last update e964276...3a4624c. Read the comment docs.

codecov[bot] avatar Nov 03 '20 20:11 codecov[bot]

I'm occasionally getting this race condition in CI, haven't run into this locally yet. If you look at the timestamps you can see that it's not related to exceeding the test's 4 minute timeout:

...

INFO [11-03|23:52:10] Started eth service.

INFO [11-03|23:52:29] Looking for suited peers...

not ok 1 ERROR [11-03|23:52:41] Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed at doWrite (_stream_writable.js:399:19) at writeOrBuffer (_stream_writable.js:387:5) at Socket.Writable.write (_stream_writable.js:318:11) at Peer._sendMessage (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:187:22) at Peer._sendPong (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:246:14) at Peer._handlePing (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:408:14) at Peer._handleMessage (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:432:22) at Peer._handleBody (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:485:26) at Peer._onSocketData (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:515:30) at Socket.emit (events.js:314:20) 
  ---
    operator: fail
    at: Socket.<anonymous> (/home/runner/work/ethereumjs-client/ethereumjs-client/test/cli/cli.spec.ts:24:11)
    stack: |-
      Error: ERROR [11-03|23:52:41] Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
          at doWrite (_stream_writable.js:399:19)
          at writeOrBuffer (_stream_writable.js:387:5)
          at Socket.Writable.write (_stream_writable.js:318:11)
          at Peer._sendMessage (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:187:22)
          at Peer._sendPong (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:246:14)
          at Peer._handlePing (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:408:14)
          at Peer._handleMessage (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:432:22)
          at Peer._handleBody (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:485:26)
          at Peer._onSocketData (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:515:30)
          at Socket.emit (events.js:314:20)
      
          at Test.assert [as _assert] (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/tape/lib/test.js:226:54)
          at Test.bound [as _assert] (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/tape/lib/test.js:77:32)
          at Test.fail (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/tape/lib/test.js:319:10)
          at Test.bound [as fail] (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/tape/lib/test.js:77:32)
          at Socket.<anonymous> (/home/runner/work/ethereumjs-client/ethereumjs-client/test/cli/cli.spec.ts:24:11)
          at Socket.emit (events.js:314:20)
          at addChunk (_stream_readable.js:298:12)
          at readableAddChunk (_stream_readable.js:273:9)
          at Socket.Readable.push (_stream_readable.js:214:10)
          at Pipe.onStreamRead (internal/stream_base_commons.js:188:23)
  ...
ERROR [11-03|23:52:41] Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
    at doWrite (_stream_writable.js:399:19)
    at writeOrBuffer (_stream_writable.js:387:5)
    at Socket.Writable.write (_stream_writable.js:318:11)
    at Peer._sendMessage (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:187:22)
    at Peer._sendPong (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:246:14)
    at Peer._handlePing (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:408:14)
    at Peer._handleMessage (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:432:22)
    at Peer._handleBody (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:485:26)
    at Peer._onSocketData (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:515:30)
    at Socket.emit (events.js:314:20)

I'm still looking into why this happens.

One idea I have is that it may be because of the default 8s timeout in some other parts of the lib:

Screen Shot 2020-11-03 at 4 11 13 PM

ryanio avatar Nov 03 '20 23:11 ryanio

It's in a ping-pong method handler. It seems like node server is shutting down without waiting of underlying sockets to be closed.

rumkin avatar Nov 04 '20 00:11 rumkin

It's in a ping-pong method handler. It seems like node server is shutting down without waiting of underlying sockets to be closed.

yeah, I'm finding that the handshake is indeed timing out (Error: Handshake timed out after 8000ms), but I'm having trouble locating why the server or socket would be closing or closed due to this timeout.

It looks like in the error stack trace above that it does eventually get the ping message back so it's trying to send back pong, but the socket is closed.

If the socket does close in devp2p, then it should set the socket _closed property to true so that it doesn't hit an error of writing to a closed socket (will just return instead).

I'm not seeing anywhere else currently that if the handshake timeout limit is exceeded, that it's stopping, closing, or destroying anything.

Still looking into it 🤔

ryanio avatar Nov 04 '20 21:11 ryanio

Continuing debugging here, my hunch in this run below is that it's a race condition of a peer disconnecting (TOO_MANY_PEERS) but the peer still trying to send a pong response back to the socket?

This is still confusing to me though because at the top of _sendMessage in devp2p there is if (this._closed) return false so it shouldn't reach the _socket.write

INFO [11-05|19:37:00] Started eth service.

DEBUG [11-05|19:37:01] Peer connected: id=279944d8 address=35.158.244.151:30303 transport=rlpx protocols=eth 

DEBUG [11-05|19:37:01] Found fast peer: id=279944d8 address=35.158.244.151:30303 transport=rlpx protocols=eth 

DEBUG [11-05|19:37:01] Peer added: id=279944d8 address=35.158.244.151:30303 transport=rlpx protocols=eth 

DEBUG [11-05|19:37:01] Peer disconnected (TOO_MANY_PEERS): id=279944d8 address=35.158.244.151:30303 transport=rlpx protocols=eth 

DEBUG [11-05|19:37:01] Peer removed: id=279944d8 address=35.158.244.151:30303 transport=rlpx protocols=eth 

DEBUG [11-05|19:37:01] Peer connected: id=715171f5 address=52.231.165.108:30303 transport=rlpx protocols=eth 

DEBUG [11-05|19:37:01] Found fast peer: id=715171f5 address=52.231.165.108:30303 transport=rlpx protocols=eth 

DEBUG [11-05|19:37:01] Peer added: id=715171f5 address=52.231.165.108:30303 transport=rlpx protocols=eth 

DEBUG [11-05|19:37:01] Peer disconnected (TOO_MANY_PEERS): id=715171f5 address=52.231.165.108:30303 transport=rlpx protocols=eth 

DEBUG [11-05|19:37:01] Peer removed: id=715171f5 address=52.231.165.108:30303 transport=rlpx protocols=eth 

INFO [11-05|19:37:19] Looking for suited peers...

not ok 1 ERROR [11-05|19:37:30] Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed at doWrite (_stream_writable.js:399:19) at writeOrBuffer (_stream_writable.js:387:5) at Socket.Writable.write (_stream_writable.js:318:11) at Peer._sendMessage (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:187:22) at Peer._sendPong (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:246:14) at Peer._handlePing (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:408:14) at Peer._handleMessage (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:432:22) at Peer._handleBody (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:485:26) at Peer._onSocketData (/home/runner/work/ethereumjs-client/ethereumjs-client/node_modules/ethereumjs-devp2p/dist/rlpx/peer.js:515:30) at Socket.emit (events.js:314:20)

ryanio avatar Nov 05 '20 20:11 ryanio

I have rebased this branch on latest master.

It is still working well for me locally (see my latest run below), however still debugging the intermittent timeout issue on CI.

TAP version 13
# [CLI]
# should begin downloading blocks
INFO [11-20|11:18:29] Sync data directory: /Users/rg/Library/Ethereum/ethereumjs/chaindata
INFO [11-20|11:18:29] Initializing Ethereumjs client...
INFO [11-20|11:18:29] Full sync mode
INFO [11-20|11:18:29] Connecting to network: mainnet
INFO [11-20|11:18:29] Latest local block: number=30848 td=22399522225262025 hash=17fa9bf8...
INFO [11-20|11:18:29] Synchronizing blockchain...
INFO [11-20|11:18:29] Started rlpx server.
INFO [11-20|11:18:29] Started libp2p server.
INFO [11-20|11:18:29] Listener up transport=rlpx url=enode://4b8019e15c7c675e2b9abd88d0450394cc6df515cab35c6bf05170454be7ac5faae9bd9c7fdd1895c786d0817c069f9d1f8b659e297cd21564c10a5aa1118892@[::]:30303
INFO [11-20|11:18:29] Listener up transport=libp2p url=/p2p-circuit/ipfs/QmR7LFxcifAv2uqPH3iBReB2VKhsEaL5WwRGHnBReQouYU
INFO [11-20|11:18:29] Listener up transport=libp2p url=/p2p-circuit/ip4/127.0.0.1/tcp/50580/ws/ipfs/QmR7LFxcifAv2uqPH3iBReB2VKhsEaL5WwRGHnBReQouYU
INFO [11-20|11:18:29] Listener up transport=libp2p url=/ip4/127.0.0.1/tcp/50580/ws/ipfs/QmR7LFxcifAv2uqPH3iBReB2VKhsEaL5WwRGHnBReQouYU
INFO [11-20|11:18:29] Started eth service.
INFO [11-20|11:18:49] Looking for suited peers...
INFO [11-20|11:19:09] Looking for suited peers...
INFO [11-20|11:19:29] Retriggering bootstrap.
ok 1 successfully imported blocks
INFO [11-20|11:19:42] Imported blocks count=128 number=30849 hash=b9731de4... peers=3
INFO [11-20|11:19:42] Caught interrupt signal. Shutting down...
INFO [11-20|11:19:49] Synchronized
INFO [11-20|11:19:50] Stopped eth service.
INFO [11-20|11:19:50] Stopped rlpx server.
INFO [11-20|11:19:50] Stopped libp2p server.
INFO [11-20|11:19:50] Exiting.

1..1
# tests 1
# pass  1

# ok

ryanio avatar Nov 20 '20 19:11 ryanio

What version of Node throws this error?

rumkin avatar Nov 20 '20 20:11 rumkin

What version of Node throws this error?

The ci runs on 12.x in this PR

ryanio avatar Nov 20 '20 21:11 ryanio