[Bug]: Intermittent failures in the reorganize pages integration tests

[timvandermeij]

Attach (recommended) or Link to PDF file

N/A

Web browser and its version

Firefox 150.0

Operating system and its version

Arch Linux

PDF.js version

5.7.284 (and master)

Is the bug present in the latest PDF.js version?

Yes

Is a browser extension

No

Steps to reproduce the problem

1. Run the integration tests.
2. Notice the following intermittent failures in the reorganize pages integration tests:

Failures:
1) Reorganize Pages View Drag & Drop should reorder thumbnails after dropping
  Message:
    ProtocolError: script.callFunction timed out. Increase the 'protocolTimeout' setting in launch/connect calls for a higher timeout if needed.
  Stack:
        at <instance_members_initializer> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:99:14)
        at new Callback (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:103:16)
        at CallbackRegistry.create (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:22:26)
        at BidiConnection.send (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Connection.js:70:32)
        at Session.send (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/core/Session.js:134:42)
        at Session.<anonymous> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/util/decorators.js:101:27)
        at WindowRealm.callFunction (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/core/Realm.js:92:51)
        at WindowRealm.<anonymous> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/util/decorators.js:101:27)
        at #evaluate (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Realm.js:136:42)
        at BidiFrameRealm.evaluate (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Realm.js:106:36)

2) Reorganize Pages View Drag & Drop should reorder thumbnails after dropping two non-adjacent pages
  Message:
    In firefox:
        Expected $[0] = 1 to equal 2.
        Expected $[1] = 14 to equal 1.
        Expected $[2] = 2 to equal 14.
  Stack:
        at <Jasmine>
        at file:///home/runner/work/pdf.js/pdf.js/test/integration/reorganize_pages_spec.mjs:326:14
        at async Promise.all (index 0)
        at async UserContext.<anonymous> (file:///home/runner/work/pdf.js/pdf.js/test/integration/reorganize_pages_spec.mjs:297:7)
  Message:
    In chrome:
        Expected $[0] = 1 to equal 2.
        Expected $[1] = 14 to equal 1.
        Expected $[2] = 2 to equal 14.
  Stack:
        at <Jasmine>
        at file:///home/runner/work/pdf.js/pdf.js/test/integration/reorganize_pages_spec.mjs:326:14
        at runNextTicks (node:internal/process/task_queues:65:5)
        at listOnTimeout (node:internal/timers:567:9)
        at process.processTimers (node:internal/timers:541:7)
  Message:
    Error: Waiting failed
  Stack:
    error properties: Object({ cause: ProtocolError: script.callFunction timed out. Increase the 'protocolTimeout' setting in launch/connect calls for a higher timeout if needed. })
        at <instance_members_initializer> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/WaitTask.js:21:21)
        at new WaitTask (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/WaitTask.js:27:16)
        at BidiFrameRealm.waitForFunction (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/api/Realm.js:49:26)
        at BidiFrame.waitForFunction (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/api/Frame.js:580:43)
        at BidiFrame.<anonymous> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/util/decorators.js:101:27)
        at BidiPage.waitForFunction (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/api/Page.js:1447:37)
        at waitForHavingContents (file:///home/runner/work/pdf.js/pdf.js/test/integration/reorganize_pages_spec.mjs:92:15)
        at async file:///home/runner/work/pdf.js/pdf.js/test/integration/reorganize_pages_spec.mjs:327:11
        at async Promise.all (index 0)
        at async UserContext.<anonymous> (file:///home/runner/work/pdf.js/pdf.js/test/integration/reorganize_pages_spec.mjs:297:7)
    Caused by: ProtocolError: script.callFunction timed out. Increase the 'protocolTimeout' setting in launch/connect calls for a higher timeout if needed.
        at <instance_members_initializer> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:99:14)
        at new Callback (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:103:16)
        at CallbackRegistry.create (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:22:26)
        at BidiConnection.send (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Connection.js:70:32)
        at Session.send (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/core/Session.js:134:42)
        at Session.<anonymous> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/util/decorators.js:101:27)
        at WindowRealm.callFunction (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/core/Realm.js:92:51)
        at WindowRealm.<anonymous> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/util/decorators.js:101:27)
        at #evaluate (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Realm.js:136:42)
        at BidiFrameRealm.evaluateHandle (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Realm.js:103:36)

3) Reorganize Pages View Drag & Drop should select the dropped page (bug 2010820)
  Message:
    ProtocolError: script.callFunction timed out. Increase the 'protocolTimeout' setting in launch/connect calls for a higher timeout if needed.
  Stack:
        at <instance_members_initializer> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:99:14)
        at new Callback (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:103:16)
        at CallbackRegistry.create (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:22:26)
        at BidiConnection.send (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Connection.js:70:32)
        at Session.send (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/core/Session.js:134:42)
        at Session.<anonymous> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/util/decorators.js:101:27)
        at WindowRealm.callFunction (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/core/Realm.js:92:51)
        at WindowRealm.<anonymous> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/util/decorators.js:101:27)
        at #evaluate (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Realm.js:136:42)
        at BidiFrameRealm.evaluate (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Realm.js:106:36)

4) Reorganize Pages View Save a pdf should check that a save is triggered
  Message:
    ProtocolError: script.callFunction timed out. Increase the 'protocolTimeout' setting in launch/connect calls for a higher timeout if needed.
  Stack:
        at <instance_members_initializer> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:99:14)
        at new Callback (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:103:16)
        at CallbackRegistry.create (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:22:26)
        at BidiConnection.send (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Connection.js:70:32)
        at Session.send (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/core/Session.js:134:42)
        at Session.<anonymous> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/util/decorators.js:101:27)
        at WindowRealm.callFunction (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/core/Realm.js:92:51)
        at WindowRealm.<anonymous> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/util/decorators.js:101:27)
        at #evaluate (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Realm.js:136:42)
        at BidiFrameRealm.evaluate (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Realm.js:106:36)

5) Reorganize Pages View Undo after drag-and-drop move followed by delete restores correct page mapping should restore the post-move mapping when undoing a delete
  Message:
    ProtocolError: script.callFunction timed out. Increase the 'protocolTimeout' setting in launch/connect calls for a higher timeout if needed.
  Stack:
        at <instance_members_initializer> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:99:14)
        at new Callback (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:103:16)
        at CallbackRegistry.create (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:22:26)
        at BidiConnection.send (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Connection.js:70:32)
        at Session.send (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/core/Session.js:134:42)
        at Session.<anonymous> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/util/decorators.js:101:27)
        at WindowRealm.callFunction (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/core/Realm.js:92:51)
        at WindowRealm.<anonymous> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/util/decorators.js:101:27)
        at #evaluate (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Realm.js:136:42)
        at BidiFrameRealm.evaluate (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Realm.js:106:36)

6) Reorganize Pages View Selection counter must be cleared after drag-and-drop (bug 2022884) should hide the selection counter after dropping selected pages
  Message:
    ProtocolError: script.callFunction timed out. Increase the 'protocolTimeout' setting in launch/connect calls for a higher timeout if needed.
  Stack:
        at <instance_members_initializer> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:99:14)
        at new Callback (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:103:16)
        at CallbackRegistry.create (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/common/CallbackRegistry.js:22:26)
        at BidiConnection.send (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Connection.js:70:32)
        at Session.send (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/core/Session.js:134:42)
        at Session.<anonymous> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/util/decorators.js:101:27)
        at WindowRealm.callFunction (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/core/Realm.js:92:51)
        at WindowRealm.<anonymous> (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/util/decorators.js:101:27)
        at #evaluate (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Realm.js:136:42)
        at BidiFrameRealm.evaluate (file:///home/runner/work/pdf.js/pdf.js/node_modules/puppeteer-core/lib/esm/puppeteer/bidi/Realm.js:106:36)

What is the expected behavior?

The integration tests should pass consistently.

What went wrong?

The integration tests fail intermittently.

Link to a viewer

No response

Additional context

No response

[timvandermeij]

The common denominator for the failing integration tests is that they all rely on drag-and-drop functionality, and debugging in #21173 (where the coverage addition turned the intermittents into permafails due to timing differences) provided the following observations:

• The failing tests hang on awaiting the result of the drag-and-drop action, which is usually the pagesedited event.
• This event is not fired because in #onStopDragging, in the thumbnail viewer code, we skip over the branch that emits it due to lastDraggedOverIndex being -1.
• It's set to that value in #findClosestThumbnail, which in turn fails to set the correct number because #isOneColumnView is false (the default), however that is incorrect because in the integration tests we do in fact have a single-column view.
• The #isOneColumnView value should be set correctly by #computeThumbnailsPosition, but there the issue is that this._thumbnails.length is 0.

In short, what happens is that #computeThumbnailsPosition is called before the thumbnails are actually ready, and causes incorrect state to be set internally, which begs the question how this method can be called prematurely. It turns out that the premature call happens due to a resize event being put on the event bus, which happens in the views manager to trigger thumbnail rendering after the views manager is done resizing (via e.g. animations when the toggle button is pressed).

The problem is therefore that the sidebar is opened, and resize finishes, before the thumbnails are actually ready. The latter happens in setDocument of the thumbnail viewer, and there we see that it depends on the first page being ready. However, this is what we don't await in the integration tests: we only wait until the toggle button is visible and then immediately proceed.

The total flow is therefore:

• The test waits until the toggle button becomes available in the DOM, and then proceeds without waiting for page 1 to be ready.
• waitForThumbnailVisible is called first, which calls showViewsManager and that in turn triggers the sidebar opening and resizing, which fires the resize event on the event bus.
• The thumbmail viewer sees the resize event and calls #computeThumbnailsPosition, however the thumbnails are not there because setDocument isn't done yet, so incorrect values end up being set.
• The drag-and-drop action happens, but the thumbnail viewer state is still incorrect until page 1 resolved.
• Page 1 resolves and setDocument finishes, but by this time the drag-and-drop operation has already failed because it worked on the wrong state.

The fix is therefore to wait until the first page is rendered before starting the test, which makes sure that the thumbnails are ready before we proceed with the drag-and-drop action.

Note that the waitForThumbnailVisible helper function itself is not bugged and works as expected: we just call it too soon.