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

Introduce a waitForScripting helper function and use it in all scripting integration tests #18405

Merged

Conversation

timvandermeij
Copy link
Contributor

Code inspection uncovered that quite a few integration tests don't wait for scripting to be ready before proceeding, which is a source of intermittent failures, especially on slower machines where e.g. creating the sandbox takes longer.

This commit fixes the issues by introducing a waitForScripting helper function and calling it consistently in all scripting integration tests.

Fixes a part of #18396.

…pting integration tests

Code inspection uncovered that quite a few integration tests don't wait
for scripting to be ready before proceeding, which is a source of
intermittent failures, especially on slower machines where e.g. creating
the sandbox takes longer.

This commit fixes the issues by introducing a `waitForScripting` helper
function and calling it consistently in all scripting integration tests.
@timvandermeij timvandermeij force-pushed the intermittent-waitforscripting branch from 0b4f04a to b540b63 Compare July 6, 2024 17:29
@timvandermeij
Copy link
Contributor Author

timvandermeij commented Jul 6, 2024

I have looked into the impact of this change with diff 1 from #18396 (comment). This idea is to bring tests that don't properly await scripting initialization to the surface by slowing down sandbox creation, similar to what would happen on a slower machine such as the Windows bot.

Before this patch running only the scripting integration tests with diff 1 applied resulted in 5 failures (note that we have seen some of them before on the bots):

Failures:
1) Interaction in js-authors.pdf must print authors in a text field
  Message:
    ProtocolError: Runtime.callFunctionOn timed out. Increase the 'protocolTimeout' setting in launch/connect calls for a higher timeout if needed.
  Stack:
        at <instance_members_initializer> (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:89:14)
        at new Callback (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:93:16)
        at CallbackRegistry.create (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:19:26)
        at Connection._rawSend (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/Connection.js:86:26)
        at CdpCDPSession.send (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/CDPSession.js:63:33)
        at #evaluate (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/ExecutionContext.js:353:50)
        at async ExecutionContext.evaluateHandle (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/ExecutionContext.js:320:16)
        at async IsolatedWorld.evaluateHandle (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/IsolatedWorld.js:85:16)
        at async CdpJSHandle.evaluateHandle (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/api/JSHandle.js:147:20)
        at async WaitTask.rerun (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/WaitTask.js:100:28)

2) Interaction in listbox_actions.pdf must print selected value in a text field
  Message:
    ProtocolError: Runtime.callFunctionOn timed out. Increase the 'protocolTimeout' setting in launch/connect calls for a higher timeout if needed.
  Stack:
        at <instance_members_initializer> (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:89:14)
        at new Callback (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:93:16)
        at CallbackRegistry.create (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:19:26)
        at Connection._rawSend (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/Connection.js:86:26)
        at CdpCDPSession.send (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/CDPSession.js:63:33)
        at #evaluate (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/ExecutionContext.js:353:50)
        at async ExecutionContext.evaluateHandle (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/ExecutionContext.js:320:16)
        at async IsolatedWorld.evaluateHandle (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/IsolatedWorld.js:85:16)
        at async CdpJSHandle.evaluateHandle (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/api/JSHandle.js:147:20)
        at async WaitTask.rerun (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/WaitTask.js:100:28)

3) Interaction in js-colors.pdf must change colors
  Message:
    ProtocolError: Runtime.callFunctionOn timed out. Increase the 'protocolTimeout' setting in launch/connect calls for a higher timeout if needed.
  Stack:
        at <instance_members_initializer> (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:89:14)
        at new Callback (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:93:16)
        at CallbackRegistry.create (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:19:26)
        at Connection._rawSend (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/Connection.js:86:26)
        at CdpCDPSession.send (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/CDPSession.js:63:33)
        at #evaluate (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/ExecutionContext.js:353:50)
        at async ExecutionContext.evaluateHandle (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/ExecutionContext.js:320:16)
        at async IsolatedWorld.evaluateHandle (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/IsolatedWorld.js:85:16)
        at async CdpJSHandle.evaluateHandle (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/api/JSHandle.js:147:20)
        at async WaitTask.rerun (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/WaitTask.js:100:28)

4) Interaction in secHandler.pdf must print securityHandler value in a text field
  Message:
    ProtocolError: Runtime.callFunctionOn timed out. Increase the 'protocolTimeout' setting in launch/connect calls for a higher timeout if needed.
  Stack:
        at <instance_members_initializer> (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:89:14)
        at new Callback (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:93:16)
        at CallbackRegistry.create (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:19:26)
        at Connection._rawSend (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/Connection.js:86:26)
        at CdpCDPSession.send (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/CDPSession.js:63:33)
        at #evaluate (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/ExecutionContext.js:353:50)
        at async ExecutionContext.evaluateHandle (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/ExecutionContext.js:320:16)
        at async IsolatedWorld.evaluateHandle (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/IsolatedWorld.js:85:16)
        at async CdpJSHandle.evaluateHandle (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/api/JSHandle.js:147:20)
        at async WaitTask.rerun (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/WaitTask.js:100:28)

5) Interaction in bug1844576.pdf must check that a field has the correct formatted value
  Message:
    ProtocolError: Waiting for selector `[data-annotation-id="9R"] > canvas[hidden]` failed: Runtime.callFunctionOn timed out. Increase the 'protocolTimeout' setting in launch/connect calls for a higher timeout if needed.
  Stack:
        at <instance_members_initializer> (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:89:14)
        at new Callback (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:93:16)
        at CallbackRegistry.create (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:19:26)
        at Connection._rawSend (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/Connection.js:86:26)
        at CdpCDPSession.send (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/CDPSession.js:63:33)
        at #evaluate (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/ExecutionContext.js:353:50)
        at async ExecutionContext.evaluateHandle (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/ExecutionContext.js:320:16)
        at async IsolatedWorld.evaluateHandle (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/cdp/IsolatedWorld.js:85:16)
        at async CdpJSHandle.evaluateHandle (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/api/JSHandle.js:147:20)
        at async WaitTask.rerun (file:///home/timvandermeij/Documenten/Ontwikkeling/pdf.js/Code/node_modules/puppeteer-core/lib/esm/puppeteer/common/WaitTask.js:100:28)
        
58 specs, 5 failures
Finished in 307.085 seconds

However, note that we are lucky with only 5 failures. There were quite a few more tests that didn't await scripting initialization, but those passed more-or-less "accidentally" because they are in the same describe block. If the first test in the describe block doesn't await scripting initialization it will time out after 30 seconds, but by that time scripting is initialized because that only got delayed by 2 seconds. This means that the next tests in the block will pass because we don't re-initialize the document between tests in the same describe block due to using beforeAll.

Therefore, the only reason there wasn't more breakage is because we always run the integration tests in a fixed order, which is in contrast to the unit tests that we run in a random order and which would be nice to fix later. If we would run them in a random order those tests can't depend on the first test in the block to fix this for them anymore. This patch therefore also gets rid of an implicit dependency in the tests, which is a step towards eventually randomizing them.

After this patch running only the scripting integration tests with diff 1 applied resulted in no failures anymore:

58 specs, 0 failures
Finished in 211.827 seconds

@timvandermeij
Copy link
Contributor Author

/botio integrationtest

@moz-tools-bot
Copy link
Collaborator

From: Bot.io (Windows)


Received

Command cmd_integrationtest from @timvandermeij received. Current queue size: 0

Live output at: http://54.193.163.58:8877/4c9b86873c4b736/output.txt

@moz-tools-bot
Copy link
Collaborator

From: Bot.io (Linux m4)


Received

Command cmd_integrationtest from @timvandermeij received. Current queue size: 0

Live output at: http://54.241.84.105:8877/c169167d256b2da/output.txt

@moz-tools-bot
Copy link
Collaborator

From: Bot.io (Linux m4)


Success

Full output at http://54.241.84.105:8877/c169167d256b2da/output.txt

Total script time: 7.95 mins

  • Integration Tests: Passed

@moz-tools-bot
Copy link
Collaborator

From: Bot.io (Windows)


Success

Full output at http://54.193.163.58:8877/4c9b86873c4b736/output.txt

Total script time: 16.84 mins

  • Integration Tests: Passed

Copy link
Contributor

@calixteman calixteman left a comment

Choose a reason for hiding this comment

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

LGTM. Thank you.

@calixteman calixteman merged commit 2a125bd into mozilla:master Jul 7, 2024
7 checks passed
@timvandermeij timvandermeij deleted the intermittent-waitforscripting branch July 7, 2024 12:15
@timvandermeij timvandermeij removed the request for review from Snuffleupagus July 7, 2024 12:15
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants