TestHandshake fails occasionally

[btc]

=== RUN TestHandshake
fatal error: all goroutines are asleep - deadlock!
goroutine 16 [chan receive]:
testing.RunTests(0x69de80, 0x76a710, 0x1, 0x1, 0x1)
    /home/travis/.gvm/gos/go1.3.1/src/pkg/testing/testing.go:505 +0x923
testing.Main(0x69de80, 0x76a710, 0x1, 0x1, 0x7780a0, 0x0, 0x0, 0x7780a0, 0x0, 0x0)
    /home/travis/.gvm/gos/go1.3.1/src/pkg/testing/testing.go:435 +0x84
main.main()
    github.com/jbenet/go-ipfs/identify/_test/_testmain.go:47 +0x9c
goroutine 19 [finalizer wait]:
runtime.park(0x413090, 0x7739f0, 0x7724e9)
    /home/travis/.gvm/gos/go1.3.1/src/pkg/runtime/proc.c:1369 +0x89
runtime.parkunlock(0x7739f0, 0x7724e9)
    /home/travis/.gvm/gos/go1.3.1/src/pkg/runtime/proc.c:1385 +0x3b
runfinq()
    /home/travis/.gvm/gos/go1.3.1/src/pkg/runtime/mgc0.c:2644 +0xcf
runtime.goexit()
    /home/travis/.gvm/gos/go1.3.1/src/pkg/runtime/proc.c:1445
goroutine 20 [chan receive]:
github.com/jbenet/go-ipfs/identify.Handshake(0xc208086380, 0xc20802d490, 0xc20802a0d0, 0xc20802a000, 0x30, 0x0, 0x0, 0x0)
    /home/travis/gopath/src/github.com/jbenet/go-ipfs/identify/identify.go:157 +0x159f
github.com/jbenet/go-ipfs/identify.TestHandshake(0xc2080501b0)
    /home/travis/gopath/src/github.com/jbenet/go-ipfs/identify/identify_test.go:50 +0x6f1
testing.tRunner(0xc2080501b0, 0x76a710)
    /home/travis/.gvm/gos/go1.3.1/src/pkg/testing/testing.go:422 +0x8b
created by testing.RunTests
    /home/travis/.gvm/gos/go1.3.1/src/pkg/testing/testing.go:504 +0x8db
goroutine 22 [chan receive]:
github.com/jbenet/go-ipfs/identify.secureInProxy(0xc20802a0d0, 0xc20807e720, 0x64e230, 0x6, 0xc208066870, 0x10, 0x44, 0xc208066880, 0x20, 0x34, ...)
    /home/travis/gopath/src/github.com/jbenet/go-ipfs/identify/identify.go:186 +0x168
created by github.com/jbenet/go-ipfs/identify.Handshake
    /home/travis/gopath/src/github.com/jbenet/go-ipfs/identify/identify.go:151 +0x1402
goroutine 23 [chan receive]:
github.com/jbenet/go-ipfs/identify.secureOutProxy(0xc20802a000, 0xc20807e780, 0x64e230, 0x6, 0xc208066820, 0x10, 0x44, 0xc208066830, 0x20, 0x34, ...)
    /home/travis/gopath/src/github.com/jbenet/go-ipfs/identify/identify.go:221 +0x16b
created by github.com/jbenet/go-ipfs/identify.Handshake
    /home/travis/gopath/src/github.com/jbenet/go-ipfs/identify/identify.go:152 +0x14b9
FAIL    github.com/jbenet/go-ipfs/identify  0.112s

[whyrusleeping]

Im glad im not crazy, i ran into this once. Havent been able to get a repro since.

[btc]

I'll continue to report test failures as I discover them. I hope that collecting them will help

ps. To help with investigation, I'll also make sure to include the commit hash of the code that failed.

[btc]

This one is

6f82f7b

https://travis-ci.org/jbenet/go-ipfs/jobs/35159633

[whyrusleeping]

Yeah, there's another random error I get "malformed public key" every so often.

[whyrusleeping]

This deadlock is weird. There should be two goroutines in the Handshake method (and two sets of secure I/O). Im only seeing one... One must have somehow failed, but didnt end up causing a t.Fatal to trigger. Im gonna throw some panics in and run the test until i can repro a failure.

[btc]

It was on feat/bitswap-internal-notifications at 6f82f7b

[whyrusleeping]

I was also able to reproduce it once after switching to master. 20 runs later, no luck with a repro

[btc]

Looks like deadlock occurs when:

• peer a's handshake fails silently, peer b signals finished (identify.go:156) and waits on secureIn for a response(identify.go:157)

I found some spots where errors are ignored. Adding error handling. Will open a PR.

[btc]

@jbenet Is there a spec for the handshake anywhere?