x/tools/go/pointer: crash in solver

[alandonovan]

$ go get -u google.golang.org/grpc # @7263089
$ go build golang.org/x/tools/cmd/callgraph # @ c1def51
$ ./callgraph -algo=pta -ptalog=/tmp/ptalog -test google.golang.org/grpc
Internal panic in pointer analysis:
...
golang.org/x/tools/go/pointer.(*analysis).callEdge(0xc005eee1c0, 0xc015995e00, 0xc01ab7b4e0, 0x7c2a)
        /usr/local/google/home/adonovan/got/src/golang.org/x/tools/go/pointer/analysis.go:368 +0x79b
golang.org/x/tools/go/pointer.Analyze(0xc00262ca00, 0x0, 0x739320, 0xc02970b1b0)
        /usr/local/google/home/adonovan/got/src/golang.org/x/tools/go/pointer/analysis.go:354 +0x6b2
main.doCallgraph(0x888c40, 0x7fff0845364c, 0x3, 0x70e307, 0x3f, 0xc000088001, 0xc0000a4130, 0x1, 0x1, 0x0, ...)
        /usr/local/google/home/adonovan/got/src/golang.org/x/tools/cmd/callgraph/main.go:233 +0x2b3
...
callgraph: internal error in pointer analysis: callEdge dynamic function call -> n31786: not a function object (please report this bug)

TODO: look through the 1.7GB log file and identify what's up with node n31786.

[ondrajz]

Not sure if this is the same issue, but comparing just stack traces it seems that the panic occurs somewhere else in the code. I'll put this here since it seems related either way.

Running callgraph -algo=pta -format graphviz github.com/lightningnetwork/lnd panics here:

Internal panic in pointer analysis:
goroutine 1 [running]:
runtime/debug.Stack(0x24, 0x0, 0x0)
	/usr/local/go/src/runtime/debug/stack.go:24 +0xa7
runtime/debug.PrintStack()
	/usr/local/go/src/runtime/debug/stack.go:16 +0x22
golang.org/x/tools/go/pointer.Analyze.func1(0xc47133dc48)
	/home/furby/go/src/golang.org/x/tools/go/pointer/analysis.go:227 +0x110
panic(0x68bce0, 0xc44fe99c80)
	/usr/local/go/src/runtime/panic.go:502 +0x229
golang.org/x/tools/go/pointer.(*analysis).taggedValue(0xc42ab28700, 0xc4000331aa, 0x1, 0x64, 0xc426000000)
	/home/furby/go/src/golang.org/x/tools/go/pointer/gen.go:272 +0x13a
golang.org/x/tools/go/pointer.(*untagConstraint).solve(0xc42ddf4640, 0xc42ab28700, 0xc426fb9cc0)
	/home/furby/go/src/golang.org/x/tools/go/pointer/solve.go:295 +0xd2
golang.org/x/tools/go/pointer.(*analysis).solveConstraints(0xc42ab28700, 0xc44a600090, 0xc426fb9cc0)
	/home/furby/go/src/golang.org/x/tools/go/pointer/solve.go:165 +0xa9
golang.org/x/tools/go/pointer.(*analysis).solve(0xc42ab28700)
	/home/furby/go/src/golang.org/x/tools/go/pointer/solve.go:59 +0x2fb
golang.org/x/tools/go/pointer.Analyze(0xc42ce4ca00, 0x0, 0x735380, 0xc44fe99ca0)
	/home/furby/go/src/golang.org/x/tools/go/pointer/analysis.go:331 +0x51d
main.doCallgraph(0x880be0, 0x7ffce4a89798, 0x3, 0x7ffce4a897a4, 0x8, 0x0, 0xc4200a4130, 0x1, 0x1, 0x0, ...)
	/home/furby/go/src/golang.org/x/tools/cmd/callgraph/main.go:233 +0x2cc
main.main()
	/home/furby/go/src/golang.org/x/tools/cmd/callgraph/main.go:161 +0x96
callgraph: internal error in pointer analysis: not a tagged object: n209322 (please report this bug)

Origin of the issue: ondrajz/go-callvis#24

[ondrajz]

@alandonovan I poked a little in callgraph analysis logs of the grpc package.. and I found narrowed down the cause of the panic: callEdge <site> -> n<calleeid>: not a function object.

I don't know much about how the analysis internally works in pointer package, but I tried to add some extra debugs here and there, until I saw something relevant..

analyze failed: internal error in pointer analysis: 
callEdge (dynamic function call) - cg729:(*google.golang.org/grpc.lbCacheClientConn).close -> n34467: not a function object (cg722:(*google.golang.org/grpc.lbCacheClientConn).RemoveSubConn)

This probably has something to do with this call in close() method of lbCacheClientConn:

func (ccc *lbCacheClientConn) close() {
	ccc.mu.Lock()
	// Only cancel all existing timers. There's no need to remove SubConns.
	for _, entry := range ccc.subConnCache {
		entry.cancel()	// <-- this call
	}
	ccc.mu.Unlock()
}

which is defined as a field (variable, not defined as func):

type subConnCacheEntry struct {
	sc balancer.SubConn

	cancel        func()	// <-- func as variable
	abortDeleting bool
}

I suspect that might cause the check to fail for some reason. Or perhaps it catches some rare case when the graph data is not calculated properly?

Here's more of the log output just before panic (not sure if it's gonna be helpful):

...
===
CALLER: cg722:(*google.golang.org/grpc.lbCacheClientConn).RemoveSubConn (shared contour) (*google.golang.org/grpc.lbCacheClientConn).RemoveSubConn
 ----> static method call [9398397] =  - (*sync.Mutex).Lock(t3) (*ssa.Function) - (*sync.Mutex).Lock(t3) 0
 ----> static method call [9398401] =  - (*sync.Mutex).Unlock(t6) (*ssa.Function) 
 ----> static function call [9398892] =  - time.AfterFunc(t38, t39) (*ssa.Function) - time.AfterFunc(t38, t39) 5
 ----> dynamic method call [9398770] =  - invoke t51.RemoveSubConn(t52) (*ssa.UnOp) - invoke t51.RemoveSubConn(t52) 6
  - CALLEE: cg15113:(*google.golang.org/grpc.ccBalancerWrapper).RemoveSubConn (func(sc google.golang.org/grpc/balancer.SubConn))
  - CALLEE: cg25434:(*google.golang.org/grpc.mockClientConn).RemoveSubConn (func(sc google.golang.org/grpc/balancer.SubConn))
  - CALLEE: cg33125:(*google.golang.org/grpc.ccBalancerWrapper).RemoveSubConn (func(sc google.golang.org/grpc/balancer.SubConn))
===
CALLER: cg725:(*google.golang.org/grpc.lbCacheClientConn).UpdateBalancerState (shared contour) (*google.golang.org/grpc.lbCacheClientConn).UpdateBalancerState
 ----> dynamic method call [9399697] =  - invoke t1.UpdateBalancerState(s, p) (*ssa.UnOp) - invoke t1.UpdateBalancerState(s, p) 0
  - CALLEE: cg15122:(*google.golang.org/grpc.ccBalancerWrapper).UpdateBalancerState (func(s google.golang.org/grpc/connectivity.State, p google.golang.org/grpc/balancer.Picker))
  - CALLEE: cg25443:(*google.golang.org/grpc.mockClientConn).UpdateBalancerState (func(s google.golang.org/grpc/connectivity.State, p google.golang.org/grpc/balancer.Picker))
  - CALLEE: cg33134:(*google.golang.org/grpc.ccBalancerWrapper).UpdateBalancerState (func(s google.golang.org/grpc/connectivity.State, p google.golang.org/grpc/balancer.Picker))
===
CALLER: cg729:(*google.golang.org/grpc.lbCacheClientConn).close (shared contour) (*google.golang.org/grpc.lbCacheClientConn).close
 ----> static method call [9399759] =  - (*sync.Mutex).Lock(t0) (*ssa.Function) - (*sync.Mutex).Lock(t0) 0
 ----> dynamic function call [9399891] =  - t9() (*ssa.UnOp) - t9() 2
  - CALLEE: cg722:(*google.golang.org/grpc.lbCacheClientConn).RemoveSubConn (struct{sc google.golang.org/grpc/balancer.SubConn; cancel func(); abortDeleting bool})
NODE /home/ondrej/go/pkg/mod/google.golang.org/grpc@v1.12.0/grpclb_util.go:155:31 - typ=struct{sc google.golang.org/grpc/balancer.SubConn; cancel func(); abortDeleting bool} sub=&{typ:0xc00cb819b0 op:<nil> tail:<nil>} solve=&{complex:[] copyTo:{Sparse:{root:{offset:9223372036854775807 bits:[0 0 0 0] next:0xc0218c1158 prev:0xc0218c1158}}} pts:{Sparse:{root:{offset:0 bits:[0 0 0 0] next:<nil> prev:<nil>}}} prevPTS:{Sparse:{root:{offset:9223372036854775807 bits:[0 0 0 0] next:0xc0218c11c8 prev:0xc0218c11c8}}}}
Internal panic in pointer analysis:
goroutine 1 [running]:
runtime/debug.Stack(0x24, 0x0, 0x0)
	/usr/local/go/src/runtime/debug/stack.go:24 +0x9d
runtime/debug.PrintStack()
	/usr/local/go/src/runtime/debug/stack.go:16 +0x22
golang.org/x/tools/go/pointer.Analyze.func1(0xc014279d88)
	/home/ondrej/go/src/github.com/TrueFurby/go-callvis/vendor/golang.org/x/tools/go/pointer/analysis.go:227 +0x157
panic(0x8da8e0, 0xc00067dc50)
	/usr/local/go/src/runtime/panic.go:522 +0x1b5
golang.org/x/tools/go/pointer.(*analysis).callEdge(0xc01efec700, 0xc01f230e40, 0xc0217f3640, 0x86a3)
	/home/ondrej/go/src/github.com/TrueFurby/go-callvis/vendor/golang.org/x/tools/go/pointer/analysis.go:382 +0xa1f
golang.org/x/tools/go/pointer.Analyze(0xc01f19a3c0, 0x0, 0xa4f760, 0xc00067dc60)
	/home/ondrej/go/src/github.com/TrueFurby/go-callvis/vendor/golang.org/x/tools/go/pointer/analysis.go:366 +0x797
main.doAnalysis(0xddf340, 0x1, 0xc0000ae060, 0x1, 0x1)
	/home/ondrej/go/src/github.com/TrueFurby/go-callvis/analysis.go:105 +0x4aa
main.main()
	/home/ondrej/go/src/github.com/TrueFurby/go-callvis/main.go:107 +0x15b
2019/04/22 02:38:44 analyze failed: internal error in pointer analysis: callEdge(9399891) [dynamic function call] cg729:(*google.golang.org/grpc.lbCacheClientConn).close -> n34467: not a function object (cg722:(*google.golang.org/grpc.lbCacheClientConn).RemoveSubConn) (please report this bug)

I'd be really glad if someone had time and looked at this. I want to prevent this from happening in go-callvis. And since grpc is pretty common dependency, it happens a lot: ondrajz/go-callvis#24

[ondrajz]

@alandonovan Is there any chance you or someone else willl have time to look into this? It still seems to occur..

[mr-ma]

I encountered this very bug; since this issue was opened on April 2018, I have the impression that is not a priority. @alandonovan is there any estimate as to when or if this problem will be fixed at all?

[scott-cotton]

@mr-ma Issue could be related to #45735, which is recently fixed.

[timothy-king]

Alan's example no longer reproduces for me with grpc @ c8482678 and callgraph @ bf6c7f2.

The one major change to the instructions I did was to run:
$ callgraph -algo=pta google.golang.org/grpc/...
As the original instructions complained about not finding a main package.

Not reproducing @ofabry's example on v0.13.0-beta of github.com/lightningnetwork/lnd. @ofabry can you confirm?

[adonovan]

x/tools/go/pointer was deleted; see #59676.