`lsif-go --animation` hangs when listing dependencies on sourcegraph/sourcegraph

[chrismwendt]

• lsif-go commit: cde8136
• sourcegraph/sourcegraph commit: 2d7f5b9a014a81a33df5812ede6f5cfa368b49ee

Delve goroutines

(dlv) goroutines -t 1000
  Goroutine 1 - User: /Users/chrismwendt/github.com/sourcegraph/lsif-go/internal/output/output.go:71 github.com/sourcegraph/lsif-go/internal/output.WithProgressParallel.func2 (0x102dd842c) [select]
	 0  0x0000000102c54b3c in runtime.gopark
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	 1  0x0000000102c65aac in runtime.selectgo
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/select.go:327
	 2  0x0000000102dd842c in github.com/sourcegraph/lsif-go/internal/output.WithProgressParallel.func2
	     at /Users/chrismwendt/github.com/sourcegraph/lsif-go/internal/output/output.go:71
	 3  0x0000000102dd8a08 in github.com/sourcegraph/lsif-go/internal/output.withTitleAnimated.func1
	     at /Users/chrismwendt/github.com/sourcegraph/lsif-go/internal/output/output.go:114
	 4  0x0000000102dd6754 in github.com/efritz/pentimento.PrintProgress
	     at /Users/chrismwendt/go/pkg/mod/github.com/efritz/pentimento@v0.0.0-20190429011147-ade47d831101/printer.go:46
	 5  0x0000000102dd87d8 in github.com/sourcegraph/lsif-go/internal/output.withTitleAnimated
	     at /Users/chrismwendt/github.com/sourcegraph/lsif-go/internal/output/output.go:109
	 6  0x0000000102dd8504 in github.com/sourcegraph/lsif-go/internal/output.withTitle
	     at /Users/chrismwendt/github.com/sourcegraph/lsif-go/internal/output/output.go:89
	 7  0x0000000102dd8340 in github.com/sourcegraph/lsif-go/internal/output.WithProgressParallel
	     at /Users/chrismwendt/github.com/sourcegraph/lsif-go/internal/output/output.go:69
	 8  0x0000000102dd8268 in github.com/sourcegraph/lsif-go/internal/output.WithProgress
	     at /Users/chrismwendt/github.com/sourcegraph/lsif-go/internal/output/output.go:56
	 9  0x0000000102f080f4 in github.com/sourcegraph/lsif-go/internal/gomod.ListDependencies
	     at /Users/chrismwendt/github.com/sourcegraph/lsif-go/internal/gomod/dependencies.go:73
	10  0x000000010304b768 in main.mainErr
	     at /Users/chrismwendt/github.com/sourcegraph/lsif-go/cmd/lsif-go/main.go:59
	11  0x000000010304b3a0 in main.main
	     at /Users/chrismwendt/github.com/sourcegraph/lsif-go/cmd/lsif-go/main.go:21
	12  0x0000000102c546e4 in runtime.main
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:255
	13  0x0000000102c83c64 in runtime.goexit
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
  Goroutine 2 - User: /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367 runtime.gopark (0x102c54b3c) [force gc (idle) 456959h19m52.782832459s]
	0  0x0000000102c54b3c in runtime.gopark
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	1  0x0000000102c549c0 in runtime.goparkunlock
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:372
	2  0x0000000102c549c0 in runtime.forcegchelper
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:306
	3  0x0000000102c83c64 in runtime.goexit
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
  Goroutine 3 - User: /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367 runtime.gopark (0x102c54b3c) [GC sweep wait]
	0  0x0000000102c54b3c in runtime.gopark
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	1  0x0000000102c402b0 in runtime.goparkunlock
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:372
	2  0x0000000102c402b0 in runtime.bgsweep
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/mgcsweep.go:182
	3  0x0000000102c83c64 in runtime.goexit
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
  Goroutine 4 - User: /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367 runtime.gopark (0x102c54b3c) [GC scavenge wait]
	0  0x0000000102c54b3c in runtime.gopark
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	1  0x0000000102c3e570 in runtime.goparkunlock
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:372
	2  0x0000000102c3e570 in runtime.bgscavenge
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/mgcscavenge.go:314
	3  0x0000000102c83c64 in runtime.goexit
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
  Goroutine 5 - User: /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367 runtime.gopark (0x102c54b3c) [finalizer wait 456959h19m52.785584459s]
	0  0x0000000102c54b3c in runtime.gopark
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	1  0x0000000102c35028 in runtime.goparkunlock
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:372
	2  0x0000000102c35028 in runtime.runfinq
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/mfinal.go:177
	3  0x0000000102c83c64 in runtime.goexit
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
  Goroutine 10 - User: /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/sema.go:56 sync.runtime_Semacquire (0x102c803d8) [semacquire 456959h21m57.201825084s]
	0  0x0000000102c54b3c in runtime.gopark
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	1  0x0000000102c66b08 in runtime.goparkunlock
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:372
	2  0x0000000102c66b08 in runtime.semacquire1
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/sema.go:144
	3  0x0000000102c803d8 in sync.runtime_Semacquire
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/sema.go:56
	4  0x0000000102c9b624 in sync.(*WaitGroup).Wait
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/sync/waitgroup.go:130
	5  0x0000000102f096cc in github.com/sourcegraph/lsif-go/internal/gomod.resolveImportPaths
	    at /Users/chrismwendt/github.com/sourcegraph/lsif-go/internal/gomod/dependencies.go:264
	6  0x0000000102f08788 in github.com/sourcegraph/lsif-go/internal/gomod.ListDependencies.func1
	    at /Users/chrismwendt/github.com/sourcegraph/lsif-go/internal/gomod/dependencies.go:69
	7  0x0000000102dd8044 in github.com/sourcegraph/lsif-go/internal/parallel.Run.func1
	    at /Users/chrismwendt/github.com/sourcegraph/lsif-go/internal/parallel/parallel.go:24
	8  0x0000000102c83c64 in runtime.goexit
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
  Goroutine 29 - User: /Users/chrismwendt/go/pkg/mod/github.com/efritz/pentimento@v0.0.0-20190429011147-ade47d831101/printer.go:112 github.com/efritz/pentimento.(*Printer).Refresh.func1 (0x102dd6da8) [chan receive 456959h21m57.203261084s]
	0  0x0000000102c54b3c in runtime.gopark
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	1  0x0000000102c234a4 in runtime.chanrecv
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/chan.go:576
	2  0x0000000102c22e98 in runtime.chanrecv2
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/chan.go:444
	3  0x0000000102dd6da8 in github.com/efritz/pentimento.(*Printer).Refresh.func1
	    at /Users/chrismwendt/go/pkg/mod/github.com/efritz/pentimento@v0.0.0-20190429011147-ade47d831101/printer.go:112
	4  0x0000000102c83c64 in runtime.goexit
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
  Goroutine 35 - User: /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/sema.go:56 sync.runtime_Semacquire (0x102c803d8) [semacquire 456959h21m57.204448084s]
	0  0x0000000102c54b3c in runtime.gopark
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	1  0x0000000102c66b08 in runtime.goparkunlock
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:372
	2  0x0000000102c66b08 in runtime.semacquire1
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/sema.go:144
	3  0x0000000102c803d8 in sync.runtime_Semacquire
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/sema.go:56
	4  0x0000000102c9b624 in sync.(*WaitGroup).Wait
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/sync/waitgroup.go:130
	5  0x0000000102dd8488 in github.com/sourcegraph/lsif-go/internal/output.WithProgressParallel.func1
	    at /Users/chrismwendt/github.com/sourcegraph/lsif-go/internal/output/output.go:65
	6  0x0000000102c83c64 in runtime.goexit
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
  Goroutine 36 - User: /Users/chrismwendt/go/pkg/mod/github.com/efritz/pentimento@v0.0.0-20190429011147-ade47d831101/printer.go:112 github.com/efritz/pentimento.(*Printer).Refresh.func1 (0x102dd6da8) [chan receive]
	0  0x0000000102c54b3c in runtime.gopark
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	1  0x0000000102c234a4 in runtime.chanrecv
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/chan.go:576
	2  0x0000000102c22e98 in runtime.chanrecv2
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/chan.go:444
	3  0x0000000102dd6da8 in github.com/efritz/pentimento.(*Printer).Refresh.func1
	    at /Users/chrismwendt/go/pkg/mod/github.com/efritz/pentimento@v0.0.0-20190429011147-ade47d831101/printer.go:112
	4  0x0000000102c83c64 in runtime.goexit
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
  Goroutine 55 - User: :0 ??? (0x18e1385a0) (thread 6519685) [chan receive 456959h21m52.808257042s]
	0  0x000000018e1385a0 in ???
	    at ?:-1
	1  0x0000000102c83a8c in runtime.asmcgocall
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:935
	    error: protocol error E08 during memory read for packet $mffffffffffc00e20,8
	(truncated)
  Goroutine 82 - User: /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367 runtime.gopark (0x102c54b3c) [GC worker (idle) 456959h21m57.209622084s]
	0  0x0000000102c54b3c in runtime.gopark
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	1  0x0000000102c38034 in runtime.gcBgMarkWorker
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/mgc.go:1200
	2  0x0000000102c83c64 in runtime.goexit
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
  Goroutine 83 - User: /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367 runtime.gopark (0x102c54b3c) [GC worker (idle)]
	0  0x0000000102c54b3c in runtime.gopark
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	1  0x0000000102c38034 in runtime.gcBgMarkWorker
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/mgc.go:1200
	2  0x0000000102c83c64 in runtime.goexit
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
  Goroutine 84 - User: /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367 runtime.gopark (0x102c54b3c) [GC worker (idle)]
	0  0x0000000102c54b3c in runtime.gopark
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	1  0x0000000102c38034 in runtime.gcBgMarkWorker
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/mgc.go:1200
	2  0x0000000102c83c64 in runtime.goexit
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
  Goroutine 85 - User: /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367 runtime.gopark (0x102c54b3c) [GC worker (idle) 456959h21m56.325406584s]
	0  0x0000000102c54b3c in runtime.gopark
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	1  0x0000000102c38034 in runtime.gcBgMarkWorker
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/mgc.go:1200
	2  0x0000000102c83c64 in runtime.goexit
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
  Goroutine 98 - User: /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367 runtime.gopark (0x102c54b3c) [GC worker (idle)]
	0  0x0000000102c54b3c in runtime.gopark
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	1  0x0000000102c38034 in runtime.gcBgMarkWorker
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/mgc.go:1200
	2  0x0000000102c83c64 in runtime.goexit
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
  Goroutine 99 - User: /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367 runtime.gopark (0x102c54b3c) [GC worker (idle)]
	0  0x0000000102c54b3c in runtime.gopark
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	1  0x0000000102c38034 in runtime.gcBgMarkWorker
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/mgc.go:1200
	2  0x0000000102c83c64 in runtime.goexit
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
  Goroutine 114 - User: /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367 runtime.gopark (0x102c54b3c) [GC worker (idle) 456959h21m56.890885542s]
	0  0x0000000102c54b3c in runtime.gopark
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	1  0x0000000102c38034 in runtime.gcBgMarkWorker
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/mgc.go:1200
	2  0x0000000102c83c64 in runtime.goexit
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
  Goroutine 115 - User: /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367 runtime.gopark (0x102c54b3c) [GC worker (idle) 456959h21m55.663103792s]
	0  0x0000000102c54b3c in runtime.gopark
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	1  0x0000000102c38034 in runtime.gcBgMarkWorker
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/mgc.go:1200
	2  0x0000000102c83c64 in runtime.goexit
	    at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
  Goroutine 559 - User: /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/netpoll.go:229 internal/poll.runtime_pollWait (0x102c7e9f4) [IO wait 456959h21m52.815328042s]
	 0  0x0000000102c54b3c in runtime.gopark
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/proc.go:367
	 1  0x0000000102c4d2d8 in runtime.netpollblock
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/netpoll.go:445
	 2  0x0000000102c7e9f4 in internal/poll.runtime_pollWait
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/netpoll.go:229
	 3  0x0000000102ce03a8 in internal/poll.(*pollDesc).wait
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/internal/poll/fd_poll_runtime.go:84
	 4  0x0000000102ce148c in internal/poll.(*pollDesc).waitRead
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/internal/poll/fd_poll_runtime.go:89
	 5  0x0000000102ce148c in internal/poll.(*FD).Read
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/internal/poll/fd_unix.go:167
	 6  0x0000000102ce7524 in os.(*File).read
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/os/file_posix.go:32
	 7  0x0000000102ce7524 in os.(*File).Read
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/os/file.go:119
	 8  0x0000000102d16b24 in bytes.(*Buffer).ReadFrom
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/bytes/buffer.go:204
	 9  0x0000000102cbf5a4 in io.copyBuffer
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/io/io.go:409
	10  0x0000000102db6514 in io.Copy
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/io/io.go:382
	11  0x0000000102db6514 in os/exec.(*Cmd).writerDescriptor.func1
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/os/exec/exec.go:311
	12  0x0000000102db6f58 in os/exec.(*Cmd).Start.func1
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/os/exec/exec.go:441
	13  0x0000000102c83c64 in runtime.goexit
	     at /opt/homebrew/Cellar/go/1.17/libexec/src/runtime/asm_arm64.s:1133
[19 goroutines]

I don't know why there are no goroutines in that block. It appears as though it's in deadlock.

However, I noticed there's a frame in os/exec.(*Cmd).Start.func1 and deeper in io.Copy waiting for stdout from a subprocessed, so I checked pstree for child processes and found:

 |   |       \-+= 29322 chrismwendt /Users/chrismwendt/github.com/sourcegraph/lsif-go/lsif-go
 |   |         \-+- 29730 chrismwendt git ls-remote git+ssh://git.apache.org/thrift
 |   |           \--- 29731 chrismwendt /usr/bin/ssh -o SendEnv=GIT_PROTOCOL git.apache.org git-upload-pack '/thrift'

I ran it myself:

$ git ls-remote git+ssh://git.apache.org/thrift
The authenticity of host 'git.apache.org (52.202.80.70)' can't be established.
ECDSA key fingerprint is SHA256:EzwREkEsDEDLPU4dybKtxgPuXW8Gt/P5Qapo1VheWqw.
Are you sure you want to continue connecting (yes/no/[fingerprint])?

And it hung. When I typed yes, it said "permission denied".

I'm not sure why this is hanging for me when recent lsif-go runs in CI are working https://github.com/sourcegraph/sourcegraph/runs/5252625222?check_suite_focus=true#step:4:5

[jlisee]

As a customer I get this as well and it's a confusing and bad first experience. I suggest updating whatever system you have here to detect the request for input and drop out of interactive mode and ask the user for input.

Here is what it looked like:

✔ Resolving module name... Done (890.16ms)
⠸ Listing dependencies... 0/1
⠹ Listing dependencies... 0/1

⠼ Listing dependencies... 0/1

I was able to get around it by doing:

$ lsif-go -v --no-animation

Resolving module name
Finished in 911.09ms.

Listing dependencies
WARNING: Failed to resolve repo aurora.tech/av (unrecognized import path "<hidden>") %!s(*vcs.RepoRoot=<nil>).
The authenticity of host 'git.apache.org (65.108.73.173)' can't be established.
ECDSA key fingerprint is SHA256:hKCOFRIQOmR+9NuChvXFrggGWmP9F7Sg+EsHR6mzLLg.
Are you sure you want to continue connecting (yes/no)? yes
Finished in 8.29s

[chrismwendt]

Checking out a different commit (and in one case checking out commit A, B, then A again) fixed the problem somehow. Maybe there's some stale local git checkout state floating around?

[olafurpg]

I updated the title to reflect that this bug only reproduces with --animation enabled. I just released 1.9.1, which disabled animation by default. Thank you @jlisee for identifying the workaround!