Data Race in TestServerRoughDisconnect

[eikenb]

I can reproduce this "reliably" by running just that test in a while loop, sometimes it takes a couple dozen runs but it always happens. The traceback is below.

I've been looking at this all evening and while at first I thought it was a problem with the test I'm thinking more now that it is an actual bug. It is a race between the io.Copy in the test and the connection being closed by a defer'd call in conn.recv().

=== RUN TestServerRoughDisconnect

WARNING: DATA RACE
Read at 0x00c4200c98c0 by goroutine 6:
os.(*File).write()
/home/jae/projects/go/goroot/src/os/file_unix.go:249 +0x8a
os.(*File).Write()
/home/jae/projects/go/goroot/src/os/file.go:142 +0x6f
os/exec.(*closeOnce).Write()
:42 +0x81
github.com/pkg/sftp.(*conn).Write()
:3 +0x8b
github.com/pkg/sftp.sendPacket()
/home/jae/projects/go/golib/src/github.com/pkg/sftp/packet.go:130 +0x230
github.com/pkg/sftp.(*conn).sendPacket()
/home/jae/projects/go/golib/src/github.com/pkg/sftp/conn.go:26 +0xad
github.com/pkg/sftp.(*clientConn).dispatchRequest()
/home/jae/projects/go/golib/src/github.com/pkg/sftp/conn.go:96 +0x12b
github.com/pkg/sftp.(*File).WriteTo.func1()
/home/jae/projects/go/golib/src/github.com/pkg/sftp/client.go:774 +0x186
github.com/pkg/sftp.(*File).WriteTo()
/home/jae/projects/go/golib/src/github.com/pkg/sftp/client.go:783 +0x3a3
io.copyBuffer()
/home/jae/projects/go/goroot/src/io/io.go:380 +0x43f
io.Copy()
/home/jae/projects/go/goroot/src/io/io.go:360 +0x7e
github.com/pkg/sftp.TestServerRoughDisconnect()
/home/jae/projects/go/golib/src/github.com/pkg/sftp/client_integration_test.go:1352 +0x1fc
testing.tRunner()
/home/jae/projects/go/goroot/src/testing/testing.go:610 +0xc9

Previous write at 0x00c4200c98c0 by goroutine 7:
os.(*file).close()
/home/jae/projects/go/goroot/src/os/file_unix.go:143 +0x124
os.(*File).Close()
/home/jae/projects/go/goroot/src/os/file_unix.go:132 +0x55
os/exec.(*closeOnce).close()
/home/jae/projects/go/goroot/src/os/exec/exec.go:535 +0x50
os/exec.(*closeOnce).(os/exec.close)-fm()
/home/jae/projects/go/goroot/src/os/exec/exec.go:530 +0x41
sync.(*Once).Do()
/home/jae/projects/go/goroot/src/sync/once.go:44 +0xf2
os/exec.(*closeOnce).Close()
/home/jae/projects/go/goroot/src/os/exec/exec.go:530 +0x79
github.com/pkg/sftp.(*clientConn).recv()
/home/jae/projects/go/golib/src/github.com/pkg/sftp/conn.go:57 +0x3dd
github.com/pkg/sftp.(*clientConn).loop()
/home/jae/projects/go/golib/src/github.com/pkg/sftp/conn.go:44 +0x68

Goroutine 6 (running) created at:
testing.(*T).Run()
/home/jae/projects/go/goroot/src/testing/testing.go:646 +0x52f
testing.RunTests.func1()
/home/jae/projects/go/goroot/src/testing/testing.go:793 +0xb9
testing.tRunner()
/home/jae/projects/go/goroot/src/testing/testing.go:610 +0xc9
testing.RunTests()
/home/jae/projects/go/goroot/src/testing/testing.go:799 +0x4ba
testing.(*M).Run()
/home/jae/projects/go/goroot/src/testing/testing.go:743 +0x12f
main.main()
github.com/pkg/sftp/_test/_testmain.go:234 +0x1b8

Goroutine 7 (running) created at:
github.com/pkg/sftp.NewClientPipe()
/home/jae/projects/go/golib/src/github.com/pkg/sftp/client.go:77 +0x345
github.com/pkg/sftp.testClient()
/home/jae/projects/go/golib/src/github.com/pkg/sftp/client_integration_test.go:182 +0x386
github.com/pkg/sftp.TestServerRoughDisconnect()
/home/jae/projects/go/golib/src/github.com/pkg/sftp/client_integration_test.go:1338 +0xd2
testing.tRunner()
/home/jae/projects/go/goroot/src/testing/testing.go:610 +0xc9

[eikenb]

My tentative fix for this is to change..

defer c.conn.Close()

to..

defer func() {
    c.Lock()
    c.conn.Close()
    c.Unlock()
}()

At the beginning of (*clientConn).recv() (in conn.go). The idea is to lock the connection during the Close call to prevent the race with read. But it annoys me as while I have a vague idea of what is going wrong I haven't been able to track down the corresponding lock that would prevent the read.

[eikenb]

NM. Found the corresponding lock. It is in (c *clientConn) dispatchRequest(), which you see in the first traceback in the race dump (the io.Copy operation). The fix is in the other traceback (in the close). So at least I have symmetry now. There is still a part of me that suspects that this might be an artifact of the testing setup, but at this point I'm ready to go with it. I'll leave this sit for a couple days in case anyone wants to chime in.

[eikenb]

Note that this came up while I was reviewing #152 for merging. It was failing all its travis tests at least partially due to this race.