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.

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

fix: handle wasm module loading failure and improve logging and perfo… #13

Closed
wants to merge 3 commits into from
Closed

fix: handle wasm module loading failure and improve logging and perfo… #13

wants to merge 3 commits into from

Conversation

Gregory-Ledray
Copy link
Contributor

@Gregory-Ledray Gregory-Ledray commented Feb 5, 2020

Problems

Sorted from real problem to nice-to-have:

  1. 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.
  2. Logging & Debugging: When this happens, there is virtually no debugging information available.

Solutions

  1. 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.
  2. 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:

greg@LAPTOP-AH6IAHBO:/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>

@Gregory-Ledray
Copy link
Contributor Author

I've been using git diff 063d0778d7520c6da44e1a9cd50aa983fe695d6d to review these changes vs. master since things are messy with 2 PRs going on at once. If you want, I can squash these changes too, or I think there should be a button to do it when merging to master.

Copy link
Owner

@agnivade agnivade left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hey, thanks for the PR, and sorry for the delay.

Let me add some context to the fmt.Printf decision. The idea is that this tool should print the log lines exactly the way "go test" runs a test. i.e. you should not realize a browser is running the test for you. If we change to logger.Printf, that defeats the purpose.

Secondly, I totally agree that it's a bug when the test doesn't stop if the instantiation fails. But I'm not sure if your solution is the right approach here. A console error is an error, which should be logged, not an exception. What I had in mind was to actually throw an exception if the file didn't load/initialize properly, then do a chromedp.Cancel(ctx) in the *cdpruntime.EventExceptionThrown case. I don't see any reason to keep the program running if a javascript exception was thrown.

Regarding adding debug logging, it's something that's definitely needed. But I don't want to add yet another env variable for it. Instead, let's overload the -v flag for it. And have a deeper option like -v=2 to enable the debug logging.

Thoughts ?

@Gregory-Ledray
Copy link
Contributor Author

Gregory-Ledray commented Feb 23, 2020 via email

@agnivade
Copy link
Owner

as long as what you've suggested will eventually be compatible with
making the output JSON just like how I think there's a JSON flag for go
test

Not sure I fully understand this. I was talking about fmt.Printf vs log.Printf. The debug logging is in JSON but that's a different topic.

I used a console error because it's a recoverable and even expected case I
want to be able to test for my E2E tests

Yes that's the point. But here you were using a console error and making it irrecoverable. That's why I wanted to change it to an exception.

@Gregory-Ledray
Copy link
Contributor Author

Gregory-Ledray commented Feb 25, 2020

For JSON, I was thinking about go test -json which I guess is used with this:
https://golang.org/cmd/test2json/

It would be nice if the output of wasmbrowsertest could also be piped to test2json including debugging information. I have no personal need for that, but I imagine someone will want it some day. I switched over to logger in part because I imagine some day the print calls will get wrapped in a function call which either logs as it currently does or logs in a way which is compatible with test2json, and at that point I assume someone would refactor the code to all use logger calls or all use fmt calls - keeping both is possible but seems odd to me to log some errors in handleEvent with fmt.Printf but others - like chromedp.Cancel errors - with logger.Printf.

I didn't realize console.xyz is all the same thing just with different styling - I just assumed console.error did something more useful than changing the printed color in the console. Anyway throwing an exception and handling it in handleEvent sounds fine.

Verbose-flag wise, it looks like a boolean in go help build so I'm not excited about making it a int flag in wasmbrowsertest:

        -v
                print the names of packages as they are compiled.

I'd rather give developers basically no output (as currently happens) and then when you add -v just dump out everything a developer could possibly need.

@agnivade
Copy link
Owner

Yeah let me put some more thought into the -v flag. Agree with you on other points. I havent found a good way to differentiate internal logs with go test logs.

Closing this one for now then. Thanks very much for the discussion and the ideas.

@agnivade agnivade closed this Feb 25, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants