TimedPromise timed out after 500ms

[aharui]

System

• Version: 0.24.0
• Platform: macOS
• Firefox: 68.0.2 (64-bit)
• Selenium: 3.141.59

Testcase

See attached.
marionette.zip

I've tried to reduce this test case, but cannot figure out how. I can force the timeout by running lots of script code, but the script in reduced test cases always completes where in this larger test case the click does not seem to run script code.

Unzip and run (with Java)

java -Dwebdriver.gecko.driver=<path to>geckodriver -classpath .:<path to>selenium/client-combined-3.141.59.jar:<path to>selenium/libs/byte-buddy-1.8.15.jar:<path to>selenium/libs/commons-exec-1.3.jar:<path to>selenium/libs/guava-25.0-jre.jar:<path to>selenium/libs/okhttp-3.11.0.jar:<path to>selenium/libs/okio-1.14.0.jar TimedPromiseBugMustella file:///<path to this folder>/mustella/index.html 

Stacktrace

    TimedPromise timed out after 500 ms: stacktrace:
bail@chrome://marionette/content/sync.js:223:64

Trace-level log

See attached.
TraceLevelLog.txt

I wasn't sure whether to re-open #1584 or not.

[aharui]

This test case puts up a text input field and two buttons in a div. Clicking on the buttons increase or decrease the value in the input field.

The test script increases the value twice then tries to decrease the value. That click doesn't seem to happen and instead the TimedPromise timed out error occurs.

I've added a third increase value click to prove that it isn't the 3rd event that times out.

[whimboo]

This warning actually comes from flushing the event loop.

If that really hides that an element hasn't been clicked, we should allow the promise to raise a timeout error. With that in-place we might get more reports of broken behavior, but at least could see where fixes would be necessary. @andreastt what do you think?

Note that I cannot run the test given that the example HTML file doesn't show any content. So maybe it was wrongly saved.

[aharui]

If you just load the HTML file, it will not show any content. The Java-based test script will cause content to appear and then run clicks on it. Please let me know if you ran the Java command-line and still didn't see any content, and maybe post your trace logs so I can compare it to my run.

[andreastt]

The problem is that I don’t know under what circumstances window.setTimeout(…, 0) would not fire, possibly we are missing a state check for something:

  let spinEventLoop = resolve => {
    unloadEv = resolve;
    clickEv = () => {
      if (win.closed) {
        resolve();
      } else {
        win.setTimeout(resolve, 0);
      }
    };

    win.addEventListener("unload", unloadEv, { mozSystemGroup: true });
    el.addEventListener("click", clickEv, { mozSystemGroup: true });
  };

(Above code from https://searchfox.org/mozilla-central/rev/9415ecf29ba1acbef9381335e0ecde5916ca4073/testing/marionette/interaction.js#406-418.)

We know there are a number of users affected by this problem, so making it throw will cause test cases that are currently working to start erroring, so I’m not sure that making it throw will improve the situation since we are none the wiser as to why this is happening.

A reproducible test case with some added logging to spinEventLoop might be a better approach however.

[aharui]

Let me know if you need help getting my test case to run. If I understand the responses so far, the issue may not be the way the timeout is set to fire, but rather, the timeout is an indication that in some cases, calling RemoteWebElement.click() does not actually dispatch a 'click' event that the JavaScript code sees. So if you can get my test case to run in your debuggers, the thing to debug is the code paths for how RemoteWebElement.click() ends up dispatching a 'click' event in the browser

[whimboo]

@aharui would you mind running your tests again with a recent Firefox Nightly build? It provides more information about the stack now, which will help us to find the code using the TimedPromise. Thanks.

[PiotrZgadzaj]

We have same problem with our test suite since upgrading Firefox to 65/66. Sometimes interactions with the page does not impact what is displayed in the browser. In case of such problems, i'm sure that browser send the request to the server, because i see it in the logs, also the response is correct, however because of some reason, browser does not render the response and logs following messages:

1585665376991 Marionette WARN TimedPromise timed out after 500 ms: stacktrace:
bail@chrome://marionette/content/sync.js:224:64

Do you know if newer FF are also affected by that? for example 70 or 71?

[mirao]

Do you know if newer FF are also affected by that? for example 70 or 71?

@PiotrZgadzaj Yes I can see it with FF 74, geckodriver 0.26, Selenium 3.141.59 on Ubuntu 18.04:

1586257529499	Marionette	WARN	TimedPromise timed out after 10 ms: stacktrace:
TimedPromise/<@chrome://marionette/content/sync.js:244:13
TimedPromise@chrome://marionette/content/sync.js:229:10
Sleep@chrome://marionette/content/sync.js:282:10
dispatchPause@chrome://marionette/content/action.js:1482:10
toEvents/<@chrome://marionette/content/action.js:1156:16
action.dispatchTickActions@chrome://marionette/content/action.js:1060:35
action.dispatch/chainEvents<@chrome://marionette/content/action.js:1028:20
1586257560558	Marionette	WARN	TimedPromise timed out after 500 ms: stacktrace:
TimedPromise/<@chrome://marionette/content/sync.js:244:13
TimedPromise@chrome://marionette/content/sync.js:229:10
interaction.flushEventLoop@chrome://marionette/content/interaction.js:416:10
webdriverClickElement@chrome://marionette/content/interaction.js:182:31

[PiotrZgadzaj]

I will try with newest nightly Build which is available. For me, problem started showing up after upgrade from FF64 to FF65. It occurs in scenario where ajax request returns new iframe for the page. Browser simply do not update the DOM. In our tests, we run multiple tests one after another, on same browser instance. When the problem occurs, it keeps occuring for few tests in a row and then suddenly browser/marionette recovers itself and everything is fine again

[whimboo]

@mirao your reported warning is not relevant and expected to happen. The call to Sleep as it is done in your case shouldn't show the warning and stack at all. There is https://bugzilla.mozilla.org/show_bug.cgi?id=1606637 to get this fixed.

@PiotrZgadzaj if you are still able to reproduce please send the stack for the TimedPromise. Thanks.

[DudaGod]

Can you explain why is my comment is marked as off-topic?

[whimboo]

There is no need for "me too" comments. As I have layed out above in my last comment the issue is known, and as long as this referenced bug hasn't been fixed you won't see a change in behavior. Also there is no better solution than off-topic available when hiding such comments.

[whimboo]

This issue is fixed now and will no longer occur with the next Firefox Nightly build. I also requested an uplift for Firefox 81 beta.