Skip to content
This repository has been archived by the owner on Dec 10, 2020. It is now read-only.

Add basic client/cli test #176

Open
wants to merge 1 commit into
base: master
Choose a base branch
from
Open

Add basic client/cli test #176

wants to merge 1 commit into from

Conversation

ryanio
Copy link
Contributor

@ryanio ryanio commented Nov 3, 2020

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

@codecov
Copy link

codecov bot commented Nov 3, 2020

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%) ⬇️
lib/sync/fetcher/fetcher.ts 78.84% <0.00%> (+1.92%) ⬆️

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.

test/cli/cli.spec.ts Outdated Show resolved Hide resolved
package.json Show resolved Hide resolved
t.fail(message)
end()
}
if (message.includes('Imported blocks')) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

FYI If data chunk size exceeds 16Kb (default value for readableHighWaterMark), then it will be split into several chunks to fit 16Kb size limit. So it's possible to meet the situation, when some part of 'Imported block' is in the first chunk and other is in another. It could be highly possible if script writes big bunch of data in one libuv event loop cycle, not sure if Client will ever do it. But if it will, then there will be false negative tests.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ah good to know, thanks, I was wondering about how it may be chunked. Any suggestions on a better or more reliable way to parse the incoming data?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think native IPC could be used here, it will simplify things dramatically. I've added #177 with a support of IPC logger. So we can just merge this PR (cause it works) and then apply that PR. Or if #177 wouldn't be applied to add IPC logger into current code.

@ryanio
Copy link
Contributor Author

ryanio commented Nov 3, 2020

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

@rumkin
Copy link
Contributor

rumkin commented Nov 4, 2020

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

@ryanio
Copy link
Contributor Author

ryanio commented Nov 4, 2020

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
Copy link
Contributor Author

ryanio commented Nov 5, 2020

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 ryanio force-pushed the add-cli-test branch 2 times, most recently from 2335c4e to 5b98930 Compare November 12, 2020 22:03
@ryanio
Copy link
Contributor Author

ryanio commented Nov 20, 2020

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

@rumkin
Copy link
Contributor

rumkin commented Nov 20, 2020

What version of Node throws this error?

@ryanio
Copy link
Contributor Author

ryanio commented Nov 20, 2020

What version of Node throws this error?

The ci runs on 12.x in this PR

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants