http://bugs.winehq.org/show_bug.cgi?id=18643
Anastasius Focht focht@gmx.net changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |focht@gmx.net
--- Comment #8 from Anastasius Focht focht@gmx.net 2009-05-30 10:10:24 --- Hello,
that app seems to use remoting Ipc Channel facility of .NET (local IPC communication between managed processes). The IPC channel is implemented in .NET using Named Pipes.
--- snip --- ... fixme:win:EnumDisplayDevicesW ((null),0,0x33b3f0,0x00000000), stub! fixme:advapi:RegisterEventSourceW ((null),L".NET Runtime"): stub fixme:advapi:ReportEventW (0xcafe4242,0x0001,0x0000,0x000003ff,(nil),0x0001,0x00000000,0x48cd510,(nil)): stub err:eventlog:ReportEventW L".NET Runtime version 2.0.50727.42 - Fatal Execution Engine Error (7A05E2B3) (80131506)" fixme:advapi:DeregisterEventSource (0xcafe4242) stub --- snip ---
Running this app under managed debugger one can see following:
--- snip --- ... Thread 0x24 Current State:Background,GCUnsafe spot 0) [Internal Frame, 'M-->U', System.Runtime.Remoting.Channels.Ipc.NativePipe::ConnectNamedPipe] 1)* System.Runtime.Remoting.Channels.Ipc.IpcPort::WaitForConnect +0031[native] +0000[IL] in <Unknown File Name>:<Unknown Line Number> 2) System.Runtime.Remoting.Channels.Ipc.IpcServerChannel::Listen +0630[native] +0261[IL] in <Unknown File Name>:<Unknown Line Number> 3) System.Threading.ThreadHelper::ThreadStart_Context +0113[native] +0036[IL] in <Unknown File Name>:<Unknown Line Number> 4) System.Threading.ExecutionContext::Run +0236[native] +0095[IL] in <Unknown File Name>:<Unknown Line Number> 5) System.Threading.ThreadHelper::ThreadStart +0082[native] +0025[IL] in <Unknown File Name>:<Unknown Line Number> 6) [Internal Frame, 'AD switch':(AD ''. #) -->(AD 'StubDomain'. #2)] ... Unhandled exception generated: (0xa610b4) <System.ExecutionEngineException> _className=<null> _exceptionMethod=<null> _exceptionMethodString=<null> _message=<null> _data=<null> _innerException=<null> _helpURL=<null> _stackTrace=<null> _stackTraceString=<null> _remoteStackTraceString=<null> _remoteStackIndex=0 _dynamicMethods=<null> _HResult=-2146233082 _source=<null> _xptrs=0 _xcode=-532459699 Exception is called:UNHANDLED --- snip ---
Execution trace log with +tid,+seh,+ntdll,+sync,+server gives following:
The server creates the named pipe and associates io completion port with it to achieve asynchronous IO over a named pipe.
--- snip --- ... 001c:trace:sync:CreateNamedPipeW (L"\\.\pipe\localhost:6591", 0x40000003, 00000000, 255, 8192, 8192, -1, 0x97c5bc) 001c:trace:ntdll:NtCreateNamedPipeFile (0x307dc98 c0100000 L"\??\pipe\localhost:6591" 0x307dc70 0 5 2 0 0 0 -1 8192 8192 0x307dc64) 001c: create_named_pipe( access=c0100000, attributes=00000040, rootdir=0000, options=00000002, maxinstances=ffffffff, outsize=00002000, insize=00002000, timeout=+4294967.2950000, flags=00000000, name=L"\??\pipe\localhost:6591" ) 001c: create_named_pipe() = 0 { handle=0240 } 001c:trace:sync:CreateIoCompletionPort (0x240, 0x228, 7a07c050, 00000002) 001c:trace:ntdll:NtSetInformationFile (0x240,0x307df58,0x307df60,0x00000008,0x0000001e) 001c: set_completion_info( handle=0240, ckey=7a07c050, chandle=0228 ) 001c: set_completion_info() = 0 --- snip ---
The server thread tries to listen by connecting to named pipe:
--- snip --- 001c:trace:sync:ConnectNamedPipe (0x240,(nil)) 001c:trace:ntdll:NtFsControlFile (0x240,(nil),(nil),(nil),0x307dfc4,0x00110008,(nil),0x00000000,(nil),0x00000000) 001c: ioctl( code=FSCTL_PIPE_LISTEN, async={handle=0240,event=0000,callback=7bc3e865,iosb=0307dfc4,arg=001d2e10,cvalue=00000000}, blocking=1, in_data={} ) 001c: ioctl() = PENDING { wait=0000, options=00000002, out_data={} } --- snip ---
I'm not sure what is expected to happen if the server passes NULL overlapped to ConnectNamedPipe() when the pipe was created with FILE_FLAG_OVERLAPPED and io completion port bound to it. Because it doesn't seem to return expected result (operation pending), the server tries to create the named pipe again and again, accompanied with the io completion port. This goes on several seconds, leaving a large number of handles open (handle value increasing):
--- snip --- ... 001c:trace:sync:CreateNamedPipeW (L"\\.\pipe\localhost:6591", 0x40000003, 00000000, 255, 8192, 8192, -1, 0xc03f5c) 001c:trace:ntdll:NtCreateNamedPipeFile (0x307dc98 c0100000 L"\??\pipe\localhost:6591" 0x307dc70 0 5 2 0 0 0 -1 8192 8192 0x307dc64) 001c: create_named_pipe( access=c0100000, attributes=00000040, rootdir=0000, options=00000002, maxinstances=ffffffff, outsize=00002000, insize=00002000, timeout=+4294967.2950000, flags=00000000, name=L"\??\pipe\localhost:6591" ) 001c: create_named_pipe() = 0 { handle=a60c } 001c:trace:sync:CreateIoCompletionPort (0xa60c, 0x228, 7a07c050, 00000002) 001c:trace:ntdll:NtSetInformationFile (0xa60c,0x307df58,0x307df60,0x00000008,0x0000001e) 001c: set_completion_info( handle=a60c, ckey=7a07c050, chandle=0228 ) 001c: set_completion_info() = 0 001c:trace:sync:ConnectNamedPipe (0xa60c,(nil)) 001c:trace:ntdll:NtFsControlFile (0xa60c,(nil),(nil),(nil),0x307dfc4,0x00110008,(nil),0x00000000,(nil),0x00000000) 001c: ioctl( code=FSCTL_PIPE_LISTEN, async={handle=a60c,event=0000,callback=7bc3e865,iosb=0307dfc4,arg=05c57b18,cvalue=00000000}, blocking=1, in_data={} ) 001c: ioctl() = PENDING { wait=0000, options=00000002, out_data={} } ... --- snip ---
At this point it seems a garbage collector thread wakes up and begins to free managed handles along with their native (OS) counterparts. Though not really sure, just a guess...
--- snip --- 0018: *wakeup* signaled=0 001c: event_op() = 0 0018: close_handle( handle=a608 ) 001c: *sent signal* signal=10 0018: close_handle() = 0 0018: close_handle( handle=a604 ) 0018: close_handle() = 0 0018: close_handle( handle=a600 ) 0018: close_handle() = 0 .... 001c: set_thread_context( handle=fffffffe, suspend=1, context={cpu=x86,eip=60000832,esp=0307dc44,ebp=0307dcd0,eflags=00000246,cs=0023,ss=002b,ds=002b,es=002b,fs=0063,gs=006b,eax=00000000,ebx=00000002,ecx=0307dcf4,edx=00000000,esi=00000008,edi=7bc9d554,dr0=00000000,dr1=00000000,dr2=00000000,dr3=00000000,dr6=00000000,dr7=00000000fp.ctrl=ffff037f,fp.status=ffff0020,fp.tag=ffffffff,fp.err_off=79f13c4e,fp.err_sel=00000010,fp.data_off=0307dde0,fp.data_sel=0000002b,fp.cr0npx=00000020,fp.reg0=0,fp.reg1=9,fp.reg2=11,fp.reg3=0.0643275,fp.reg4=6.29146e+06,fp.reg5=6.29146e+06,fp.reg6=2.09715e+06,fp.reg7=2.09715e+06,extended={0020037f,077c0000,79f13c4e,00000000,0307dde0,00000000,00001fa0,0000ffff,00000000,00000000,00000000,00000000,00000000,90000000,00004002,00000000,00000000,b0000000,00004002,00000000,883be20f,83be20ef,00003ffb,00000000,00000000,c0000000,00004015,00000000,00000000,c0000000,00004015,00000000,00000000,80000000,00004014,00000000,00000000,80000000,00004014,00000000,00bde63c,00bde6f4,00bde704,00bde7bc,00bde7cc,00bde884,00bde894,00bde94c,00bde95c,00bdea14,00bdea24,00bdeadc,00bdeaec,00bdeba4,00bdebb4,00bdec6c,00bdec7c,00bded34,00bded44,00bdedfc,00bdee0c,00bdeec4,00bdeed4,00bdef8c,00bdef9c,00bdf054,00bdf064,00bdf11c,00bdf12c,00bdf1e4,00bdf1f4,00bdf2ac,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000}} ) 001c: set_thread_context() = 0 { self=1 } 0018: close_handle( handle=a354 ) 0018: close_handle() = 0 --- snip ---
The originating server thread which created all the pipe instances and io completion ports is woken up and exception is thrown due to handles forcibly closed:
--- snip --- ... 001c: select( flags=4, cookie=7ffcb2dc, signal=0000, prev_apc=a350, timeout=1c9e131b6429e26 (-0.0001000), result={APC_ASYNC_IO,status=HANDLES_CLOSED,total=2045739617,apc=00000000}, handles={} ) 001c: select() = USER_APC { timeout=1c9e131b6429e26 (-0.0001000), call={APC_ASYNC_IO,func=7bc3e865,user=05c57ab8,sb=0307dfc4,status=HANDLES_CLOSED}, apc_handle=a34c } 0018: close_handle( handle=a348 ) 0018: close_handle() = 0 ... 001c: get_thread_context( handle=fffffffe, flags=00000000, suspend=1 ) 001c: get_thread_context() = 0 { self=1, context={cpu=x86,eip=60000832,esp=0307dc44,ebp=0307dcd0,eflags=00000246,cs=0023,ss=002b,ds=002b,es=002b,fs=0063,gs=006b,eax=00000000,ebx=00000002,ecx=0307dcf4,edx=00000000,esi=00000008,edi=7bc9d554,dr0=00000000,dr1=00000000,dr2=00000000,dr3=00000000,dr6=00000000,dr7=00000000fp.ctrl=ffff037f,fp.status=ffff0020,fp.tag=ffffffff,fp.err_off=79f13c4e,fp.err_sel=00000010,fp.data_off=0307dde0,fp.data_sel=0000002b,fp.cr0npx=00000020,fp.reg0=0,fp.reg1=9,fp.reg2=11,fp.reg3=0.0643275,fp.reg4=6.29146e+06,fp.reg5=6.29146e+06,fp.reg6=2.09715e+06,fp.reg7=2.09715e+06,extended={0020037f,077c0000,79f13c4e,00000000,0307dde0,00000000,00001fa0,0000ffff,00000000,00000000,00000000,00000000,00000000,90000000,00004002,00000000,00000000,b0000000,00004002,00000000,883be20f,83be20ef,00003ffb,00000000,00000000,c0000000,00004015,00000000,00000000,c0000000,00004015,00000000,00000000,80000000,00004014,00000000,00000000,80000000,00004014,00000000,00bde63c,00bde6f4,00bde704,00bde7bc,00bde7cc,00bde884,00bde894,00bde94c,00bde95c,00bdea14,00bdea24,00bdeadc,00bdeaec,00bdeba4,00bdebb4,00bdec6c,00bdec7c,00bded34,00bded44,00bdedfc,00bdee0c,00bdeec4,00bdeed4,00bdef8c,00bdef9c,00bdf054,00bdf064,00bdf11c,00bdf12c,00bdf1e4,00bdf1f4,00bdf2ac,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000}} } 001c:trace:seh:raise_exception code=c0000005 flags=0 addr=0x79ef8261 ip=79ef8261 tid=001c 001c:trace:seh:raise_exception info[0]=00000001 001c:trace:seh:raise_exception info[1]=7fffffe6 001c:trace:seh:raise_exception eax=00a5ec4c ebx=00000000 ecx=00a5ec8c edx=02958020 esi=001d4410 edi=00000017 001c:trace:seh:raise_exception ebp=8000000a esp=0307dfd0 cs=0023 ds=002b es=002b fs=0063 gs=006b flags=00010246 001c:trace:seh:call_vectored_handlers calling handler at 0x6972e426 code=c0000005 flags=0 001c:trace:seh:call_vectored_handlers handler at 0x6972e426 returned 0 001c:trace:seh:call_vectored_handlers calling handler at 0x7b8408e7 code=c0000005 flags=0 001c:trace:seh:call_vectored_handlers handler at 0x7b8408e7 returned 0 001c:trace:seh:call_stack_handlers calling handler at 0x7a319444 code=c0000005 flags=0 001c:trace:seh:call_stack_handlers handler at 0x7a319444 returned 1 001c:trace:seh:call_stack_handlers calling handler at 0x79f948ec code=c0000005 flags=0 --- snip ---
There will be nested exceptions thereafter due to other known .NET bugs but this is the initial one.
Regards