http://bugs.winehq.org/show_bug.cgi?id=29168
--- Comment #106 from Xolotl Loki xoloki@gmail.com 2012-02-20 23:47:06 CST --- I keep looking at this from time to time, but still no real progress.
I'm still focusing on the server handshake on port 8995. I had previously determined that TOR calls WSARecv, and is returned the 22 byte server header asynchronously. TOR immediately calls WSARecv again, and after a minute the connection times out, and is closed.
Debugging with +tid, I discovered something new today: the thread that does the second WSARecv call on the 8995 socket is *not* the same as the thread which is delivered the 22 byte header. I then added +seh, and discovered:
0045:trace:winsock:WS2_async_recv socket 0178 not PENDING so return ws2_async_apc as *apc and pass status 0 and result 22 through iosb 0045:trace:winsock:WS2_async_recv socket 0178 returning status 0 000d:trace:winsock:WSARecv socket 0178, calling WS2_recv_base 000d:trace:winsock:WS2_recv_base socket 0178, wsabuf 0xa4ce630, nbufs 1, flags 0, from (nil), fromlen -1, ovl 0x526a0f50, func (nil) [2012-02-20 18:54:57] 0045:trace:seh:raise_exception eax=000000ff ebx=00000000 ecx=00000000 edx=01784065 esi=00000400 edi=7b8351f0 0045:trace:seh:raise_exception eax=000000ff ebx=00000000 ecx=00000000 edx=01789457 esi=00000400 edi=7b8351f0 0045:trace:seh:raise_exception eax=000000ff ebx=00000000 ecx=00000000 edx=0178d980 esi=00000400 edi=7b8351f0
Basically, the thread that receives the data crashes, and another thread tries to read again. However, the data is already gone, so the new IO thread gets nothing, and we never progress. I was lucky to see this, because it was only the value of edx happening to match the socket handle I was grepping.
So I ran again with +relay, and after sifting through 11GB of data, I found nothing particularly useful:
000d:Ret KERNEL32.GetCurrentThreadId() retval=0000000d ret=10004837 000d:Call KERNEL32.GetCurrentThreadId() ret=1000033:Ret KERNEL32.GetLastError() retval=00000000 ret=78543849 000d:Call KERNEL32.SetEvent(00000328) ret=00365655 000d:Ret KERNEL32.SetEvent() retval=00000001 ret=00365655 000d:Call user32.GetClientRect(000a0052,0a2ce950) ret=006fa5f6 000d:Ret user32.GetClientRect() retval=00000001 ret=006fa5f6 000d:Call KERNEL32.QueryPerformanceCounter(0a2ce8f8) ret=006f9a14 000d:Ret KERNEL32.QueryPerformanceCounter() retval=00000001 ret=006f9a14 000d:trace:seh:raise_exception code=80000004 flags=0 addr=0x70a9c1 ip=0070a9c1 tid=000d
So I'm at an impasse again. I think I know what's going on; the IO thread crashes after getting the server header, never sending the reply, and another thread times out waiting for more data. But I don't see anything suspicious going on right before the crash, which means the trail is cold again.