Problems
Sorted from real problem to nice-to-have:
- Unhandled error path: If the webassembly module fails to instantiate via instantiateStreaming the Done button is never enabled because when the WASM file failed to instantiate it skipped setting the done button. That in turn leads to the program waiting on the
chromedp.WaitEnabled
command until the test times out.
- Logging & Debugging: When this happens, there is virtually no debugging information available.
Solutions
- A console error is being logged but it is insufficient to stop the tests from running. In the event of such a failure, use logger.Fatal since it means wasmbrowsertest itself is failing.
- First, func handleEvent in main.go was using "fmt.Print" instead of logger.Printf, which caused problems for whatever reason. Second, in
case *cdpruntime.EventConsoleAPICalled
it was assumed the error would be a number. I can add a new case specifically for console.Error which helps with this.
I also created a 'DEBUG' option which contained the information I needed to debug the problems I was running in to; presumably such a thing will be helpful for someone else in the future.
What the changes look like on WSL, where the program seems to hang
With DEBUG=on
DEBUG=on ./wasmbrowsertest ./testdata/test.wasm
2020/02/07 12:18:43 browser log: {"id":1,"method":"Target.setDiscoverTargets","params":{"discover":true}}
2020/02/07 12:18:43 browser log: {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"755af249-070b-4a9f-b918-8daa8399581a","type":"browser","title":"","url":"","attached":false}}}
2020/02/07 12:18:43 browser log: {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"A63CE0F5C34057F27BDCA988F2A7F6C7","type":"page","title":"","url":"about:blank","attached":false,"browserContextId":"C7E01B11619625966EC22D59BBA95FC0"}}}
2020/02/07 12:18:43 browser log: {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"e1bb48d1-6ee2-45fc-958d-a4d9c020fda4","type":"browser","title":"","url":"","attached":true}}}
2020/02/07 12:18:43 browser log: {"id":1,"result":{}}
2020/02/07 12:18:43 browser log: {"id":2,"method":"Target.attachToTarget","params":{"targetId":"A63CE0F5C34057F27BDCA988F2A7F6C7"}}
2020/02/07 12:18:43 browser log: {"method":"Target.targetInfoChanged","params":{"targetInfo":{"targetId":"A63CE0F5C34057F27BDCA988F2A7F6C7","type":"page","title":"","url":"about:blank","attached":true,"browserContextId":"C7E01B11619625966EC22D59BBA95FC0"}}}
2020/02/07 12:18:43 browser log: {"method":"Target.attachedToTarget","params":{"sessionId":"2D0E92901307FDDD0989795EAD93A074","targetInfo":{"targetId":"A63CE0F5C34057F27BDCA988F2A7F6C7","type":"page","title":"","url":"about:blank","attached":true,"browserContextId"
:"C7E01B11619625966EC22D59BBA95FC0"},"waitingForDebugger":false}}
2020/02/07 12:18:43 browser log: {"id":2,"result":{"sessionId":"2D0E92901307FDDD0989795EAD93A074"}}
2020/02/07 12:18:43 browser log: {"id":4,"method":"Target.sendMessageToTarget","params":{"message":"{\"id\":3,\"method\":\"Log.enable\"}","sessionId":"2D0E92901307FDDD0989795EAD93A074"}}
2020/02/07 12:18:43 browser log: {"id":4,"result":{}}
[the output continued...]
With DEBUG=off it can seem to hang:
[email protected]:/mnt/c/Users/gledr/Polyapp_Apps/gocode/src/github.com/agnivade/wasmbrowsertest$ DEBUG=off ./wasmbrowsertest ./testdata/test.wasm
^C
Running on Windows, where the program works
DEBUG=off
C:\Users\gledr\Polyapp_Apps\gocode\src\github.com\agnivade\wasmbrowsertest>wasmbrowsertest.exe ./testdata/test.wasm
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: panic: syscall/js: Value.Call: property _makeFuncWrapper is not a function, got undefined
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241:
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: goroutine 1 [running]:
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: syscall/js.Value.Call(0x7ff8000000000007, 0x4e248, 0x10, 0xc063bc8, 0x1, 0x1, 0x10)
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: /usr/local/go/src/syscall/js/js.go:299 +0x87
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: syscall/js.FuncOf(0xc00e480, 0xc00e480, 0xc03c1e0)
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: /usr/local/go/src/syscall/js/func.go:46 +0xa
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: syscall.fsCall(0x4c22f, 0x5, 0xc063cf0, 0x5, 0x5, 0xc072040, 0x4bf93, 0x4)
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: /usr/local/go/src/syscall/fs_js.go:477 +0x6
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: syscall.Write(0x1, 0xc01c0e8, 0x5, 0x8, 0x54ab0, 0xc000180, 0x14370004)
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: /usr/local/go/src/syscall/fs_js.go:397 +0xc
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: internal/poll.(*FD).Write(0xc03c0c0, 0xc01c0e8, 0x5, 0x8, 0x0, 0x0, 0x0)
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: /usr/local/go/src/internal/poll/fd_unix.go:268 +0x21
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: os.(*File).write(...)
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: /usr/local/go/src/os/file_unix.go:280
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: os.(*File).Write(0xc00c020, 0xc01c0e8, 0x5, 0x8, 0x0, 0xc01a1e0, 0x10ac0004)
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: /usr/local/go/src/os/file.go:145 +0xf
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: fmt.Fprintln(0x6da40, 0xc00c020, 0xc063ee8, 0x1, 0x1, 0x2, 0x1, 0xc06c000)
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: /usr/local/go/src/fmt/print.go:266 +0x8
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: fmt.Println(...)
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: /usr/local/go/src/fmt/print.go:275
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: testing.(*M).Run(0xc06c000, 0x0)
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: /usr/local/go/src/testing/testing.go:1083 +0x31
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: main.main()
[wasmbrowsertest]: 2020/02/07 12:22:54 main.go:241: _testmain.go:50 +0xe
[wasmbrowsertest]: 2020/02/07 12:22:59 main.go:178: context deadline exceeded
C:\Users\gledr\Polyapp_Apps\gocode\src\github.com\agnivade\wasmbrowsertest>
DEBUG=on
C:\Users\gledr\Polyapp_Apps\gocode\src\github.com\agnivade\wasmbrowsertest>wasmbrowsertest.exe ./testdata/test.wasm
2020/02/07 12:24:23 browser log: {"id":1,"method":"Target.setDiscoverTargets","params":{"discover":true}}
2020/02/07 12:24:23 browser log: {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"1bbfbedc-9a89-4465-b1f4-83aa72889b7c","type":"browser","title":"","url":"","attached":true}}}
2020/02/07 12:24:23 browser log: {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"50428D1AA16D99A04CBDD84E9D90B920","type":"page","title":"","url":"about:blank","attached":false,"browserContextId":"6F575330AD73032CD7862515A656A644"}}}
2020/02/07 12:24:23 browser log: {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"58e2edef-7c49-4ed5-af05-a3f1b3213413","type":"browser","title":"","url":"","attached":false}}}
2020/02/07 12:24:23 browser log: {"id":1,"result":{}}
2020/02/07 12:24:23 browser log: {"id":2,"method":"Target.attachToTarget","params":{"targetId":"50428D1AA16D99A04CBDD84E9D90B920"}}
2020/02/07 12:24:23 browser log: {"method":"Target.targetInfoChanged","params":{"targetInfo":{"targetId":"50428D1AA16D99A04CBDD84E9D90B920","type":"page","title":"","url":"about:blank","attached":true,"browserContextId":"6F575330AD73032CD7862515A656A644"}}}
2020/02/07 12:24:23 browser log: {"method":"Target.attachedToTarget","params":{"sessionId":"635E07B8B2999ECD6436F96FA18AF099","targetInfo":{"targetId":"50428D1AA16D99A04CBDD84E9D90B920","type":"page","title":"","url":"about:blank","attached":true,"browserContextId":"6F575330AD73032CD7862515A656A644"},"waitingForDebugger":false}}
2020/02/07 12:24:23 browser log: {"id":2,"result":{"sessionId":"635E07B8B2999ECD6436F96FA18AF099"}}
2020/02/07 12:24:23 browser log: {"id":4,"method":"Target.sendMessageToTarget","params":{"message":"{\"id\":3,\"method\":\"Log.enable\"}","sessionId":"635E07B8B2999ECD6436F96FA18AF099"}}
2020/02/07 12:24:23 browser log: {"id":4,"result":{}}
output continued...
[wasmbrowsertest]: 2020/02/07 12:24:24 main.go:241: /usr/local/go/src/syscall/fs_js.go:477 +0x6
2020/02/07 12:24:24 browser log: {"method":"Target.receivedMessageFromTarget","params":{"sessionId":"635E07B8B2999ECD6436F96FA18AF099","message":"{\"method\":\"Runtime.consoleAPICalled\",\"params\":{\"type\":\"log\",\"args\":[{\"type\":\"string\",\"value\":\"\\t_testmain.go:50 +0xe\"}],\"executionContextId\":2,\"timestamp\":1581099864049.165,\"stackTrace\":{\"callFrames\":[{\"functionName\":\"writeSync\",\"scriptId\":\"3\",\"url\":\"http://localhost:61758/wasm_exec.js\",\"lineNumber\":40,\"columnNumber\":13},{\"functionName\":\"runtime.wasmWrite\",\"scriptId\":\"3\",\"url\":\"http://localhost:61758/wasm_exec.js\",\"lineNumber\":247,\"columnNumber\":9},{\"functionName\":\"runtime.wasmWrite\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":940,\"columnNumber\":794847},{\"functionName\":\"runtime.write\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":449,\"columnNumber\":393933},{\"functionName\":\"runtime.writeErr\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":808,\"columnNumber\":754824},{\"functionName\":\"runtime.gwrite\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":484,\"columnNumber\":418290},{\"functionName\":\"runtime.printstring\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":494,\"columnNumber\":422490},{\"functionName\":\"runtime.printnl\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":486,\"columnNumber\":418914},{\"functionName\":\"runtime.gentraceback\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":773,\"columnNumber\":701854},{\"functionName\":\"runtime.traceback1\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":779,\"columnNumber\":714840},{\"functionName\":\"runtime.traceback\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":778,\"columnNumber\":714129},{\"functionName\":\"runtime.dopanic_m\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":479,\"columnNumber\":415364},{\"functionName\":\"runtime.fatalpanic.func1\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":856,\"columnNumber\":775565},{\"functionName\":\"runtime.systemstack\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":880,\"columnNumber\":783937},{\"functionName\":\"runtime.fatalpanic\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":477,\"columnNumber\":412556},{\"functionName\":\"runtime.gopanic\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":470,\"columnNumber\":408514},{\"functionName\":\"syscall_js.Value.Call\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":1122,\"columnNumber\":877261},{\"functionName\":\"syscall_js.FuncOf\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":1109,\"columnNumber\":863358},{\"functionName\":\"syscall.fsCall\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":1176,\"columnNumber\":911155},{\"functionName\":\"syscall.Write\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":1172,\"columnNumber\":907110},{\"functionName\":\"internal_poll.__FD_.Write\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":1257,\"columnNumber\":988940},{\"functionName\":\"os.__File_.Write\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":1271,\"columnNumber\":999354},{\"functionName\":\"fmt.Fprintln\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":1896,\"columnNumber\":1418366},{\"functionName\":\"testing.__M_.Run\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":2074,\"columnNumber\":1630924},{\"functionName\":\"wasm_pc_f_loop\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":925,\"columnNumber\":794310},{\"functionName\":\"wasm_export_run\",\"scriptId\":\"5\",\"url\":\"\",\"lineNumber\":923,\"columnNumber\":794277},{\"functionName\":\"run\",\"scriptId\":\"3\",\"url\":\"http://localhost:61758/wasm_exec.js\",\"lineNumber\":474,\"columnNumber\":22},{\"functionName\":\"\",\"scriptId\":\"4\",\"url\":\"http://localhost:61758/\",\"lineNumber\":93,\"columnNumber\":12}]}}}","targetId":"50428D1AA16D99A04CBDD84E9D90B920"}}
[wasmbrowsertest]: 2020/02/07 12:24:24 main.go:241: syscall.Write(0x1, 0xc01a0f0, 0x5, 0x8, 0x54ab0, 0xc000180, 0x14370004)
2020/02/07 12:24:24 browser log: {"method":"Target.receivedMessageFromTarget","params":{"sessionId":"635E07B8B2999ECD6436F96FA18AF099","message":"{\"method\":\"DOM.attributeRemoved\",\"params\":{\"nodeId\":14,\"name\":\"disabled\"}}","targetId":"50428D1AA16D99A04CBDD84E9D90B920"}}
2020/02/07 12:24:24 browser log: {"method":"Target.receivedMessageFromTarget","params":{"sessionId":"635E07B8B2999ECD6436F96FA18AF099","message":"{\"id\":53,\"result\":{\"searchId\":\"29664.7\",\"resultCount\":1}}","targetId":"50428D1AA16D99A04CBDD84E9D90B920"}}
[wasmbrowsertest]: 2020/02/07 12:24:24 main.go:241: /usr/local/go/src/syscall/fs_js.go:397 +0xc
[wasmbrowsertest]: 2020/02/07 12:24:24 main.go:241: internal/poll.(*FD).Write(0xc03c0c0, 0xc01a0f0, 0x5, 0x8, 0x0, 0x0, 0x0)
[wasmbrowsertest]: 2020/02/07 12:24:24 main.go:241: /usr/local/go/src/internal/poll/fd_unix.go:268 +0x21
[wasmbrowsertest]: 2020/02/07 12:24:24 main.go:241: os.(*File).write(...)
[wasmbrowsertest]: 2020/02/07 12:24:24 main.go:241: /usr/local/go/src/os/file_unix.go:280
[wasmbrowsertest]: 2020/02/07 12:24:24 main.go:241: os.(*File).Write(0xc00c020, 0xc01a0f0, 0x5, 0x8, 0x0, 0xc01c1e0, 0x10ac0004)
[wasmbrowsertest]: 2020/02/07 12:24:24 main.go:241: /usr/local/go/src/os/file.go:145 +0xf
[wasmbrowsertest]: 2020/02/07 12:24:24 main.go:241: fmt.Fprintln(0x6da40, 0xc00c020, 0xc063ee8, 0x1, 0x1, 0x2, 0x1, 0xc06c000)
[wasmbrowsertest]: 2020/02/07 12:24:24 main.go:241: /usr/local/go/src/fmt/print.go:266 +0x8
[wasmbrowsertest]: 2020/02/07 12:24:24 main.go:241: fmt.Println(...)
[wasmbrowsertest]: 2020/02/07 12:24:24 main.go:241: /usr/local/go/src/fmt/print.go:275
[wasmbrowsertest]: 2020/02/07 12:24:24 main.go:241: testing.(*M).Run(0xc06c000, 0x0)
[wasmbrowsertest]: 2020/02/07 12:24:24 main.go:241: /usr/local/go/src/testing/testing.go:1083 +0x31
[wasmbrowsertest]: 2020/02/07 12:24:24 main.go:241: main.main()
[wasmbrowsertest]: 2020/02/07 12:24:24 main.go:241: _testmain.go:50 +0xe
2020/02/07 12:24:24 browser log: {"id":56,"method":"Target.sendMessageToTarget","params":{"message":"{\"id\":55,\"method\":\"DOM.getSearchResults\",\"params\":{\"searchId\":\"29664.7\",\"fromIndex\":0,\"toIndex\":1}}","sessionId":"635E07B8B2999ECD6436F96FA18AF099"}}
2020/02/07 12:24:24 browser log: {"id":56,"result":{}}
2020/02/07 12:24:24 browser log: {"method":"Target.receivedMessageFromTarget","params":{"sessionId":"635E07B8B2999ECD6436F96FA18AF099","message":"{\"id\":55,\"result\":{\"nodeIds\":[14]}}","targetId":"50428D1AA16D99A04CBDD84E9D90B920"}}
2020/02/07 12:24:24 browser log: {"id":58,"method":"Target.sendMessageToTarget","params":{"message":"{\"id\":57,\"method\":\"Runtime.evaluate\",\"params\":{\"expression\":\"exitCode;\",\"returnByValue\":true}}","sessionId":"635E07B8B2999ECD6436F96FA18AF099"}}
2020/02/07 12:24:24 browser log: {"id":58,"result":{}}
2020/02/07 12:24:24 browser log: {"method":"Target.receivedMessageFromTarget","params":{"sessionId":"635E07B8B2999ECD6436F96FA18AF099","message":"{\"id\":57,\"result\":{\"result\":{\"type\":\"number\",\"value\":2,\"description\":\"2\"}}}","targetId":"50428D1AA16D99A04CBDD84E9D90B920"}}
[wasmbrowsertest]: 2020/02/07 12:24:29 main.go:178: context deadline exceeded
C:\Users\gledr\Polyapp_Apps\gocode\src\github.com\agnivade\wasmbrowsertest>