Bug 187547 – [WinCairo] run-api-tests is timing out for almost all test cases

• Status: RESOLVED
• Resolution: FIXED
• Component: Tools / Tests

[Fujii Hironori]

[WinCairo] run-api-tests is failing for almost all test cases

https://build.webkit.org/builders/WinCairo%2064-bit%20WKL%20Release%20%28Tests%29/builds/551

(...)
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWTF.exe', '--gtest_list_tests']
> "C:\WebKit-BuildWorker\wincairo-wkl-release-tests\build\WebKitBuild\Release\bin64\TestWTF.exe --gtest_list_tests" took 0.10s
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWebCore.exe', '--gtest_list_tests']
> "C:\WebKit-BuildWorker\wincairo-wkl-release-tests\build\WebKitBuild\Release\bin64\TestWebCore.exe --gtest_list_tests" took 0.12s
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWebKitLegacy.exe', '--gtest_list_tests']
> "C:\WebKit-BuildWorker\wincairo-wkl-release-tests\build\WebKitBuild\Release\bin64\TestWebKitLegacy.exe --gtest_list_tests" took 0.09s
> Found 860 tests
> Running tests
> Sharding tests ...
> worker/0 starting
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWTF.exe', '--gtest_filter=WTF_HashMap.DeletedAddressOfOperator']
> TestWTF.WTF_HashMap.DeletedAddressOfOperator Timeout
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWTF.exe', '--gtest_filter=WTF_HashMap.DoubleHashCollisions']
> TestWTF.WTF_HashMap.DoubleHashCollisions Timeout
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWTF.exe', '--gtest_filter=WTF_HashMap.EfficientGetter']
> TestWTF.WTF_HashMap.EfficientGetter Timeout
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWTF.exe', '--gtest_filter=WTF_HashMap.Ensure']
> TestWTF.WTF_HashMap.Ensure Timeout
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWTF.exe', '--gtest_filter=WTF_HashMap.Ensure_LambdasCapturingByReference']
> TestWTF.WTF_HashMap.Ensure_LambdasCapturingByReference Timeout
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWTF.exe', '--gtest_filter=WTF_HashMap.Ensure_MoveOnlyValues']
> TestWTF.WTF_HashMap.Ensure_MoveOnlyValues Passed
(...)

[Fujii Hironori]

Created attachment 344751 [details]
WIP patch

[Fujii Hironori]

It seems that ServerProcess is designed for interactive commands which basically never exits.
https://trac.webkit.org/browser/webkit/trunk/Tools/Scripts/webkitpy/port/server_process.py

But, TestWebKitAPI is not an interactive command, and it exits as soon as it finishes.

I think the reason webkitpy/api_tests/runner.py is using ServerProcess is non-blocking read for timeout.

'subprocess' module of Python 3 has timeout.
https://docs.python.org/3.7/library/subprocess.html

But, unfortunately, Python 2 doesn't.

[Fujii Hironori]

Created attachment 344835 [details]
WIP patch

This WIP patch introduces new test failures.
PeekNamedPipe fails because MockFile returns invalid file descriptors.
Umm, :-(

> C:\webkit>python Tools\Scripts\test-webkitpy -v webkitpy.port.server_process_unittest
> Skipping lldb_webkit tests; could not find path to lldb.py ''.
> Skipping QueueStatusServer tests; the Google AppEngine Python SDK is not installed.
> Suppressing most webkitpy logging while running unit tests.
> [1/6] webkitpy.port.server_process_unittest.TestServerProcess.test_basic passed
> [2/6] webkitpy.port.server_process_unittest.TestServerProcess.test_broken_pipe erred:
>   Traceback (most recent call last):
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process_unittest.py", line 207, in test_broken_pipe
>       server_process.write("should break")
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 170, in write
>       self.stop(0.0)
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 372, in stop
>       return self._wait_for_stop(timeout_secs)
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 392, in _wait_for_stop
>       self._wait_for_data_and_update_buffers_using_win32_apis(now)
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 301, in _wait_for_data_and_update_buffers_using_win32_apis
>       output = self._non_blocking_read_win32(out_fh)
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 315, in _non_blocking_read_win32
>       _, avail, _ = win32pipe.PeekNamedPipe(handle, 0)
>   error: (1, 'PeekNamedPipe', '????????????????')
> 
> [3/6] webkitpy.port.server_process_unittest.TestServerProcess.test_cleanup erred:
>   Traceback (most recent call last):
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process_unittest.py", line 197, in test_cleanup
>       server_process.stop()
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 372, in stop
>       return self._wait_for_stop(timeout_secs)
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 392, in _wait_for_stop
>       self._wait_for_data_and_update_buffers_using_win32_apis(now)
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 301, in _wait_for_data_and_update_buffers_using_win32_apis
>       output = self._non_blocking_read_win32(out_fh)
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 315, in _non_blocking_read_win32
>       _, avail, _ = win32pipe.PeekNamedPipe(handle, 0)
>   error: (1, 'PeekNamedPipe', '????????????????')
> 
> [4/6] webkitpy.port.server_process_unittest.TestServerProcess.test_process_crashing passed
> [5/6] webkitpy.port.server_process_unittest.TestServerProcess.test_process_crashing_no_data passed
> [6/6] webkitpy.port.server_process_unittest.TestServerProcess.test_read_after_process_exits passed
> Ran 6 tests in 0.750s
> FAILED (failures=0, errors=2)
> 
> C:\webkit>

[Ross Kirsling]

It appears that simply removing the `time.sleep(0.01)` is enough to fix the issue for run-api-tests.

The PeekNamedPipe errors seem to occur when we do the non-blocking read even though poll() is no longer None (i.e. the result of moving the while condition).

---

Note that there is an *existing* error with TestServerProcess.test_basic -- first, this condition appears to be bogus(?):
https://github.com/WebKit/webkit/blob/master/Tools/Scripts/webkitpy/port/server_process_unittest.py#L110-L112

Once we fix that though, we get...
> [1/5] webkitpy.port.server_process_unittest.TestServerProcess.test_basic erred:
>   Traceback (most recent call last):
>     File "C:\...\Tools\Scripts\webkitpy\port\server_process_unittest.py", line 123, in test_basic
>       self.assertEqual(line.strip(), "stderr")
>   AttributeError: 'NoneType' object has no attribute 'strip'

...which I still don't understand, but could probably be tracked in a separate ticket.

[Ross Kirsling]

(In reply to Ross Kirsling from comment #4)
> ...which I still don't understand, but could probably be tracked in a
> separate ticket.

Oops, looks like there's already a patch for this in https://bugs.webkit.org/show_bug.cgi?id=187581. :D

[Ross Kirsling]

Created attachment 344980 [details]
Patch

[Ross Kirsling]

For some enigmatic reason, the issue was caused by calling Popen.poll immediately after time.sleep (or even win32api.Sleep).

The solution, however, was simple enough in hindsight:
- do NOT return immediately if we're still before the deadline (even if the process has exited)
- do NOT sleep if the process has already exited

[Fujii Hironori]

(In reply to Ross Kirsling from comment #7)
> For some enigmatic reason, the issue was caused by calling Popen.poll
> immediately after time.sleep (or even win32api.Sleep).

What is the issue? What will happen if Popen.poll is called immediately after time.sleep?


> The solution, however, was simple enough in hindsight:
> - do NOT return immediately if we're still before the deadline (even if the
> process has exited)
> - do NOT sleep if the process has already exited

So simple. Nice.

[Fujii Hironori]

Comment on attachment 344980 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=344980&action=review

> Tools/Scripts/webkitpy/port/server_process.py:308
>                  return

You should put the condition here instead of above.

self._proc.poll() is not None:
  return

> Tools/Scripts/webkitpy/port/server_process_unittest.py:131
> +        cmd = [sys.executable, '-c', 'import sys; print "stdout"; sys.stdout.flush(); print >>sys.stderr, "stderr"; sys.stderr.flush();']

All files are flushed when the process exits. You don't need to flush.

[Ross Kirsling]

Created attachment 345018 [details]
Patch

[Ross Kirsling]

Note: WinCairo failure here is of course unrelated. (I think it went red because I manually fixed the issue on the bot between the first and second checks.)

[Fujii Hironori]

Comment on attachment 345018 [details]
Patch

r+

[WebKit Commit Bot]

Comment on attachment 345018 [details]
Patch

Clearing flags on attachment: 345018

Committed r233834: <https://trac.webkit.org/changeset/233834>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.

[Radar WebKit Bug Importer]

<rdar://problem/42194916>

[Fujii Hironori]

Here is the WinCairo EWS error message:

> midl : command line error MIDL1016 : cannot create intermediate file C:\Users\ContainerAdministrator\AppData\Local\Temp\MIDEFA7.tmp

Filed Bug 187725.