Bug 177834 – Layout Test http/tests/inspector/network/beacon-type.html is flaky.

• Status: RESOLVED
• Resolution: FIXED
• Component: Web Inspector

[Matt Lewis]

http/tests/inspector/network/beacon-type.html is a flaky timeout on Sierra and High Sierra WK2 according to the dashboard.

https://webkit-test-results.webkit.org/dashboards/flakiness_dashboard.html#showAllRuns=true&tests=http%2Ftests%2Finspector%2Fnetwork%2Fbeacon-type.html

It looks like the flaky timeout started with this build:
https://build.webkit.org/results/Apple%20High%20Sierra%20Release%20WK2%20(Tests)/r222740%20(113)/results.html
https://build.webkit.org/builders/Apple%20High%20Sierra%20Release%20WK2%20(Tests)/builds/113

and this revision:
https://trac.webkit.org/changeset/222739/webkit

Diff:
--- /Volumes/Data/slave/sierra-release-tests-wk2/build/layout-test-results/http/tests/inspector/network/beacon-type-expected.txt
+++ /Volumes/Data/slave/sierra-release-tests-wk2/build/layout-test-results/http/tests/inspector/network/beacon-type-actual.txt
@@ -1,22 +1,5 @@
-Tests for Resource.Type.Beacon.
+#PID UNRESPONSIVE - com.apple.WebKit.WebContent.Development (pid 28326)
+FAIL: Timed out waiting for notifyDone to be called
 
-
-== Running test suite: Resource.Type.Beacon
--- Running test case: Resource.Type.Beacon.204
-PASS: Resource should be Beacon type.
-PASS: Resource should be a POST request.
-PASS: Resource should have a 204 response.
-PASS: Resource should not have request data.
-
--- Running test case: Resource.Type.Beacon.404
-PASS: Resource should be Beacon type.
-PASS: Resource should be a POST request.
-PASS: Resource should have a 404 response.
-PASS: Resource should not have request data.
-
--- Running test case: Resource.Type.Beacon.WithData
-PASS: Resource should be Beacon type.
-PASS: Resource should be a POST request.
-PASS: Resource should have a 200 response.
-PASS: Resource should have 'SENDING-DATA' request data.
-
+#EOF
+#EOF


current build:
https://build.webkit.org/results/Apple%20Sierra%20Release%20WK2%20(Tests)/r222788%20(4724)/results.html
https://build.webkit.org/builders/Apple%20Sierra%20Release%20WK2%20(Tests)/builds/4724

[Joseph Pecoraro]

Added debug logging with:
https://trac.webkit.org/changeset/222805/webkit

That will hopefully get me actionable data about why this test is timing out.

[Matt Lewis]

event: {"method":"Network.requestWillBeSent","params":{"requestId":"0.23","frameId":"0.1","loaderId":"0.6","documentURL":"http://127.0.0.1:8000/inspector/network/beacon-type.html",
"request":{"url":"http://127.0.0.1:8000/inspector/network/resources/beacon.php?status=204","method":"POST","headers":{"Referer":"http://127.0.0.1:8000/inspector/network/beacon-type.html","User-Agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13) AppleWebKit/605.1.9 (KHTML, like Gecko)","Origin":"http://127.0.0.1:8000","Accept":"*/*","Cache-Control":"max-age=0"}},"timestamp":0.015034461997856852,"initiator":{"type":"script","stackTrace":[{"functionName":"sendBeacon","url":"[native code]","scriptId":"0","lineNumber":0,"columnNumber":0},{"functionName":"triggerBeaconWith204Response","url":"http://127.0.0.1:8000/inspector/network/beacon-type.html","scriptId":"113","lineNumber":8,"columnNumber":25},{"functionName":"global code","url":"","scriptId":"121","lineNumber":1,"columnNumber":29},{"functionName":"evaluateWithScopeExtension","url":"[native code]","scriptId":"0","lineNumber":0,"columnNumber":0},{"functionName":"_evaluateOn","url":"","scriptId":"117","lineNumber":128,"columnNumber":29},{"functionName":"_evaluateAndWrap","url":"","scriptId":"117","lineNumber":122,"columnNumber":108}]},"type":"Beacon"}}
response: {"result":{"result":{"type":"undefined"},"wasThrown":false},"id":27}
event: {"method":"Network.responseReceived","params":{"requestId":"0.23","frameId":"0.1","loaderId":"0.6","timestamp":0.017259075997571927,"type":"Beacon","response":{"url":"http://127.0.0.1:8000/inspector/network/resources/beacon.php?status=204","status":204,"statusText":"No Content","headers":{"Content-Type":"text/html","Keep-Alive":"timeout=15, max=86","Date":"Tue, 03 Oct 2017 20:43:45 GMT","Connection":"Keep-Alive","X-Powered-By":"PHP/7.1.7","Server":"Apache/2.4.27 (Unix) PHP/7.1.7 LibreSSL/2.2.7"},"mimeType":"text/html","source":"unknown"}}}
event: {"method":"Network.loadingFinished","params":{"requestId":"0.23","timestamp":0.0172940810007276,"metrics":{}}}
PASS: Resource should be Beacon type.
request: {"id":28,"method":"Runtime.evaluate","params":{"expression":"TestPage.addResult(unescape(\"PASS%3A%20Resource%20should%20be%20Beacon%20type.\"))","objectGroup":"test","includeCommandLineAPI":false}}
PASS: Resource should be a POST request.
request: {"id":29,"method":"Runtime.evaluate","params":{"expression":"TestPage.addResult(unescape(\"PASS%3A%20Resource%20should%20be%20a%20POST%20request.\"))","objectGroup":"test","includeCommandLineAPI":false}}
event: {"method":"Debugger.scriptParsed","params":{"scriptId":"122","url":"","startLine":0,"startColumn":0,"endLine":0,"endColumn":81}}
response: {"result":{"result":{"type":"undefined"},"wasThrown":false},"id":28}
event: {"method":"Debugger.scriptParsed","params":{"scriptId":"123","url":"","startLine":0,"startColumn":0,"endLine":0,"endColumn":86}}
response: {"result":{"result":{"type":"undefined"},"wasThrown":false},"id":29}
Wait on notifyDone timed out, process com.apple.WebKit.WebContent.Development pid = 12965#EOF

[Joseph Pecoraro]

> {"method":"Network.loadingFinished","params":{"requestId":"0.23","timestamp": 0.0172940810007276,"metrics":{}}}
> PASS: Resource should be Beacon type.

This is the key. The loadingFinished event was received and processed before the Test's Promise microtask runs. So this promise ends up waiting on events for the resource load to complete but it has already completed. We can skip the wait on events if the resource load finished.

I was able to reproduce ~1 in 250 runs on my laptop.
After fix I wasn't able to reproduce. Going to land the tiny test change unreviewed.

[Joseph Pecoraro]

<https://trac.webkit.org/changeset/222808/webkit>

[Radar WebKit Bug Importer]

<rdar://problem/34798863>