wasmbrowsertest: wasmbrowsertest taking too long and not printing any output

https://travis-ci.com/nhooyr/websocket/jobs/288703981

--- FAIL: TestWasm (60.00s)
    conn_test.go:305: wasm test binary failed: signal: killed:

This is indicating the go test -exec=wasmbrowsertest command failed as it was killed by the 60s timeout.

travis config: https://github.com/nhooyr/websocket/blob/5afbe3c1d163117b5ff9df021aa4b14e6ab2e7b5/.travis.yml#L25-L31

go test invocation: https://github.com/nhooyr/websocket/blob/wasm/conn_test.go#L300-L307

wasm test: https://github.com/nhooyr/websocket/blob/5afbe3c1d163117b5ff9df021aa4b14e6ab2e7b5/ws_js_test.go

As you can see, even with the t.Fatal in the wasm test, wasmbrowsertest is timing out after 60s and prints no output. Any ideas why?

About this issue

  • Original URL
  • State: closed
  • Created 4 years ago
  • Comments: 39 (13 by maintainers)

Commits related to this issue

Most upvoted comments

I plan to take a look some time. I will keep this open for now.

+1
agnivade on May 10, 2020

I cloned your repo locally. It seems like your tests itself were incorrect.

  • You were not logging the output from the command at all. Hence, no output was coming even after adding a ā€œ-test.vā€.
  • You were compiling to a different binary, and running a different one.
  • Your command argument invocation was wrong.

Are you sure you tested this locally before running in CI ? šŸ˜‰

--- a/conn_test.go
+++ b/conn_test.go
@@ -298,7 +298,7 @@ func TestWasm(t *testing.T) {
        ctx, cancel := context.WithTimeout(context.Background(), time.Minute)
        defer cancel()
 
-       cmd := exec.CommandContext(ctx, "go", "test", "-c", "-o wasm.test", ".")
+       cmd := exec.CommandContext(ctx, "go", "test", "-c", "-o", "test.wasm", ".")
        cmd.Env = append(os.Environ(), "GOOS=js", "GOARCH=wasm", fmt.Sprintf("WS_ECHO_SERVER_URL=%v", wstest.URL(s)))
 
        timer := time.AfterFunc(time.Second*20, func() {
@@ -310,6 +310,7 @@ func TestWasm(t *testing.T) {
        if err != nil {
                t.Fatalf("wasm test binary failed: %v:\n%s", err, b)
        }
+       t.Logf("%s\n", b)
 
        browserTestCmd := exec.CommandContext(ctx, "wasmbrowsertest", "./test.wasm", "-test.v")
        browserTestCmd.Env = append(os.Environ(), "GOOS=js", "GOARCH=wasm", fmt.Sprintf("WS_ECHO_SERVER_URL=%v", wstest.URL(s)))
@@ -323,6 +324,7 @@ func TestWasm(t *testing.T) {
        if err != nil {
                t.Fatalf("wasm test binary failed: %v:\n%s", err, b)
        }
+       t.Logf("%s\n", b)
 }

Here is the diff which fixes it. Let me know if you still see problems.

+1
agnivade on Apr 25, 2020 
2020/04/08 07:49:06 websocket: failed to marshal close frame: status code StatusCode(-1) cannot be set
--- FAIL: TestWasm (21.05s)
    conn_test.go:324: wasm test binary failed: exit status 2:
        SIGQUIT: quit
        PC=0x465cf1 m=0 sigcode=0
        
        goroutine 0 [idle]:
        runtime.futex(0xf70e88, 0x80, 0x0, 0x0, 0x7fff00000000, 0x0, 0x8a, 0x40c34d, 0x7ffff225ece8, 0x40c66f, ...)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/runtime/sys_linux_amd64.s:567 +0x21
        runtime.futexsleep(0xf70e88, 0x100000000, 0xffffffffffffffff)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/runtime/os_linux.go:45 +0x46
        runtime.notesleep(0xf70e88)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/runtime/lock_futex.go:151 +0x9f
        runtime.stopm()
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/runtime/proc.go:1828 +0xc0
        runtime.findrunnable(0xc000050800, 0x0)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/runtime/proc.go:2360 +0xa0d
        runtime.schedule()
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/runtime/proc.go:2520 +0x2fc
        runtime.park_m(0xc000000180)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/runtime/proc.go:2690 +0x9d
        runtime.mcall(0x0)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/runtime/asm_amd64.s:318 +0x5b
        
        goroutine 1 [select]:
        github.com/chromedp/chromedp.(*Selector).Do(0xc00007b6c0, 0xb46b00, 0xc0001fdda0, 0x0, 0x0)
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/query.go:161 +0x15e
        github.com/chromedp/chromedp.Tasks.Do(0xc000185f10, 0x3, 0x3, 0xb46b00, 0xc0001fdda0, 0xc000154480, 0xb46b00)
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/chromedp.go:403 +0x72
        github.com/chromedp/chromedp.Run(0xb46b00, 0xc0001fd9b0, 0xc0001fbf10, 0x3, 0x3, 0x0, 0x0)
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/chromedp.go:239 +0x144
        main.main()
        	/home/travis/gopath/pkg/mod/github.com/agnivade/wasmbrowsertest@v0.3.3/main.go:148 +0xb89
        
        goroutine 8 [chan receive]:
        github.com/chromedp/chromedp.NewContext.func1(0xb46b00, 0xc0001fd9b0, 0xc00013c370)
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/chromedp.go:129 +0x78
        created by github.com/chromedp/chromedp.NewContext
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/chromedp.go:128 +0x22a
        
        goroutine 9 [IO wait]:
        internal/poll.runtime_pollWait(0x7f75c142cf18, 0x72, 0x0)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/runtime/netpoll.go:203 +0x55
        internal/poll.(*pollDesc).wait(0xc00017e998, 0x72, 0x0, 0x0, 0xa648b7)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/internal/poll/fd_poll_runtime.go:87 +0x45
        internal/poll.(*pollDesc).waitRead(...)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/internal/poll/fd_poll_runtime.go:92
        internal/poll.(*FD).Accept(0xc00017e980, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/internal/poll/fd_unix.go:384 +0x1d4
        net.(*netFD).accept(0xc00017e980, 0xc000070dd0, 0xf70d40, 0x7f75eaf61108)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/net/fd_unix.go:238 +0x42
        net.(*TCPListener).accept(0xc00000eb40, 0xc000070e10, 0x40e478, 0x30)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/net/tcpsock_posix.go:139 +0x32
        net.(*TCPListener).Accept(0xc00000eb40, 0xa253a0, 0xc0001fdaa0, 0x9b0720, 0xf5e500)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/net/tcpsock.go:261 +0x64
        net/http.(*Server).Serve(0xc00016e0e0, 0xb45940, 0xc00000eb40, 0x0, 0x0)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/net/http/server.go:2901 +0x25d
        main.main.func2(0xc00016e0e0, 0xb45940, 0xc00000eb40, 0xc00004d4d0, 0xc00007e8c0, 0xc000048540)
        	/home/travis/gopath/pkg/mod/github.com/agnivade/wasmbrowsertest@v0.3.3/main.go:104 +0x43
        created by main.main
        	/home/travis/gopath/pkg/mod/github.com/agnivade/wasmbrowsertest@v0.3.3/main.go:103 +0x8db
        
        goroutine 10 [select]:
        os/exec.(*Cmd).Start.func2(0xc000120c60)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/os/exec/exec.go:444 +0xc4
        created by os/exec.(*Cmd).Start
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/os/exec/exec.go:443 +0x6a6
        
        goroutine 11 [chan receive]:
        github.com/chromedp/chromedp.(*ExecAllocator).Allocate.func2(0xb46b00, 0xc0001fd9b0, 0xc000120c60, 0xc000120c01, 0xc000206440, 0x1d, 0xc00013c370, 0xc00007ecd0)
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/allocate.go:199 +0x4c
        created by github.com/chromedp/chromedp.(*ExecAllocator).Allocate
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/allocate.go:198 +0xa4d
        
        goroutine 13 [select]:
        github.com/chromedp/chromedp.(*Browser).run(0xc0000ac000, 0xb46b00, 0xc0001fd9b0)
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/browser.go:262 +0x2b9
        created by github.com/chromedp/chromedp.NewBrowser
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/browser.go:109 +0x3f9
        
        goroutine 14 [chan receive]:
        github.com/chromedp/chromedp.(*ExecAllocator).Allocate.func4(0xc0000ac000, 0xc00013c370)
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/allocate.go:248 +0x38
        created by github.com/chromedp/chromedp.(*ExecAllocator).Allocate
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/allocate.go:244 +0xd0e
        
        goroutine 15 [IO wait]:
        internal/poll.runtime_pollWait(0x7f75c142ce38, 0x72, 0xffffffffffffffff)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/runtime/netpoll.go:203 +0x55
        internal/poll.(*pollDesc).wait(0xc0000b6198, 0x72, 0x0, 0xc, 0xffffffffffffffff)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/internal/poll/fd_poll_runtime.go:87 +0x45
        internal/poll.(*pollDesc).waitRead(...)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/internal/poll/fd_poll_runtime.go:92
        internal/poll.(*FD).Read(0xc0000b6180, 0xc00003c8f0, 0x2, 0xc, 0x0, 0x0, 0x0)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/internal/poll/fd_unix.go:169 +0x19b
        net.(*netFD).Read(0xc0000b6180, 0xc00003c8f0, 0x2, 0xc, 0x0, 0xc, 0xc00003c8f0)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/net/fd_unix.go:202 +0x4f
        net.(*conn).Read(0xc0000b4008, 0xc00003c8f0, 0x2, 0xc, 0x0, 0x0, 0x0)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/net/net.go:184 +0x8e
        io.ReadAtLeast(0xb3de40, 0xc0000b4008, 0xc00003c8f0, 0x2, 0xc, 0x2, 0x1, 0xc00006ad08, 0x44f45e)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/io/io.go:310 +0x87
        io.ReadFull(...)
        	/home/travis/.gimme/versions/go1.14.1.linux.amd64/src/io/io.go:329
        github.com/gobwas/ws.ReadHeader(0xb3de40, 0xc0000b4008, 0x0, 0x0, 0xa48220, 0xb3de40)
        	/home/travis/gopath/pkg/mod/github.com/gobwas/ws@v1.0.3/read.go:25 +0x97
        github.com/gobwas/ws/wsutil.(*Reader).NextFrame(0xc00000c5b0, 0x0, 0x0, 0xb3de40, 0xc0000b4008)
        	/home/travis/gopath/pkg/mod/github.com/gobwas/ws@v1.0.3/wsutil/reader.go:151 +0x57
        github.com/chromedp/chromedp.(*Conn).Read(0xc00000c5a0, 0xb46b00, 0xc0001fd9b0, 0xc0004b85a0, 0x0, 0x0)
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/conn.go:89 +0xfd
        github.com/chromedp/chromedp.(*Browser).run.func1(0xc0000ac000, 0xb46b00, 0xc0001fd9b0, 0xc0001a2e40, 0xc0001a2ea0)
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/browser.go:219 +0x82
        created by github.com/chromedp/chromedp.(*Browser).run
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/browser.go:216 +0x10a
        
        goroutine 16 [select]:
        github.com/chromedp/chromedp.(*Target).run(0xc000154480, 0xb46b00, 0xc0001fd9b0)
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/target.go:92 +0x151
        created by github.com/chromedp/chromedp.(*Context).attachTarget
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/chromedp.go:314 +0x2cd
        
        goroutine 34 [select]:
        github.com/chromedp/chromedp.(*Target).run.func1(0xb46b00, 0xc0001fd9b0, 0xc000154480, 0xc0001a33e0)
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/target.go:53 +0xec
        created by github.com/chromedp/chromedp.(*Target).run
        	/home/travis/gopath/pkg/mod/github.com/chromedp/chromedp@v0.5.3/target.go:51 +0x96
        
        rax    0xca
        rbx    0xf70d40
        rcx    0x465cf3
        rdx    0x0
        rdi    0xf70e88
        rsi    0x80
        rbp    0x7ffff225ecb0
        rsp    0x7ffff225ec68
        r8     0x0
        r9     0x0
        r10    0x0
        r11    0x286
        r12    0x3
        r13    0xf707e0
        r14    0xc00047ed80
        r15    0x0
        rip    0x465cf1
        rflags 0x286
        cs     0x33
        fs     0x0
        gs     0x0
FAIL
coverage: 86.1% of statements in ./...
FAIL	nhooyr.io/websocket	21.094s
?   	nhooyr.io/websocket/internal/bpool	[no test files]
?   	nhooyr.io/websocket/internal/errd	[no test files]
?   	nhooyr.io/websocket/internal/test	[no test files]
?   	nhooyr.io/websocket/internal/test/assert	[no test files]
?   	nhooyr.io/websocket/internal/test/wstest	[no test files]
?   	nhooyr.io/websocket/internal/test/xrand	[no test files]
ok  	nhooyr.io/websocket/internal/xsync	0.007s	coverage: 0.9% of statements in ./...
?   	nhooyr.io/websocket/wsjson	[no test files]
?   	nhooyr.io/websocket/wspb	[no test files]
FAIL
+1
nhooyr on Apr 8, 2020
Read more comments on GitHub
← node_mdns: Windows 7 Node v0.8.2 Build Fails
covalent: Error when parsing electron positional arguments in workflows →