How do these failure durations make sense?

Scripted browser synthetic which

  • navigates a little bit to reach a button which when clicked launches a new window/tab,
  • clicks on that button, switches to the new window,
  • waits for an element to appear indicating the new window has finished loading,
  • and verifies some text is present in that window.

Fairly simple, and it seems to work most of the time. But sometimes it fails, although as far as I know there is no outage in the service. When it fails, it claims it was a ScriptTimeoutError and the timed out step is the one immediately after it switches to the new window. Here is an example of the end of the script log from one of the failed checks:

Step 12: Switch to Window using Handle vars.get("win4542") STARTED at 2547ms. testCase=C2
Step 12: Switch to Window using Handle vars.get("win4542") FINISHED. It took 9ms to complete. testCase=C2
Step 13: Wait For Element is Present By.id("LaunchedBookImg") STARTED at 2556ms. testCase=Cinch - launch cognero
Error in Step 13: Wait For Element is Present By.id("LaunchedBookImg")
Script execution failed: TimeoutError: timeout
  (Session info: chrome=72.0.3626.121)
  (Driver info: chromedriver=2.46.628388     (4a34a70827ac54148e092aafb70504c4ea7ae926),platform=Linux 4.14.232-177.418.amzn2.x86_64 x86_64)

For comparison, here is what the end of the script log looks like in a successful check:

Step 12: Switch to Window using Handle vars.get("win4542") STARTED at 2637ms. testCase=C2
Step 12: Switch to Window using Handle vars.get("win4542") FINISHED. It took 2ms to complete. testCase=C2
Step 13: Wait For Element is Present By.id("LaunchedBookImg") STARTED at 2639ms. testCase=C2
Step 13: Wait For Element is Present By.id("LaunchedBookImg") FINISHED. It took 2972ms to complete. testCase=C2
Step 14: Verify Text Click a link below or drag a test or question set into this area. using By.id("EmptyInstructs") STARTED at 5611ms. testCase=C2
Step 14: Verify Text Click a link below or drag a test or question set into this area. using By.id("EmptyInstructs") FINISHED. It took 269ms to complete.

Now, here’s the part that’s confusing me and doesn’t seem to make sense:

  • A successful check claims to have a duration of usually between 5500-6500ms
  • A failed check with that timeout error claims to have a duration in the 2400-3600ms range!

Yet step 13, the one that times out, is:

    .then( function(){return logger.log(13,"Wait For Element is Present By.id(\"LaunchedBookImg\")","C2"),$browser.waitForAndFindElement(By.id("LaunchedBookImg"),3000).then(e=>e)})

… which, as you can see, has a 3000ms timeout on the call to waitForAndFindElement. So, how is the entire synthetic check taking less time than that, to fail with a timeout error on step 13, while always taking more time than that when it succeeds?

I’m attaching a screenshot of the synthetic results page, where you can see a sequence of three failed checks in the midst of a bunch of successes, and see the duration column. All three of those failures were ScriptTimeoutError on step 13, like the log snipped above.

Can anyone explain these durations?

This continues happening even if I change the timeout on step 13 to something much higher, such as 5000 or 8000. It still sometimes fails with ScriptTimeoutError, and when it does fail, the total duration reported is nearly always in the 2400-3600ms range. It’s really frustrating and I don’t understand what’s happening.

@cos1 Sorry to hear that you are still experiencing this issue. This forum category is not monitored by our support team but hope that a fellow community member will be able to assist you soon.