Skip to content

Plan: secure-channel#335

Closed
yusefnapora wants to merge 7 commits intotestground:masterfrom
yusefnapora:plan/secure-channel
Closed

Plan: secure-channel#335
yusefnapora wants to merge 7 commits intotestground:masterfrom
yusefnapora:plan/secure-channel

Conversation

@yusefnapora
Copy link
Copy Markdown
Contributor

@yusefnapora yusefnapora commented Jan 13, 2020 •
edited
Loading

This adds a secure-channel test plan, described in libp2p/go-libp2p-noise#32

It just configures a libp2p Host using the provided secure_channel param and does a transfer of random data (length set by the payload_size param) from one peer to another.

Valid secure_channel values are secio, tls, and noise.

TODO:

  • add README for plan
  • re-enable docker & swarm executors in manifest

@yusefnapora yusefnapora mentioned this pull request Jan 14, 2020
Open
3 tasks
@yusefnapora
add secure-channel test plan
22b89e3
@yusefnapora
emit metrics for transfer time
6992e92
@yusefnapora
re-enable docker runners
5feaa96
@yusefnapora
rm redundant Sprintf
4e26c20
@yusefnapora
add timeout param
28c639e 
also adds a teardown function to clean up
@yusefnapora
use blankhost instead of basichost
cf7a053 
also removes calls to runenv.Abort & updates to return errors from test
@yusefnapora
stream generated data instead of making temp buf
e90afbb 
also, emits separate read and write time metrics
@yusefnapora
Copy link
Copy Markdown
Contributor Author

yusefnapora commented Jan 28, 2020

A quick update on this - I've been trying to figure out what's causing "broken pipe" errors when running this test with noise.

log output with broken pipe 
   0.4181s    MESSAGE << instance   0 >> I am 12D3KooWF48ukrFNntx5podedyYXf1WcuYPqdTTNYgCJNMZ4PDpk with addrs: [/ip4/127.0.0.1/tcp/51611 /ip4/192.168.86.108/tcp/51611 /ip6/::1/tcp/51613]. isInitator=true
   0.4181s    MESSAGE << instance   1 >> I am 12D3KooWPEPucYxaHsCH8fPaJ6mnmTYQ76SBhL2fY2uzD67L3Mxk with addrs: [/ip4/127.0.0.1/tcp/51612 /ip4/192.168.86.108/tcp/51612 /ip6/::1/tcp/51614]. isInitator=false
   2.6196s    MESSAGE << instance   0 >> initiating transfer to 12D3KooWPEPucYxaHsCH8fPaJ6mnmTYQ76SBhL2fY2uzD67L3Mxk
   2.6260s    MESSAGE << instance   1 >> new stream from 12D3KooWF48ukrFNntx5podedyYXf1WcuYPqdTTNYgCJNMZ4PDpk
   2.6262s      ERROR << instance   1 >> 2020-01-28T12:56:02.691-0500	ERROR	noise	go-libp2p-noise@v0.0.0-20200120141346-1a9c5941b6c7/protocol.go:332	write length errwrite tcp4 192.168.86.108:51612->192.168.86.108:51611: write: broken pipe
   2.6263s      ERROR << instance   1 >> github.com/libp2p/go-libp2p-noise.(*secureSession).Write.func1
   2.6263s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-libp2p-noise@v0.0.0-20200120141346-1a9c5941b6c7/protocol.go:332
   2.6263s      ERROR << instance   1 >> github.com/libp2p/go-libp2p-noise.(*secureSession).Write
   2.6263s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-libp2p-noise@v0.0.0-20200120141346-1a9c5941b6c7/protocol.go:347
   2.6263s      ERROR << instance   1 >> bufio.(*Writer).Flush
   2.6263s      ERROR << instance   1 >> 	/usr/local/go/src/bufio/bufio.go:593
   2.6263s      ERROR << instance   1 >> github.com/multiformats/go-multistream.delimWriteBuffered
   2.6263s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/multiformats/go-multistream@v0.1.0/multistream.go:72
   2.6264s      ERROR << instance   1 >> github.com/multiformats/go-multistream.(*MultistreamMuxer).Negotiate
   2.6264s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/multiformats/go-multistream@v0.1.0/multistream.go:283
   2.6264s      ERROR << instance   1 >> github.com/libp2p/go-stream-muxer-multistream.(*Transport).NewConn
   2.6265s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-stream-muxer-multistream@v0.2.0/multistream.go:50
   2.6265s      ERROR << instance   1 >> github.com/libp2p/go-libp2p-transport-upgrader.(*Upgrader).setupMuxer.func1
   2.6265s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-libp2p-transport-upgrader@v0.1.1/upgrader.go:119
   2.6265s      ERROR << instance   1 >> 2020-01-28T12:56:02.692-0500	ERROR	noise	go-libp2p-noise@v0.0.0-20200120141346-1a9c5941b6c7/protocol.go:332	write length errwrite tcp4 127.0.0.1:51612->127.0.0.1:51611: write: broken pipe
   2.6265s      ERROR << instance   1 >> github.com/libp2p/go-libp2p-noise.(*secureSession).Write.func1
   2.6265s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-libp2p-noise@v0.0.0-20200120141346-1a9c5941b6c7/protocol.go:332
   2.6272s      ERROR << instance   1 >> github.com/libp2p/go-libp2p-noise.(*secureSession).Write
   2.6273s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-libp2p-noise@v0.0.0-20200120141346-1a9c5941b6c7/protocol.go:347
   2.6273s      ERROR << instance   1 >> bufio.(*Writer).Flush
   2.6273s      ERROR << instance   1 >> 	/usr/local/go/src/bufio/bufio.go:593
   2.6273s      ERROR << instance   1 >> github.com/multiformats/go-multistream.delimWriteBuffered
   2.6273s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/multiformats/go-multistream@v0.1.0/multistream.go:72
   2.6273s      ERROR << instance   1 >> github.com/multiformats/go-multistream.(*MultistreamMuxer).Negotiate
   2.6273s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/multiformats/go-multistream@v0.1.0/multistream.go:283
   2.6273s      ERROR << instance   1 >> github.com/libp2p/go-stream-muxer-multistream.(*Transport).NewConn
   2.6273s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-stream-muxer-multistream@v0.2.0/multistream.go:50
   2.6274s      ERROR << instance   1 >> github.com/libp2p/go-libp2p-transport-upgrader.(*Upgrader).setupMuxer.func1
   2.6274s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-libp2p-transport-upgrader@v0.1.1/upgrader.go:119

What's odd is that the tests were still completing, so I tried using blankhost to eliminate the possibility that a background stream was getting terminated. The errors are still present with blankhost though, and I discovered that with a large enough payload size (~ 100kb) it will reliably fail the test as well.

log from failed test run 
Jan 28 18:00:35.340171	INFO	starting test case instance	{"testcase": "secure-channel", "runenv": ["TEST_PLAN=secure-channel", "TEST_CASE=transfer", "TEST_TAG=", "TEST_RUN=4774d3b7-60c9-4880-9aa0-b56e6f81a961", "TEST_SUBNET=127.1.0.0/16", "TEST_CASE_SEQ=0", "TEST_INSTANCE_COUNT=2", "TEST_SIDECAR=false", "TEST_BRANCH=", "TEST_REPO=", "TEST_INSTANCE_ROLE=", "TEST_INSTANCE_PARAMS=payload_size=100000|secure_channel=noise|timeout_secs=60"]}
Jan 28 18:00:35.342841	INFO	starting test case instance	{"testcase": "secure-channel", "runenv": ["TEST_PLAN=secure-channel", "TEST_CASE=transfer", "TEST_TAG=", "TEST_RUN=4774d3b7-60c9-4880-9aa0-b56e6f81a961", "TEST_SUBNET=127.1.0.0/16", "TEST_CASE_SEQ=0", "TEST_INSTANCE_COUNT=2", "TEST_SIDECAR=false", "TEST_BRANCH=", "TEST_REPO=", "TEST_INSTANCE_ROLE=", "TEST_INSTANCE_PARAMS=payload_size=100000|secure_channel=noise|timeout_secs=60"]}
   0.1886s    MESSAGE << instance   1 >> I am 12D3KooWQUZQNZSDexbCH9F8vjE1Am24fSDP4y68gw6WjE4FwbzN with addrs: [/ip4/127.0.0.1/tcp/51785 /ip4/192.168.86.108/tcp/51785 /ip6/::1/tcp/51788]. isInitator=true
   0.1886s    MESSAGE << instance   0 >> I am 12D3KooWK4oSdiUEZSXaGeDeXnybxNMGvxyH6JjxASjXsRLH1UUu with addrs: [/ip4/127.0.0.1/tcp/51786 /ip4/192.168.86.108/tcp/51786 /ip6/::1/tcp/51787]. isInitator=false
   2.3992s    MESSAGE << instance   1 >> initiating transfer to 12D3KooWK4oSdiUEZSXaGeDeXnybxNMGvxyH6JjxASjXsRLH1UUu
   2.4052s    MESSAGE << instance   0 >> new stream from 12D3KooWQUZQNZSDexbCH9F8vjE1Am24fSDP4y68gw6WjE4FwbzN
   2.4061s      ERROR << instance   0 >> 2020-01-28T13:00:37.745-0500	ERROR	noise	go-libp2p-noise@v0.0.0-20200120141346-1a9c5941b6c7/protocol.go:332	write length errwrite tcp4 192.168.86.108:51786->192.168.86.108:51785: write: broken pipe
   2.4062s      ERROR << instance   0 >> github.com/libp2p/go-libp2p-noise.(*secureSession).Write.func1
   2.4060s     METRIC << instance   1 >> {"name":"write_time","unit":"ns","improve_dir":-1,"value":590689}
   2.4062s      ERROR << instance   0 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-libp2p-noise@v0.0.0-20200120141346-1a9c5941b6c7/protocol.go:332
   2.4061s     METRIC << instance   1 >> {"name":"write_time","unit":"ns","improve_dir":-1,"value":590689}
   2.4063s      ERROR << instance   0 >> github.com/libp2p/go-libp2p-noise.(*secureSession).Write
   2.4063s      ERROR << instance   0 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-libp2p-noise@v0.0.0-20200120141346-1a9c5941b6c7/protocol.go:347
   2.4061s     METRIC << instance   1 >> {"name":"write_time","unit":"ns","improve_dir":-1,"value":590689}
   2.4063s      ERROR << instance   0 >> bufio.(*Writer).Flush
   2.4064s      ERROR << instance   0 >> 	/usr/local/go/src/bufio/bufio.go:593
   2.4064s      ERROR << instance   0 >> github.com/multiformats/go-multistream.delimWriteBuffered
   2.4064s      ERROR << instance   0 >> 	/Users/yusef/go/pkg/mod/github.com/multiformats/go-multistream@v0.1.0/multistream.go:72
   2.4064s      ERROR << instance   0 >> github.com/multiformats/go-multistream.(*MultistreamMuxer).Negotiate
   2.4064s      ERROR << instance   0 >> 	/Users/yusef/go/pkg/mod/github.com/multiformats/go-multistream@v0.1.0/multistream.go:283
   2.4064s      ERROR << instance   0 >> github.com/libp2p/go-stream-muxer-multistream.(*Transport).NewConn
   2.4064s      ERROR << instance   0 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-stream-muxer-multistream@v0.2.0/multistream.go:50
   2.4064s      ERROR << instance   0 >> github.com/libp2p/go-libp2p-transport-upgrader.(*Upgrader).setupMuxer.func1
   2.4064s      ERROR << instance   0 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-libp2p-transport-upgrader@v0.1.1/upgrader.go:119
   2.4065s      ERROR << instance   0 >> 2020-01-28T13:00:37.745-0500	ERROR	noise	go-libp2p-noise@v0.0.0-20200120141346-1a9c5941b6c7/protocol.go:332	write length errwrite tcp6 [::1]:51787->[::1]:51788: write: broken pipe
   2.4065s      ERROR << instance   0 >> github.com/libp2p/go-libp2p-noise.(*secureSession).Write.func1
   2.4066s      ERROR << instance   0 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-libp2p-noise@v0.0.0-20200120141346-1a9c5941b6c7/protocol.go:332
   2.4066s      ERROR << instance   0 >> github.com/libp2p/go-libp2p-noise.(*secureSession).Write
   2.4066s      ERROR << instance   0 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-libp2p-noise@v0.0.0-20200120141346-1a9c5941b6c7/protocol.go:347
   2.4066s      ERROR << instance   0 >> bufio.(*Writer).Flush
   2.4066s     METRIC << instance   0 >> {"name":"read_time","unit":"ns","improve_dir":-1,"value":1258452}
   2.4067s      ERROR << instance   0 >> 	/usr/local/go/src/bufio/bufio.go:593
   2.4067s      ERROR << instance   0 >> github.com/multiformats/go-multistream.delimWriteBuffered
   2.4067s      ERROR << instance   0 >> 	/Users/yusef/go/pkg/mod/github.com/multiformats/go-multistream@v0.1.0/multistream.go:72
   2.4067s      ERROR << instance   0 >> github.com/multiformats/go-multistream.(*MultistreamMuxer).Negotiate
   2.4067s      ERROR << instance   0 >> 	/Users/yusef/go/pkg/mod/github.com/multiformats/go-multistream@v0.1.0/multistream.go:283
   2.4068s      ERROR << instance   0 >> github.com/libp2p/go-stream-muxer-multistream.(*Transport).NewConn
   2.4068s      ERROR << instance   0 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-stream-muxer-multistream@v0.2.0/multistream.go:50
   2.4068s      ERROR << instance   0 >> github.com/libp2p/go-libp2p-transport-upgrader.(*Upgrader).setupMuxer.func1
   2.4067s     METRIC << instance   0 >> {"name":"read_time","unit":"ns","improve_dir":-1,"value":1258452}
   2.4069s      ERROR << instance   0 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-libp2p-transport-upgrader@v0.1.1/upgrader.go:119
   2.4067s     METRIC << instance   0 >> {"name":"read_time","unit":"ns","improve_dir":-1,"value":1258452}
   2.4067s     METRIC << instance   0 >> {"name":"read_time","unit":"ns","improve_dir":-1,"value":1258452}
   2.4071s     METRIC << instance   1 >> {"name":"write_time","unit":"ns","improve_dir":-1,"value":590689}
   2.4078s     METRIC << instance   0 >> {"name":"write_time","unit":"ns","improve_dir":-1,"value":488164}
   2.4079s     METRIC << instance   0 >> {"name":"write_time","unit":"ns","improve_dir":-1,"value":488164}
   2.4079s     METRIC << instance   0 >> {"name":"write_time","unit":"ns","improve_dir":-1,"value":488164}
   2.4082s      ERROR << instance   1 >> 2020-01-28T13:00:37.747-0500	ERROR	noise	go-libp2p-noise@v0.0.0-20200120141346-1a9c5941b6c7/protocol.go:266	decrypt errdecrypt err: could not decrypt
   2.4082s      ERROR << instance   1 >> github.com/libp2p/go-libp2p-noise.(*secureSession).Read.func1
   2.4083s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-libp2p-noise@v0.0.0-20200120141346-1a9c5941b6c7/protocol.go:266
   2.4083s      ERROR << instance   1 >> github.com/libp2p/go-libp2p-noise.(*secureSession).Read
   2.4083s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-libp2p-noise@v0.0.0-20200120141346-1a9c5941b6c7/protocol.go:285
   2.4083s      ERROR << instance   1 >> bufio.(*Reader).fill
   2.4083s      ERROR << instance   1 >> 	/usr/local/go/src/bufio/bufio.go:100
   2.4084s      ERROR << instance   1 >> bufio.(*Reader).ReadByte
   2.4084s      ERROR << instance   1 >> 	/usr/local/go/src/bufio/bufio.go:252
   2.4084s      ERROR << instance   1 >> encoding/binary.ReadUvarint
   2.4084s      ERROR << instance   1 >> 	/usr/local/go/src/encoding/binary/varint.go:110
   2.4084s      ERROR << instance   1 >> github.com/libp2p/go-mplex.(*Multiplex).readNextHeader
   2.4084s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-mplex@v0.1.0/multiplex.go:548
   2.4084s      ERROR << instance   1 >> github.com/libp2p/go-mplex.(*Multiplex).handleIncoming
   2.4084s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-mplex@v0.1.0/multiplex.go:367
   2.4104s      ERROR << instance   1 >> panic: error reading from remote stream: stream reset
   2.4104s      ERROR << instance   1 >>
   2.4104s      ERROR << instance   1 >> goroutine 100 [running]:
   2.4104s      ERROR << instance   1 >> github.com/ipfs/testground/plans/secure-channel/test.(*node).handleStream(0xc00030a3f0, 0x189d0a0, 0xc0004080a0)
   2.4104s      ERROR << instance   1 >> 	/private/var/folders/46/vkrbjbk56hlfwtpfjb74041r0000gn/T/secure-channel631824199/plan/test/transfer.go:149 +0x607
   2.4104s      ERROR << instance   1 >> github.com/libp2p/go-libp2p-blankhost.(*BlankHost).SetStreamHandler.func1(0xc000488030, 0x23, 0x59641b8, 0xc0004080a0, 0x0, 0x0)
   2.4104s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-libp2p-blankhost@v0.1.4/blank.go:125 +0x9d
   2.4104s      ERROR << instance   1 >> created by github.com/libp2p/go-libp2p-blankhost.(*BlankHost).newStreamHandler
   2.4105s      ERROR << instance   1 >> 	/Users/yusef/go/pkg/mod/github.com/libp2p/go-libp2p-blankhost@v0.1.4/blank.go:156 +0x20c
   2.4071s INCOMPLETE << instance   1 >>

This seems like an actual bug in Noise, so now I'm investigating and trying to reproduce in an integration test outside of testground.

@raulk raulk mentioned this pull request Jan 29, 2020
Closed
@yusefnapora yusefnapora mentioned this pull request Jan 29, 2020
Closed
@yusefnapora
Copy link
Copy Markdown
Contributor Author

yusefnapora commented Jan 29, 2020

I think that there are two separate issues related to the errors in the above comment.

The stream reset / decryption errors from the failed test run I believe were caused by libp2p/go-libp2p-noise#37 and fixed in libp2p/go-libp2p-noise#38.

I can now send any amount of data and complete the test.

I'm still seeing "broken pipe" errors, but I believe I've figured out the cause of those as well. The pipe is actually being broken, because the initiator was making multiple connection attempts to the responder and killing one of them once the other succeeds. If I change the code that adds remote peer addrs to the peerstore and only add a single address, the broken pipe errors go away.

@yusefnapora yusefnapora mentioned this pull request Jun 15, 2020
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

No reviews

Assignees

@yusefnapora yusefnapora

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

2 participants

@yusefnapora @Robmat05