http://bugs.winehq.org/show_bug.cgi?id=20353
Summary: chromium ipc_tests.exe fails when KERNEL32.GetQueuedCompletionStatus() hangs on peer disconnect of named pipe? Product: Wine Version: unspecified Platform: PC OS/Version: Linux Status: NEW Keywords: download, source, testcase Severity: normal Priority: P2 Component: ntdll AssignedTo: wine-bugs@winehq.org ReportedBy: dank@kegel.com
The script
wget http://kegel.com/wine/chromium/ipc_tests.exe.rz rzip -d ipc_tests.exe.rz WINEPREFIX=/data/dkegel/.winetest /data/dkegel/wine-git/wine notepad & i=1 while test $i -lt 100 do WINEDEBUG=+process,+relay WINEPREFIX=/data/dkegel/.winetest /data/dkegel/wine-git/wine ipc_tests.exe --gtest_filter=IPCChannelTest.SendMessageInChannelConnected > ipc$i.log 2>&1 i=`expr $i + 1` done grep FAIL ipc*.log
shows about 10 failures of IPCChannelTest.SendMessageInChannelConnected here (with or without logging). Looking at the logs with grep shows that successful runs end with a call to ExitProcess(0) in both parent and child, but failed runs end with just one ExitProcess(1) and a call to GetQueuedCompletionStatus() that does not return.
Searching through the chromium codebase seems to indicate that this function is called only in MessagePumpForIO::GetIOItem() in http://src.chromium.org/viewvc/chrome/trunk/src/base/message_pump_win.cc The IO completion events in this test seem mainly to come from reads of a named pipe. Grepping for the handle of that named pipe plus a few other interesting words, egrep 'FAIL|Exit|error|PASS|RUN|CreateProcess|GetQueuedCompletionStatus|0x68[^0-9a-f]|00068[^0-9a-f]'
shows lots of normal operation (an NtReadFile() followed by a few GetQueuedCompletionStatus()'s until one succeeds, then repeat; both parent and child process do this), but towards the end when the test is shutting down, something funny happens:
[parent process shuts its end down] 0024:Call KERNEL32.GetQueuedCompletionStatus(00000064,0033f9e8,0033f920,0033f914,00000000) ret=004b9d69 trace:sync:GetQueuedCompletionStatus (0x64,0x33f9e8,0x33f920,0x33f914,0) 0024:Ret KERNEL32.GetQueuedCompletionStatus() retval=00000000 ret=004b9d69 0024:Call KERNEL32.CancelIo(00000068) ret=00520112 trace:ntdll:NtCancelIoFile 0x68 0x33fa10 0024:Call KERNEL32.CloseHandle(00000068) ret=00520135 0024:Call KERNEL32.GetQueuedCompletionStatus(00000064,0033fa68,0033f9a0,0033f994,ffffffff) ret=004b9d69 trace:sync:GetQueuedCompletionStatus (0x64,0x33fa68,0x33f9a0,0x33f994,-1) 0024:Ret KERNEL32.GetQueuedCompletionStatus() retval=00000001 ret=004b9d69 0024:Call KERNEL32.GetQueuedCompletionStatus(00000064,0033fa68,0033f9a0,0033f994,ffffffff) ret=004b9d69 trace:sync:GetQueuedCompletionStatus (0x64,0x33fa68,0x33f9a0,0x33f994,-1) 0024:Ret KERNEL32.GetQueuedCompletionStatus() retval=00000001 ret=004b9d69
[child process wakes up, does some I/O, checks queue, hangs] 0037:Call KERNEL32.ReadFile(00000068,009ba620,00001000,0033f780,009ba5c4) ret=00520f00 trace:ntdll:NtReadFile (0x68,(nil),(nil),0x9ba5c4,0x9ba5c4,0x9ba620,0x00001000,0x33f2e0,(nil)),partial stub! 0037:Call KERNEL32.GetQueuedCompletionStatus(00000064,0033fa04,0033f93c,0033f930,00000000) ret=004b9d69 trace:sync:GetQueuedCompletionStatus (0x64,0x33fa04,0x33f93c,0x33f930,0) 0037:Ret KERNEL32.GetQueuedCompletionStatus() retval=00000000 ret=004b9d69 0037:Call KERNEL32.GetQueuedCompletionStatus(00000064,0033f95c,0033f894,0033f888,ffffffff) ret=004b9d69 trace:sync:GetQueuedCompletionStatus (0x64,0x33f95c,0x33f894,0x33f888,-1)
[parent process gives up and declares failure] .\ipc_tests.cc(352): error: Value of: base::WaitForSingleProcess(process_handle, 5000) 0024:Call KERNEL32.OutputDebugStringA(009d5f90 ".\ipc_tests.cc(352): error: Value of: base::WaitForSingleProcess(process_handle, 5000)\n Actual: false\nExpected: true") ret=00453839
This is all just extrapolation from one log, but it does seem like wine might not be doing the right thing with GetQueuedCompletionStatus() and named pipes. (Dang, I should have covered that case when I wrote my named pipe tests in 2003 :-)