Add a queue per handler to keep events in order

[ankur22]

Events are sometimes out of order due to use using a goroutine to publish events to the handler concurrently as there's no guarantee when the goroutines will run (the first goroutine to be created isn't necessarily going to be the first to run). To overcome this, a queue has been added per handler to synchronise all publishes of events to that handler as well as a mutex so that only one emitEvent goroutine can read from the queue and write to the handler's channel at any one time.

We tried working with a buffered channel instead of a queue (which is a slice). Unfortunately it's difficult to determine how large the channel needs to be to work with the test -- the more complex the test, the more events that will be emitted. For now we think it is easier to work with a queue that can grow when needed.

After creating the unit tests, we found that although we were receiving events in order we had created a deadlock when a handler was receiving events and emitting new events. To overcome this we had to create a "double queue" system whereby new emitted events can be stored on one queue, while the emitEvent goroutines can read off of a separate queue. When the read queue is depleted, the queues are swapped around.

Closes: #553

[imiric]

Hey, nicely done! From my local tests your change seems to work 👍

Do you think it would be possible to have tests for this? The previous behavior was flaky, so not sure how easily reproducible it is. Worth a try?

[inancgumus]

Nice idea, @ankur22! 👏 This ensures that the handlers receive emitted events in order.

One question: How can we be sure that this PR fixes the issue in #553 and maybe #482 or #427 or #496? I'm unsure whether we were aiming to fix them with this PR, though :)?

By the way, I ran this PR's tests on CI a few times, and there were errors (1, 2, 3). Also, locally, I received the following error:

time="2022-10-03T10:52:42+03:00" level=error msg="process with PID 72688 unexpectedly ended: signal: killed" category=browser elapsed="0 ms" goroutine=99722
--- FAIL: TestLocator (39.38s)
    --- FAIL: TestLocator/Tap (1.63s)
        locator_test.go:188: 
                Error Trace:    /Users/inanc/grafana/xk6-browser/tests/locator_test.go:188
                Error:          Expected value not to be nil.
                Test:           TestLocator/Tap
    --- FAIL: TestLocator/Click (30.62s)
    cleanup panicked with closing the browser: sending a message to browser: websocket: close 1006 (abnormal closure): unexpected EOFpanic: clicking on "#link": timed out after 30s [recovered]
        panic: clicking on "#link": timed out after 30s

WDYT about these errors? Do you believe they're related to this PR?

[ankur22]

Do you think it would be possible to have tests for this? The previous behavior was flaky, so not sure how easily reproducible it is. Worth a try?

Good idea, I'll try.

[ankur22]

One question: How can we be sure that this PR fixes the issue in #553 and maybe #482 or #427 or #496? I'm unsure whether we were aiming to fix them with this PR, though :)?

The aim here is to ensure that the ordering of the CDP events is maintained and the handlers receive the events in order. I'll create a test that breaks under what currently exists, and hopefully that same test will pass with whatever the fix is. Although, I think #482 and #496 should be resolved by whatever this fix is 🤞

By the way, I ran this PR's tests on CI a few times

🤔 1 and 3 are worrying, and I'll need to investigate those.

2 and the TestLocator/Tap error are a concern for us but I run into those often when running the Locator tests even on main. I believe they're caused by some sort of race issue, but not to do with the out of order CDP events.

[ankur22]

Do you think it would be possible to have tests for this? The previous behavior was flaky, so not sure how easily reproducible it is. Worth a try?

Good idea, I'll try.

Unit tests added. I verified that out of the two tests, the test that ensures that events are received in order fails in main.

[imiric]

Excellent work, Ankur! 👏

It took me a while to get the double queue approach, but it makes sense.

The tests are a great touch, and I also confirmed the order one fails on main. 👍

I ran this with several of our examples, which worked great, and with the Vistaprint script, which needs to be rewritten to use the new async APIs, but at least it didn't regress compared to main. 😅

Let's create a Cloud release when this is merged, so that it can be battle tested.

[inancgumus]

@Ankur Awesome work, thanks for this! 👏

I ran the CI tests multiple times, they worked fabulously, thanks to you.

On the 3rd run, I saw the following error in this CI job:

=== CONT  TestWaitForFrameNavigationWithinDocument/anchor
    frame_manager_test.go:46: 
        	Error Trace:	/home/runner/work/xk6-browser/xk6-browser/tests/frame_manager_test.go:46
        	            				/home/runner/work/xk6-browser/xk6-browser/tests/asm_amd64.s:1571
        	Error:      	Expected value not to be nil.
        	Test:       	TestWaitForFrameNavigationWithinDocument/anchor

I believe this one might be related to #560 or the previous related issues. I think it is not related to #553. Then again, I wanted to let you know (in case you may have an idea).

I also saw the following error when I ran the tests locally:

--- FAIL: TestLocator (1.00s)
    locator_test.go:271: 
                Error Trace:    /Users/inanc/grafana/xk6-browser/tests/locator_test.go:271
                Error:          Expected value not to be nil.
                Test:           TestLocator

This one is related to the previous error I explained above. The origin of both errors seems to be page.Goto. Although, #560 is about a timeout error, after this change, the underlying problem with page.Goto might have reached the surface.

[inancgumus]

Thanks for making all of our lives easier 🎉

[ankur22]

@Ankur Awesome work, thanks for this! 👏

I ran the CI tests multiple times, they worked fabulously, thanks to you.

On the 3rd run, I saw the following error in this CI job:

=== CONT  TestWaitForFrameNavigationWithinDocument/anchor
    frame_manager_test.go:46: 
        	Error Trace:	/home/runner/work/xk6-browser/xk6-browser/tests/frame_manager_test.go:46
        	            				/home/runner/work/xk6-browser/xk6-browser/tests/asm_amd64.s:1571
        	Error:      	Expected value not to be nil.
        	Test:       	TestWaitForFrameNavigationWithinDocument/anchor

I believe this one might be related to #560 or the previous related issues. I think it is not related to #553. Then again, I wanted to let you know (in case you may have an idea).

I also saw the following error when I ran the tests locally:

--- FAIL: TestLocator (1.00s)
    locator_test.go:271: 
                Error Trace:    /Users/inanc/grafana/xk6-browser/tests/locator_test.go:271
                Error:          Expected value not to be nil.
                Test:           TestLocator

This one is related to the previous error I explained above. The origin of both errors seems to be page.Goto. Although, #560 is about a timeout error, after this change, the underlying problem with page.Goto might have reached the surface.

Thanks @inancgumus!

I've taken a look at those errors before actually, and unfortunately they are race conditions unrelated to unordered CDP events. I did start to look into them a couple of months ago before the deadlock cloud issue was prioritised over other issues. I'd be happy to look into these next though as they're a real PITA when stress testing locally, and obviously a pain in CI -- i had to comment out a lot of tests since they kept failing in response being nil when they shouldn't have been 😭

[ankur22]

🤔 1 and 3 are worrying, and I'll need to investigate those.

These errors occurred prior to adding in the "double queue" system for managing the read and write of events from different goroutines. When using a single queue, it would deadlock, which is what those test runs showed us. Those same deadlocks shouldn't happen now with the "double queue" system (i've done stress tests locally and not had a deadlock so far).