Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

x/tools/gopls/internal/regtest/misc: timeout in TestRenamePackageWithDifferentDirectoryPath #59541

Closed
gopherbot opened this issue Apr 11, 2023 · 10 comments
Closed

x/tools/gopls/internal/regtest/misc: timeout in TestRenamePackageWithDifferentDirectoryPath #59541

gopherbot opened this issue Apr 11, 2023 · 10 comments
Assignees
@findleyr
Labels
FrozenDueToAge gopls Issues related to the Go language server, gopls. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Tools This label describes issues relating to any tools in the x/tools repository.
Milestone
Unreleased

Comments

@gopherbot
Copy link

gopherbot commented Apr 11, 2023 •
edited by bcmills 

#!watchflakes
post <- pkg == "golang.org/x/tools/gopls/internal/regtest/misc" && test == "TestRenamePackageWithDifferentDirectoryPath" && log ~ `panic: test timed out`

Issue created automatically to collect these failures.

Example (log):

serve.go:434: debug server listening at http://localhost:49257
serve.go:434: debug server listening at http://localhost:49258
panic: test timed out after 10m0s
running tests:
	TestRenamePackageWithDifferentDirectoryPath (6m49s)
	TestRenamePackageWithDifferentDirectoryPath/default (6m49s)

testing.(*T).Run(0xc002bf81a0, {0x1b890df?, 0x1ba62bf?}, 0xc0035f3ef0)
	/tmp/buildlet/go/src/testing/testing.go:1649 +0x3c8
golang.org/x/tools/gopls/internal/lsp/regtest.(*Runner).Run(0xc00031afa0, 0xc002bf81a0, {0x1bfae3a, 0xf2}, 0x1d0fbd8, {0x0, 0x0, 0xc000336f60?})
	/tmp/buildlet/gopath/src/golang.org/x/tools/gopls/internal/lsp/regtest/runner.go:169 +0x491
golang.org/x/tools/gopls/internal/lsp/regtest.Run(...)
	/tmp/buildlet/gopath/src/golang.org/x/tools/gopls/internal/lsp/regtest/regtest.go:54
golang.org/x/tools/gopls/internal/regtest/misc.TestRenamePackageWithDifferentDirectoryPath(0xc002fc8d00?)
	/tmp/buildlet/gopath/src/golang.org/x/tools/gopls/internal/regtest/misc/rename_test.go:264 +0x55
testing.tRunner(0xc002bf81a0, 0x1d0fbe0)

— watchflakes
@gopherbot gopherbot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Apr 11, 2023
@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/tools/gopls/internal/regtest/misc" && test == "TestRenamePackageWithDifferentDirectoryPath"
2023-04-10 20:09 darwin-amd64-nocgo tools@40fb89cd go@a5c79283 x/tools/gopls/internal/regtest/misc.TestRenamePackageWithDifferentDirectoryPath (log) 
serve.go:434: debug server listening at http://localhost:49257
serve.go:434: debug server listening at http://localhost:49258
panic: test timed out after 10m0s
running tests:
	TestRenamePackageWithDifferentDirectoryPath (6m49s)
	TestRenamePackageWithDifferentDirectoryPath/default (6m49s)

testing.(*T).Run(0xc002bf81a0, {0x1b890df?, 0x1ba62bf?}, 0xc0035f3ef0)
	/tmp/buildlet/go/src/testing/testing.go:1649 +0x3c8
golang.org/x/tools/gopls/internal/lsp/regtest.(*Runner).Run(0xc00031afa0, 0xc002bf81a0, {0x1bfae3a, 0xf2}, 0x1d0fbd8, {0x0, 0x0, 0xc000336f60?})
	/tmp/buildlet/gopath/src/golang.org/x/tools/gopls/internal/lsp/regtest/runner.go:169 +0x491
golang.org/x/tools/gopls/internal/lsp/regtest.Run(...)
	/tmp/buildlet/gopath/src/golang.org/x/tools/gopls/internal/lsp/regtest/regtest.go:54
golang.org/x/tools/gopls/internal/regtest/misc.TestRenamePackageWithDifferentDirectoryPath(0xc002fc8d00?)
	/tmp/buildlet/gopath/src/golang.org/x/tools/gopls/internal/regtest/misc/rename_test.go:264 +0x55
testing.tRunner(0xc002bf81a0, 0x1d0fbe0)

— watchflakes

@gopherbot gopherbot added Tools This label describes issues relating to any tools in the x/tools repository. gopls Issues related to the Go language server, gopls. labels Apr 11, 2023
@gopherbot gopherbot added this to the Unreleased milestone Apr 11, 2023
@bcmills bcmills changed the title x/tools/gopls/internal/regtest/misc: TestRenamePackageWithDifferentDirectoryPath failures x/tools/gopls/internal/regtest/misc: timeout in TestRenamePackageWithDifferentDirectoryPath Apr 11, 2023
@bcmills
Copy link
Contributor

bcmills commented Apr 11, 2023

Looks like it deadlocked during shutdown:

goroutine 39892 [semacquire, 6 minutes]:
sync.runtime_Semacquire(0x170b876?)
	/tmp/buildlet/go/src/runtime/sema.go:62 +0x25
sync.(*WaitGroup).Wait(0xc000f07380?)
	/tmp/buildlet/go/src/sync/waitgroup.go:116 +0x48
golang.org/x/tools/gopls/internal/lsp/cache.(*View).shutdown(0xc000f07380)
	/tmp/buildlet/gopath/src/golang.org/x/tools/gopls/internal/lsp/cache/view.go:587 +0xff
golang.org/x/tools/gopls/internal/lsp/cache.(*Session).Shutdown(0xc002d4d080, {0x1e368c0, 0xc00ba1aed0})
	/tmp/buildlet/gopath/src/golang.org/x/tools/gopls/internal/lsp/cache/session.go:71 +0x154
golang.org/x/tools/gopls/internal/lsp.(*Server).shutdown(0xc000133340, {0x1e36850?, 0xc00b24ab40?})
	/tmp/buildlet/gopath/src/golang.org/x/tools/gopls/internal/lsp/general.go:604 +0x145
golang.org/x/tools/gopls/internal/lsp.(*Server).Shutdown(0x0?, {0x1e36850?, 0xc00b24ab40?})
	/tmp/buildlet/gopath/src/golang.org/x/tools/gopls/internal/lsp/server_gen.go:256 +0x1d

@findleyr
Copy link
Contributor

No, it's not deadlocked. Everything is waiting for a Go command invocation:

goroutine 39939 [chan receive, 6 minutes]:
golang.org/x/tools/internal/gocommand.runCmdContext({0x1e36888, 0xc0001929a0}, 0xc0013b2c60)
	/tmp/buildlet/gopath/src/golang.org/x/tools/internal/gocommand/invoke.go:305 +0x4d9

@findleyr
Copy link
Contributor

Following https://go.dev/cl/483215, we don't panic with "detected a hanging Go command" when we encounter this Kernel bug where the process is done but cmd.Wait() does not return.

So we hang indefinitely.

CC @adonovan

@bcmills
Copy link
Contributor

bcmills commented Apr 12, 2023

Oh, interesting! I had thought that was just a longer-than-expected delay, but I agree that looks like an actual kernel bug. That's unfortunate. 😕

@bcmills
Copy link
Contributor

bcmills commented Apr 12, 2023

#19314 may be related.

@findleyr
Copy link
Contributor

I think we put back the "detected a hanging Go command" panic in this case, albeit without the useless process dump, so that this failure will continue to get aggregated into #54461. Otherwise, we'll continue to get flakes for random tests that encounter this bug.

I'll send a CL.

@findleyr findleyr self-assigned this Apr 13, 2023
@gopherbot
Copy link
Author

Change https://go.dev/cl/484742 mentions this issue: internal/gocommand: panic on hanging Go command that are done

@bcmills
Copy link
Contributor

bcmills commented Apr 14, 2023

Ok, so this is blocked waiting on copying stdout and/or stderr after the command has already exited.

Could be that there is some bug in either the darwin kernel or the runtime poller that causes the pipe to fail to unblock when the process exits.

CL 484741 might either work around the problem or help us find out more.

goroutine 39880 [IO wait, 6 minutes]:
internal/poll.runtime_pollWait(0x2bac9df8, 0x72)
	/tmp/buildlet/go/src/runtime/netpoll.go:306 +0x85
internal/poll.(*pollDesc).wait(0xc00340d500?, 0xc000f9ea00?, 0x1)
	/tmp/buildlet/go/src/internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
	/tmp/buildlet/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc00340d500, {0xc000f9ea00, 0x200, 0x200})
	/tmp/buildlet/go/src/internal/poll/fd_unix.go:167 +0x27a
os.(*File).read(...)
	/tmp/buildlet/go/src/os/file_posix.go:31
os.(*File).Read(0xc006636330, {0xc000f9ea00?, 0xc00726de68?, 0xc00726de68?})
	/tmp/buildlet/go/src/os/file.go:118 +0x52
bytes.(*Buffer).ReadFrom(0xc0040f95f0, {0x1e2fea0, 0xc006636330})
	/tmp/buildlet/go/src/bytes/buffer.go:211 +0x96
io.copyBuffer({0x1e2e580, 0xc0040f95f0}, {0x1e2fea0, 0xc006636330}, {0x0, 0x0, 0x0})
	/tmp/buildlet/go/src/io/io.go:413 +0x147
io.Copy(...)
	/tmp/buildlet/go/src/io/io.go:386
os/exec.(*Cmd).writerDescriptor.func1()
	/tmp/buildlet/go/src/os/exec/exec.go:560 +0x34
os/exec.(*Cmd).Start.func2(0x0?)
	/tmp/buildlet/go/src/os/exec/exec.go:717 +0x2c
created by os/exec.(*Cmd).Start in goroutine 39939
	/tmp/buildlet/go/src/os/exec/exec.go:716 +0x9f4
…
goroutine 39881 [IO wait, 6 minutes]:
internal/poll.runtime_pollWait(0x2bac91c8, 0x72)
	/tmp/buildlet/go/src/runtime/netpoll.go:306 +0x85
internal/poll.(*pollDesc).wait(0xc00340d5c0?, 0xc000f9ec00?, 0x1)
	/tmp/buildlet/go/src/internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
	/tmp/buildlet/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc00340d5c0, {0xc000f9ec00, 0x200, 0x200})
	/tmp/buildlet/go/src/internal/poll/fd_unix.go:167 +0x27a
os.(*File).read(...)
	/tmp/buildlet/go/src/os/file_posix.go:31
os.(*File).Read(0xc006636348, {0xc000f9ec00?, 0xc001b47e68?, 0xc001b47e68?})
	/tmp/buildlet/go/src/os/file.go:118 +0x52
bytes.(*Buffer).ReadFrom(0xc0040f9620, {0x1e2fea0, 0xc006636348})
	/tmp/buildlet/go/src/bytes/buffer.go:211 +0x96
io.copyBuffer({0x1e2e580, 0xc0040f9620}, {0x1e2fea0, 0xc006636348}, {0x0, 0x0, 0x0})
	/tmp/buildlet/go/src/io/io.go:413 +0x147
io.Copy(...)
	/tmp/buildlet/go/src/io/io.go:386
os/exec.(*Cmd).writerDescriptor.func1()
	/tmp/buildlet/go/src/os/exec/exec.go:560 +0x34
os/exec.(*Cmd).Start.func2(0x0?)
	/tmp/buildlet/go/src/os/exec/exec.go:717 +0x2c
created by os/exec.(*Cmd).Start in goroutine 39939
	/tmp/buildlet/go/src/os/exec/exec.go:716 +0x9f4
…
goroutine 39882 [chan receive, 6 minutes]:
os/exec.(*Cmd).awaitGoroutines(0xc0013b2c60, 0x0)
	/tmp/buildlet/go/src/os/exec/exec.go:941 +0x215
os/exec.(*Cmd).Wait(0xc0013b2c60)
	/tmp/buildlet/go/src/os/exec/exec.go:908 +0x16d
golang.org/x/tools/internal/gocommand.runCmdContext.func1()
	/tmp/buildlet/gopath/src/golang.org/x/tools/internal/gocommand/invoke.go:252 +0x25
created by golang.org/x/tools/internal/gocommand.runCmdContext in goroutine 39939
	/tmp/buildlet/gopath/src/golang.org/x/tools/internal/gocommand/invoke.go:251 +0xb3

@gopherbot
Copy link
Author

Change https://go.dev/cl/484743 mentions this issue: internal/gocommand: set a WaitDelay (when available) on commands

This was referenced Apr 20, 2023
Closed
Closed
@golang golang locked and limited conversation to collaborators Apr 20, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@findleyr findleyr

Labels
FrozenDueToAge gopls Issues related to the Go language server, gopls. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Tools This label describes issues relating to any tools in the x/tools repository.
Projects
Test Flakes
Status: Done
Milestone
Unreleased
Development

No branches or pull requests
3 participants
@bcmills @gopherbot @findleyr