[next, master] HandleList.Track: Creates an int variable with no references in Go world, only C, causes panics because GC frees it.

[dmitshur]

As mentioned in #196 (comment), I've found a reproducible problem where HandleList.Track is called to track a Go pointer, but when HandleList.Get is later called to retrieve it, there will be a panic (unless Go's GC is turned off via GOGC=off environment variable).

I think this issue affects both master and next branches, but this failing test case uses next branch.

In HandleList.Track:

// Track adds the given pointer to the list of pointers to track and
// returns a pointer value which can be passed to C as an opaque
// pointer.
func (v *HandleList) Track(pointer interface{}) unsafe.Pointer {
    v.Lock()

    slot := v.findUnusedSlot()
    v.handles[slot] = pointer
    v.set[slot] = true

    v.Unlock()

    return unsafe.Pointer(&slot)
}

Note that the local variable slot, of type int, created with the value returned by v.findUnusedSlot(), is only used in the return statement by being taken an address of. That pointer goes into the C world only.

When the C world calls back into Go world, it calls HandleList.Get to try to retrieve the Go pointer stored by HandleList:

// Get retrieves the pointer from the given handle
func (v *HandleList) Get(handle unsafe.Pointer) interface{} {
    slot := *(*int)(handle)

    v.RLock()

    if _, ok := v.set[slot]; !ok {
        panic(fmt.Sprintf("invalid pointer handle: %p", handle))
    }

    ptr := v.handles[slot]

    v.RUnlock()

    return ptr
}

The problem is, by now, the Go GC has run and removed the original slot local variable, so trying to dereference the handle via slot := *(*int)(handle) ends up creating an incorrect value of slot.

I've added a bunch of print statements to git2go and here's the stack trace during the fail case. Note when Track(handle) is called, slot value was 1, but when it's reconstructed by dereferencing a pointer in Get(handle), despite all pointers being the same, the result slot is 0, not 1, causing a panic:

$ git status
On branch update-git2go-api
Your branch is up-to-date with 'origin/update-git2go-api'.
nothing to commit, working directory clean
$ go test -run=TestRepository_Clone_ssh sourcegraph.com/sourcegraph/go-vcs/vcs
2015/07/06 19:07:18 0xc20805a100.Track(handle): 0xc20802af18 [slot: 1]
2015/07/06 19:07:18 populateRemoteCallbacks: ptr.payload: 0xc20802af18
2015/07/06 19:07:18 certificateCheckCallback: data: 0xc20802af18
2015/07/06 19:07:18 0xc20805a100.Get(handle): 0xc20802af18 [slot: 0]
--- FAIL: TestRepository_Clone_ssh (0.31s)
    ssh_test.go:74: Cloning from ssh://go-vcs@127.0.0.1:55020/git817689297 to /var/folders/_w/3kl_g4rn5sv1nyjblk7tf4h00000gn/T/go-vcs-test/ssh-clone177029419
panic: invalid pointer handle: 0xc20802af18 [recovered]
    panic: invalid pointer handle: 0xc20802af18

goroutine 5 [running]:
testing.func·006()
    /usr/local/go/src/testing/testing.go:441 +0x181
github.com/libgit2/git2go.(*HandleList).Get(0xc20805a100, 0xc20802af18, 0x0, 0x0)
    /Users/Dmitri/go/src/github.com/libgit2/git2go/handles.go:97 +0x2f8
github.com/libgit2/git2go.certificateCheckCallback(0x7fff5fbfe460, 0x0, 0x4f128f0, 0xc20802af18, 0x4f12510)
    /Users/Dmitri/go/src/github.com/libgit2/git2go/remote.go:244 +0x101
github.com/libgit2/git2go._Cfunc_git_clone(0xc20809b930, 0x6000480, 0x60004b0, 0x6000500, 0xc200000000)
    /Users/Dmitri/go/src/github.com/libgit2/git2go/:663 +0x43
github.com/libgit2/git2go.Clone(0xc20803d080, 0x29, 0xc208075310, 0x4f, 0xc208051f00, 0x0, 0x0, 0x0)
    /Users/Dmitri/go/src/github.com/libgit2/git2go/clone.go:41 +0x1a3
sourcegraph.com/sourcegraph/go-vcs/vcs/git.Clone(0xc20803d080, 0x29, 0xc208075310, 0x4f, 0x1, 0xc208051e80, 0x0, 0x0, 0x0, 0x0)
    /Users/Dmitri/go/src/sourcegraph.com/sourcegraph/go-vcs/vcs/git/clone_update.go:61 +0x265
sourcegraph.com/sourcegraph/go-vcs/vcs_test.func·026(0xc20803d080, 0x29, 0xc208075310, 0x4f, 0x1, 0xc208051e80, 0x0, 0x0, 0x0, 0x0)
    /Users/Dmitri/go/src/sourcegraph.com/sourcegraph/go-vcs/vcs/ssh_test.go:52 +0x87
sourcegraph.com/sourcegraph/go-vcs/vcs_test.func·028()
    /Users/Dmitri/go/src/sourcegraph.com/sourcegraph/go-vcs/vcs/ssh_test.go:75 +0x3d7
sourcegraph.com/sourcegraph/go-vcs/vcs_test.TestRepository_Clone_ssh(0xc20808e000)
    /Users/Dmitri/go/src/sourcegraph.com/sourcegraph/go-vcs/vcs/ssh_test.go:101 +0x3e0
testing.tRunner(0xc20808e000, 0x4726700)
    /usr/local/go/src/testing/testing.go:447 +0xbf
created by testing.RunTests
    /usr/local/go/src/testing/testing.go:555 +0xa8b

goroutine 1 [chan receive]:
testing.RunTests(0x45d3aa0, 0x4726460, 0x1e, 0x1e, 0x473fc01)
    /usr/local/go/src/testing/testing.go:576 +0x58e
testing.(*M).Run(0xc20803a0f0, 0x47470c0)
    /usr/local/go/src/testing/testing.go:485 +0x6c
main.main()
    sourcegraph.com/sourcegraph/go-vcs/vcs/_test/_testmain.go:136 +0x1d5

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:2232 +0x1

goroutine 6 [chan receive]:
testing.func·007()
    /usr/local/go/src/testing/testing.go:559 +0x5f
created by testing.RunTests
    /usr/local/go/src/testing/testing.go:560 +0xb9b

goroutine 15 [runnable]:
net.(*pollDesc).Wait(0xc2080b9950, 0x72, 0x0, 0x0)
    /usr/local/go/src/net/fd_poll_runtime.go:84 +0x47
net.(*pollDesc).WaitRead(0xc2080b9950, 0x0, 0x0)
    /usr/local/go/src/net/fd_poll_runtime.go:89 +0x43
net.(*netFD).accept(0xc2080b98f0, 0x0, 0x4d28b20, 0xc20802b040)
    /usr/local/go/src/net/fd_unix.go:419 +0x40b
net.(*TCPListener).AcceptTCP(0xc208038038, 0xc208018728, 0x0, 0x0)
    /usr/local/go/src/net/tcpsock_posix.go:234 +0x4e
net.(*TCPListener).Accept(0xc208038038, 0x0, 0x0, 0x0, 0x0)
    /usr/local/go/src/net/tcpsock_posix.go:244 +0x4c
sourcegraph.com/sourcegraph/go-vcs/vcs/ssh.func·004()
    /Users/Dmitri/go/src/sourcegraph.com/sourcegraph/go-vcs/vcs/ssh/server.go:101 +0x43
created by sourcegraph.com/sourcegraph/go-vcs/vcs/ssh.(*Server).Start
    /Users/Dmitri/go/src/sourcegraph.com/sourcegraph/go-vcs/vcs/ssh/server.go:114 +0x32e

goroutine 16 [chan receive]:
golang.org/x/crypto/ssh.(*connection).serverAuthenticate(0xc20805c900, 0xc208088370, 0x11, 0x0, 0x0)
    /Users/Dmitri/go/src/golang.org/x/crypto/ssh/server.go:274 +0x139
golang.org/x/crypto/ssh.(*connection).serverHandshake(0xc20805c900, 0xc208088370, 0xc208038088, 0x0, 0x0)
    /Users/Dmitri/go/src/golang.org/x/crypto/ssh/server.go:221 +0xc22
golang.org/x/crypto/ssh.NewServerConn(0x4d2bcf8, 0xc208038088, 0xc208080120, 0x0, 0x0, 0x0, 0x0, 0x0)
    /Users/Dmitri/go/src/golang.org/x/crypto/ssh/server.go:146 +0x103
sourcegraph.com/sourcegraph/go-vcs/vcs/ssh.(*Server).handleConn(0xc208080100, 0x4d2bcf8, 0xc208038088)
    /Users/Dmitri/go/src/sourcegraph.com/sourcegraph/go-vcs/vcs/ssh/server.go:124 +0x94
created by sourcegraph.com/sourcegraph/go-vcs/vcs/ssh.func·004
    /Users/Dmitri/go/src/sourcegraph.com/sourcegraph/go-vcs/vcs/ssh/server.go:112 +0x1ea

goroutine 18 [IO wait]:
net.(*pollDesc).Wait(0xc2080b8840, 0x72, 0x0, 0x0)
    /usr/local/go/src/net/fd_poll_runtime.go:84 +0x47
net.(*pollDesc).WaitRead(0xc2080b8840, 0x0, 0x0)
    /usr/local/go/src/net/fd_poll_runtime.go:89 +0x43
net.(*netFD).Read(0xc2080b87e0, 0xc20800f000, 0x1000, 0x1000, 0x0, 0x4d28b20, 0xc20802a9c8)
    /usr/local/go/src/net/fd_unix.go:242 +0x40f
net.(*conn).Read(0xc208038088, 0xc20800f000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/local/go/src/net/net.go:121 +0xdc
bufio.(*Reader).fill(0xc208084600)
    /usr/local/go/src/bufio/bufio.go:97 +0x1ce
bufio.(*Reader).Read(0xc208084600, 0xc20805c220, 0x5, 0x5, 0xc2080b8150, 0x0, 0x0)
    /usr/local/go/src/bufio/bufio.go:174 +0x26c
io.ReadAtLeast(0x4d2bf08, 0xc208084600, 0xc20805c220, 0x5, 0x5, 0x5, 0x0, 0x0, 0x0)
    /usr/local/go/src/io/io.go:298 +0xf1
io.ReadFull(0x4d2bf08, 0xc208084600, 0xc20805c220, 0x5, 0x5, 0x14, 0x0, 0x0)
    /usr/local/go/src/io/io.go:316 +0x6d
golang.org/x/crypto/ssh.(*streamPacketCipher).readPacket(0xc20805c200, 0xc200000004, 0x4d2bf08, 0xc208084600, 0x0, 0x0, 0x0, 0x0, 0x0)
    /Users/Dmitri/go/src/golang.org/x/crypto/ssh/cipher.go:142 +0xd4
golang.org/x/crypto/ssh.(*connectionState).readPacket(0xc208001e60, 0xc208084600, 0x0, 0x0, 0x0, 0x0, 0x0)
    /Users/Dmitri/go/src/golang.org/x/crypto/ssh/transport.go:111 +0xe1
golang.org/x/crypto/ssh.(*transport).readPacket(0xc208001e60, 0x0, 0x0, 0x0, 0x0, 0x0)
    /Users/Dmitri/go/src/golang.org/x/crypto/ssh/transport.go:107 +0x68
golang.org/x/crypto/ssh.(*handshakeTransport).readOnePacket(0xc2080ba000, 0x0, 0x0, 0x0, 0x0, 0x0)
    /Users/Dmitri/go/src/golang.org/x/crypto/ssh/handshake.go:153 +0x101
golang.org/x/crypto/ssh.(*handshakeTransport).readLoop(0xc2080ba000)
    /Users/Dmitri/go/src/golang.org/x/crypto/ssh/handshake.go:133 +0x28
created by golang.org/x/crypto/ssh.newServerTransport
    /Users/Dmitri/go/src/golang.org/x/crypto/ssh/handshake.go:108 +0xea
FAIL    sourcegraph.com/sourcegraph/go-vcs/vcs  0.377s

Note that the issue disappears if you turn off the GC:

vcs $ GOGC=off go test -run=TestRepository_Clone_ssh sourcegraph.com/sourcegraph/go-vcs/vcs
ok      sourcegraph.com/sourcegraph/go-vcs/vcs  0.666s

To reproduce it (without the added prints, of course), do:

go get -u sourcegraph.com/sourcegraph/go-vcs/vcs

Then check out its update-git2go-api branch. Also install git2go on its next branch. And run the go test command as shown above.

[dmitshur]

I should add, the above issue can be reproduced with go1.4.2, but as I just learned, it does not occur with go1.5beta1.

That doesn't mean it's not an issue in Go 1.5, just that it doesn't happen in the above small test case. It would still potentially happen for larger test cases if the GC happens to trigger. So you need go1.4.2 to reproduce it with the above steps.

[dmitshur]

#219 has been merged and this issue is resolved on next branch.

However, as far as I know, this issue affects master too and is still unresolved there.

@carlosmn, do you want to backport the fix of #219 to master branch as well? That would resolve this issue fully.

[dmitshur]

@carlosmn, do you want to backport the fix of #219 to master branch as well? That would resolve this issue fully.

I've done that, see PR #231.