Widespread timeouts in Edge 17

[foolip]

Edge results have always seemed to have a lot of TIMEOUT in the "Test file" row. Browsing around at random it's easy find cases for Edge 17 as well:
https://wpt.fyi/results/accelerometer/Accelerometer-enabled-by-feature-policy-attribute-redirect-on-load.https.html?sha=ad84337c03
https://wpt.fyi/results/compat/interfaces.any.html?sha=ad84337c03
https://wpt.fyi/results/wake-lock/wakelock-cancel-twice.https.html?sha=ad84337c03

@jugglinmike, as a start, could you count how many tests are like this, where only Edge has a harness-level timeout?

[gsnedders]

Do we know if this is Sauce specific or happens with native runs?

[foolip]

@thejohnjansen have you been able to compare the results from Sauce with your own runs yet?

[foolip]

I'm seeing this in https://wpt.fyi/results/old-tests/submission/Microsoft/selection?sha=eea0b54014&label=stable now.

[foolip]

Seeing this today also, in https://wpt.fyi/results/webmessaging/with-options?sha=c0a1bc68d7&label=stable

[foolip]

As a point of comparison, the same tests from the experimental Edge 18 run:
https://wpt.fyi/results/accelerometer/Accelerometer-enabled-by-feature-policy-attribute-redirect-on-load.https.html?sha=548797a187
https://wpt.fyi/results/compat/interfaces.any.html?sha=548797a187 (missing, not sure why)
https://wpt.fyi/results/wake-lock/wakelock-cancel-twice.https.html?sha=548797a187

The tests also run and have results when testing Edge 17 manually, so I'm quite sure this isn't a problem with Edge, but with the running infrastructure.

[foolip]

https://wpt.fyi/results/?product=edge@085d47ef10&product=edge@548797a187&diff compares two runs that are close in their wpt revisions. It's a bit hard to navigate (web-platform-tests/wpt.fyi#411) but here's one directory with a lot of Ede 17 timeouts which are probably spurious:
https://wpt.fyi/results/dom/events?product=edge@085d47ef10&product=edge@548797a187&diff=true

[foolip]

This issue became apparent again today on a web-platform-tests that fail only in Chrome (from wpt.fyi data) thread on blink-dev.

[foolip]

This may be the most extreme bad run I've spotted so far: https://wpt.fyi/results/?sha=5acd3bcf66

0 / N almost down the line. @jugglinmike, perhaps the setup has become totally broken somehow?

@lukebjerring, do you have an issue for "validate results"? Seems like with that in place we would reject a run like this, or label it bad at least.

[foolip]

This appears to be the most complete of recent runs:
https://wpt.fyi/results/?sha=937ed3c7b1

https://wpt.fyi/results/?sha=99e577f57c is another really bad one, and before that I can't find any that are this busted going back as far as 434ca47448. So this appears to be a recent regression.

[jugglinmike]

Well, the builds certainly aren't completing any faster. They're just slow and wrong now.

We're seeing three different kinds of errors. The first two:

▶ ERROR [expected OK] /css/css-scoping/slot-non-html-display-value.html
└   → Message: Unable to get property 'addEventListener' of undefined or null reference (WARNING: The server did not provide any stacktrace information)

▶ ERROR [expected OK] /websockets/interfaces/WebSocket/bufferedAmount/bufferedAmount-large.html
└   → Message: Unable to get property 'addEventListener' of undefined or null reference (WARNING: The server did not provide any stacktrace information)

...are always followed by a timeout, e.g.

Command duration or timeout: 390 milliseconds
Build info: version: '2.52.0', revision: '4c2593c', time: '2016-02-11 19:06:42'
System info: host: 'sauce-win10', ip: '10.100.19.211', os.name: 'Windows 10', os.arch: 'amd64', os.version: '10.0', java.version: '1.8.0_131'
Driver info: org.openqa.selenium.edge.EdgeDriver
Capabilities [{applicationCacheEnabled=true, InPrivate=false, pageLoadStrategy=normal, platform=ANY, acceptSslCerts=true, browserVersion=42.17134.1.0, platformVersion=10, locationContextEnabled=true, webStorageEnabled=true, browserName=MicrosoftEdge, takesScreenshot=true, takesElementScreenshot=true, platformName=windows}]
Session ID: XXXXXXXX-XXXX-XXXX-XXXX-XXXXE993DD85
Stacktrace:
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0 (None:-2)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance (None:-1)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance (None:-1)
    at java.lang.reflect.Constructor.newInstance (None:-1)
    at org.openqa.selenium.remote.ErrorHandler.createThrowable (ErrorHandler.java:206)
    at org.openqa.selenium.remote.ErrorHandler.throwIfResponseFailed (ErrorHandler.java:158)
    at org.openqa.selenium.remote.RemoteWebDriver.execute (RemoteWebDriver.java:678)
    at org.openqa.selenium.remote.RemoteWebDriver.executeAsyncScript (RemoteWebDriver.java:598)
    at sun.reflect.NativeMethodAccessorImpl.invoke0 (None:-2)
    at sun.reflect.NativeMethodAccessorImpl.invoke (None:-1)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke (None:-1)
    at java.lang.reflect.Method.invoke (None:-1)
    at org.openqa.selenium.support.events.EventFiringWebDriver$2.invoke (EventFiringWebDriver.java:103)
    at com.sun.proxy.$Proxy1.executeAsyncScript (None:-1)
    at org.openqa.selenium.support.events.EventFiringWebDriver.executeAsyncScript (EventFiringWebDriver.java:229)
    at org.openqa.selenium.remote.server.handler.ExecuteAsyncScript.call (ExecuteAsyncScript.java:58)
    at java.util.concurrent.FutureTask.run (None:-1)
    at org.openqa.selenium.remote.server.DefaultSession$1.run (DefaultSession.java:176)
    at java.util.concurrent.ThreadPoolExecutor.runWorker (None:-1)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run (None:-1)
    at java.lang.Thread.run (None:-1)

The third kind of error is far more common but far less helpful:

▶ ERROR [expected OK] /websockets/interfaces/WebSocket/bufferedAmount/bufferedAmount-readonly.html
└   → 1

It is never followed by a timeout.

As you can see, the logs are now formatted with the "GroupingFormatter" because that was recently made the default behavior of the WPT CLI. As mentioned there, this format is unideal for continuous integration because it limits the amount of information available in situations like these.

I have reinstated the previous default logging format for this project. This won't fix anything, but it should help us in future debugging attempts. I've updated WPT so that I'm notified of changes to WPT's tools directory, so hopefully I can stay on top of things like this in the future.

In the mean time, I have also updated to the latest release of the "Sauce Connect Binary" in the off chance that "Fixed file descriptor leak." has some bearing here.

[foolip]

Thanks for investigating Mike! Do you think it'd be worth trying more aggressive restarting, and perhaps more chunks, to mitigate breakage like this?

[jugglinmike]

Do you think it'd be worth trying more aggressive restarting

The fact that this immediately interferes with almost every "chunk" makes me think that restarting will not resolve it, but it couldn't hurt to try (especially now that we're disabling Safari on Sauce Labs). We'll see what effect this has on time-to-results (it may get ugly).

(I was ready to point out that these are "ERROR"s and not "FAILURE"s, but then I remembered that doesn't actually matter.)

perhaps more chunks

For Edge, we're currently running WPT in 100 "chunks" which already feels a bit excessive. I can give it a shot if we run out of ideas, though.

[foolip]

Oh, if it's already 100 chunks, then scratch that idea. Seems like something is broken with Sauce or the sauce support in ./wpt run then?

[jugglinmike]

We've completed a collection from Edge that involved restarting after every test failure. This increased build time from 15 hours to 24 hours, but it had no appreciable affect on the veracity of the results.

Strangely, I haven't been able to connect to Sauce Labs locally. I'm not going to prioritize fixing that yet for a few reasons:

• This is distinct from the behavior we're seeing on the workers
• We've seen our share of roving DNS issues, so this may resolve itself in time

In the interim, I can do ad-hoc testing from any of the worker machines; that's probably more authentic, anyway. ...just not while they're actively testing. Although Edge is now running 24/7, 10 of our machines do not run Sauce Labs tests, so this is still a viable option.