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

Tests Occasionally Hang on Fresh Clone of Repo #675

Closed
pmurley opened this issue Aug 3, 2020 · 4 comments
Closed

Tests Occasionally Hang on Fresh Clone of Repo #675

pmurley opened this issue Aug 3, 2020 · 4 comments

Comments

@pmurley
Copy link
Contributor

pmurley commented Aug 3, 2020

What versions are you running?

Chromedp version: ccb1bb0

$ google-chrome --version
Google Chrome 84.0.4147.105

$ go version
go version go1.14.6 linux/amd64

What did you do? Include clear steps.

  1. Clone a fresh copy of the repository
  2. Run tests (go test -v)

What did you expect to see?

Tests always passing

What did you see instead?

Tests occasionally pass, but also occasionally hang/do not complete. I have not been able to determine any factor that effects whether they hang or not -- I rerun without changing ANYTHING else and the outcome changes back and forth. It seems flaky to me.

Output (stack trace) from a failed run (timeout) is below. It appears to me it might be related to a browser not closing or a context not getting canceled properly, but I am unsure.

    --- PASS: TestRunResponse/NavigateBadTLS (0.60s)
    --- PASS: TestRunResponse/ClickBadIframe (0.77s)
    --- PASS: TestRunResponse/NavigateUnimplementedProtocol (0.62s)
    --- PASS: TestRunResponse/ClickInfiniteRedirects (0.93s)
    --- PASS: TestRunResponse/NavigateBadProtocol (0.60s)
    --- PASS: TestRunResponse/ClickNonHTML (0.79s)
    --- PASS: TestRunResponse/Navigate404 (0.52s)
    --- PASS: TestRunResponse/ClickBadProtocol (0.70s)
    --- PASS: TestRunResponse/Navigate500 (0.59s)
    --- PASS: TestRunResponse/Click500 (0.65s)
    --- PASS: TestRunResponse/Click404 (0.66s)
    --- PASS: TestRunResponse/ClickBadTLS (0.69s)
    --- PASS: TestRunResponse/Click200 (0.58s)
panic: test timed out after 2m0s

goroutine 1657 [running]:
testing.(*M).startAlarm.func1()
	/usr/local/go/src/testing/testing.go:1509 +0xdf
created by time.goFunc
	/usr/local/go/src/time/sleep.go:168 +0x44

goroutine 1 [chan receive, 1 minutes]:
testing.tRunner.func1(0xc000150d80)
	/usr/local/go/src/testing/testing.go:1004 +0x238
testing.tRunner(0xc000150d80, 0xc0000a6d78)
	/usr/local/go/src/testing/testing.go:1043 +0x10b
testing.runTests(0xc0001264c0, 0x10270e0, 0x5f, 0x5f, 0x0)
	/usr/local/go/src/testing/testing.go:1332 +0x2a7
testing.(*M).Run(0xc0001aa000, 0x0)
	/usr/local/go/src/testing/testing.go:1249 +0x1b7
github.com/chromedp/chromedp.TestMain(0xc0001aa000)
	/home/pmurley/go/src/github.com/chromedp/chromedp/chromedp_test.go:88 +0x138
main.main()
	_testmain.go:258 +0x135

goroutine 31 [chan receive, 1 minutes]:
github.com/chromedp/chromedp.Cancel(0xbc8080, 0xc00030c810, 0x0, 0x0)
	/home/pmurley/go/src/github.com/chromedp/chromedp/chromedp.go:234 +0x182
github.com/chromedp/chromedp.TestPrematureCancel(0xc000151c20)
	/home/pmurley/go/src/github.com/chromedp/chromedp/chromedp_test.go:278 +0x94
testing.tRunner(0xc000151c20, 0xb01fc8)
	/usr/local/go/src/testing/testing.go:1039 +0xdc
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:1090 +0x372

goroutine 32 [chan send, 1 minutes]:
testing.tRunner.func1(0xc000151d40)
	/usr/local/go/src/testing/testing.go:1029 +0x353
testing.tRunner(0xc000151d40, 0xb01fc0)
	/usr/local/go/src/testing/testing.go:1043 +0x10b
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:1090 +0x372

goroutine 33 [chan send, 1 minutes]:
testing.tRunner.func1(0xc000151e60)
	/usr/local/go/src/testing/testing.go:1029 +0x353
testing.tRunner(0xc000151e60, 0xb01fb8)
	/usr/local/go/src/testing/testing.go:1043 +0x10b
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:1090 +0x372

... (many more of these) ...

goroutine 109 [chan send, 1 minutes]:
testing.tRunner.func1(0xc00021b0e0)
	/usr/local/go/src/testing/testing.go:1029 +0x353
testing.tRunner(0xc00021b0e0, 0xb01e98)
	/usr/local/go/src/testing/testing.go:1043 +0x10b
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:1090 +0x372

goroutine 110 [chan send, 1 minutes]:
testing.tRunner.func1(0xc00021b200)
	/usr/local/go/src/testing/testing.go:1029 +0x353
testing.tRunner(0xc00021b200, 0xb01fa0)
	/usr/local/go/src/testing/testing.go:1043 +0x10b
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:1090 +0x372

goroutine 111 [chan receive, 1 minutes]:
testing.runTests.func1.1(0xc000150d80)
	/usr/local/go/src/testing/testing.go:1339 +0x3b
created by testing.runTests.func1
	/usr/local/go/src/testing/testing.go:1339 +0xac

goroutine 112 [chan receive, 1 minutes]:
github.com/chromedp/chromedp.NewContext.func1(0xbc8080, 0xc000230030, 0xc000234000)
	/home/pmurley/go/src/github.com/chromedp/chromedp/chromedp.go:131 +0x78
created by github.com/chromedp/chromedp.NewContext
	/home/pmurley/go/src/github.com/chromedp/chromedp/chromedp.go:130 +0x22a

goroutine 113 [select, 1 minutes]:
os/exec.(*Cmd).Start.func2(0xc00023c000)
	/usr/local/go/src/os/exec/exec.go:449 +0xc4
created by os/exec.(*Cmd).Start
	/usr/local/go/src/os/exec/exec.go:448 +0x6d0

goroutine 130 [syscall, 1 minutes]:
syscall.Syscall6(0xf7, 0x1, 0x32eb3b, 0xc000207df0, 0x1000004, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/syscall/asm_linux_amd64.s:41 +0x5
os.(*Process).blockUntilWaitable(0xc00003e360, 0x0, 0x0, 0x0)
	/usr/local/go/src/os/wait_waitid.go:31 +0x98
os.(*Process).wait(0xc00003e360, 0x0, 0x0, 0x0)
	/usr/local/go/src/os/exec_unix.go:22 +0x39
os.(*Process).Wait(...)
	/usr/local/go/src/os/exec.go:125
os/exec.(*Cmd).Wait(0xc00023c000, 0x0, 0x0)
	/usr/local/go/src/os/exec/exec.go:507 +0x60
github.com/chromedp/chromedp.(*ExecAllocator).Allocate.func2(0xc00023c000, 0x1, 0xc0000381c0, 0x34, 0xc000234000, 0xc0001460f0)
	/home/pmurley/go/src/github.com/chromedp/chromedp/allocate.go:204 +0x2f
created by github.com/chromedp/chromedp.(*ExecAllocator).Allocate
	/home/pmurley/go/src/github.com/chromedp/chromedp/allocate.go:199 +0xa32

goroutine 244 [select]:
github.com/chromedp/chromedp.(*Browser).run(0xc000148f00, 0xbc8080, 0xc000230030)
	/home/pmurley/go/src/github.com/chromedp/chromedp/browser.go:273 +0x2b9
created by github.com/chromedp/chromedp.NewBrowser
	/home/pmurley/go/src/github.com/chromedp/chromedp/browser.go:118 +0x42b

goroutine 245 [chan receive, 1 minutes]:
github.com/chromedp/chromedp.(*ExecAllocator).Allocate.func4(0xc000148f00, 0xc000234000)
	/home/pmurley/go/src/github.com/chromedp/chromedp/allocate.go:252 +0x38
created by github.com/chromedp/chromedp.(*ExecAllocator).Allocate
	/home/pmurley/go/src/github.com/chromedp/chromedp/allocate.go:245 +0xcf3

goroutine 246 [IO wait]:
internal/poll.runtime_pollWait(0x7f1c58baff18, 0x72, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:203 +0x55
internal/poll.(*pollDesc).wait(0xc0001aa398, 0x72, 0x0, 0xc, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc0001aa380, 0xc000b37960, 0x2, 0xc, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
net.(*netFD).Read(0xc0001aa380, 0xc000b37960, 0x2, 0xc, 0x0, 0xc, 0xc000b37960)
	/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc0001320c8, 0xc000b37960, 0x2, 0xc, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:184 +0x8e
io.ReadAtLeast(0xbbe240, 0xc0001320c8, 0xc000b37960, 0x2, 0xc, 0x2, 0xbc8080, 0xc000b11650, 0xbc1e20)
	/usr/local/go/src/io/io.go:310 +0x87
io.ReadFull(...)
	/usr/local/go/src/io/io.go:329
github.com/gobwas/ws.ReadHeader(0xbbe240, 0xc0001320c8, 0x0, 0x0, 0xaba180, 0xbbe240)
	/home/pmurley/go/pkg/mod/github.com/gobwas/ws@v1.0.3/read.go:25 +0x97
github.com/gobwas/ws/wsutil.(*Reader).NextFrame(0xc0001da010, 0x0, 0x0, 0xbbe240, 0xc0001320c8)
	/home/pmurley/go/pkg/mod/github.com/gobwas/ws@v1.0.3/wsutil/reader.go:151 +0x57
github.com/chromedp/chromedp.(*Conn).Read(0xc0001da000, 0xbc8080, 0xc000230030, 0xc000f0a660, 0xc000ae8420, 0xc0001f2000)
	/home/pmurley/go/src/github.com/chromedp/chromedp/conn.go:89 +0xfd
github.com/chromedp/chromedp.(*Browser).run.func1(0xc000148f00, 0xbc8080, 0xc000230030, 0xc0001c88a0, 0xc0001c8900)
	/home/pmurley/go/src/github.com/chromedp/chromedp/browser.go:230 +0x82
created by github.com/chromedp/chromedp.(*Browser).run
	/home/pmurley/go/src/github.com/chromedp/chromedp/browser.go:227 +0x10a

goroutine 257 [select, 1 minutes]:
github.com/chromedp/chromedp.(*Target).run(0xc0002e80a0, 0xbc8080, 0xc000230030)
	/home/pmurley/go/src/github.com/chromedp/chromedp/target.go:119 +0x151
created by github.com/chromedp/chromedp.(*Context).attachTarget
	/home/pmurley/go/src/github.com/chromedp/chromedp/chromedp.go:356 +0x2ce

goroutine 290 [select]:
github.com/chromedp/chromedp.(*Target).run.func1(0xbc8080, 0xc000230030, 0xc0002e80a0, 0xc00049e780)
	/home/pmurley/go/src/github.com/chromedp/chromedp/target.go:80 +0xec
created by github.com/chromedp/chromedp.(*Target).run
	/home/pmurley/go/src/github.com/chromedp/chromedp/target.go:78 +0x96

goroutine 659 [chan receive, 1 minutes]:
github.com/chromedp/chromedp.(*ExecAllocator).Allocate.func4(0xc0002e8000, 0xc0003ce0b0)
	/home/pmurley/go/src/github.com/chromedp/chromedp/allocate.go:252 +0x38
created by github.com/chromedp/chromedp.(*ExecAllocator).Allocate
	/home/pmurley/go/src/github.com/chromedp/chromedp/allocate.go:245 +0xcf3
exit status 2
FAIL	github.com/chromedp/chromedp	120.033s
@mvdan
Copy link
Contributor

mvdan commented Aug 4, 2020

Thanks for the report. It seems like TestPrematureCancel might be to blame here, I'll try to investigate.

@pmurley pmurley mentioned this issue Aug 4, 2020
Merged
@pmurley
Copy link
Contributor Author

pmurley commented Aug 11, 2020

Just checking status on this, mostly because of #674.

@mvdan
Copy link
Contributor

mvdan commented Aug 12, 2020

I've replied there :)

This was referenced Jan 14, 2021
Closed
Closed
@ZekeLu
Copy link
Member

ZekeLu commented May 5, 2021

#742 has been merged. Closing.

@ZekeLu ZekeLu closed this as completed May 5, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix deadlock in TestPrematureCancel. QuLogic/chromedp
3 participants
@ZekeLu @pmurley @mvdan