http://bugs.winehq.org/show_bug.cgi?id=14550
--- Comment #3 from Saulius K. saulius2@gmail.com 2008-08-15 09:21:44 --- Created an attachment (id=15429) --> (http://bugs.winehq.org/attachment.cgi?id=15429) interesting excerpts from a full debug log
My try to analyse the situation follows. Test app (BasicRecognition.exe) initializes COM libraries and Explorer.exe gets launched. Then test app tries to create instance of an InkRecognizerContext class. This way INKOBJ.DLL (native) gets loaded. And for some reason new threads of Explorer.exe starts creating plus entering new apartments (8000cafe) and then last of them waits for some rpc completion. The same follows for InkCollector class and then for InkRectangle class.
After this Explorer.exe tries to instantiate TabletManager class. As the class isn't registered as in-proc server, separate process gets launched from the thread of Explorer:
0019:trace:ole:create_server activating local server L"C:\windows\system32\wisptis.exe -Embedding" for {a5b020fd-e04b-4e67-b65a-e7deed25b2cf}
After the server is launched, the same Explorer thread starts doing CoWaitForMultipleHandles synchronization for a longer time (~9993 times). During it four lines are repeated:
0019:trace:ole:CoWaitForMultipleHandles (0x00000000, 0x000003e8, 0, (nil), 0x7e5612d8) 0019:trace:ole:CoWaitForMultipleHandles waiting for rpc completion 0019:err:ole:CoWaitForMultipleHandles Unexpected wait termination: -1, 87 0019:trace:ole:CoWaitForMultipleHandles -- 0x8000ffff
Every time since now the function fails with E_UNEXPECTED. But rarely some debug info from the main server thread pops in, eg:
001f:fixme:process:SetProcessShutdownParameters (00000002, 00000000): partial stub. 001f:fixme:winstation:OpenInputDesktop (0,0,2000000): stub 001f:trace:ole:CoInitializeEx ((nil), 0) 001f:trace:ole:CoInitializeEx () - Initializing the COM libraries 001f:trace:ole:RunningObjectTableImpl_Initialize 001f:trace:ole:apartment_construct creating new apartment, model=0 001f:trace:ole:apartment_construct Created apartment on OXID 1e0000cafe 001f:fixme:ole:CoInitializeSecurity (0x12da70,-1,(nil),(nil),4,3,(nil),0,(nil)) - stub! 001f:fixme:atl:AtlModuleRegisterWndClassInfoW 0x1027098 0x1027980 0x12db50 semi-stub 001f:trace:ole:CoRegisterClassObject ({a5b020fd-e04b-4e67-b65a-e7deed25b2cf},0x12db10,0x00000004,0x00000001,0x102cf74) 001f:trace:ole:CoMarshalInterface (0x12dff8, {00000001-0000-0000-c000-000000000046}, 0x12db10, 0, (nil), MSHLFLAGS_TABLESTRONG) 001f:trace:ole:CoGetStandardMarshal ({00000001-0000-0000-c000-000000000046},0x12db10,0,(nil),1,0x33fcac) 001f:trace:ole:CoMarshalInterface Using standard marshaling 001f:trace:ole:CoMarshalInterface Calling IMarshal::MarshalInterace 001f:trace:ole:StdMarshalImpl_MarshalInterface (...,{00000001-0000-0000-c000-000000000046},...) 001f:trace:rpc:RpcServerUseProtseqEpW (L"ncalrpc",10,L"\pipe\OLE_0000001e0000cafe",(nil)) 001f:trace:rpc:RpcServerUseProtseqEpExW (L"ncalrpc",10,L"\pipe\OLE_0000001e0000cafe",(nil),{12,0,0}) 001f:trace:rpc:alloc_serverprotoseq new protseq 0x12e090 created for ncalrpc 001f:trace:rpc:RPCRT4_CreateConnection connection: 0x12e128 001f:trace:rpc:rpcrt4_conn_create_pipe listening on \.\pipe\lrpc\pipe\OLE_0000001e0000cafe 001f:trace:ole:RemUnknown_QueryInterface (0x12e100)->({00000131-0000-0000-c000-000000000046}, 0x33f990) 001f:trace:ole:RemUnknown_AddRef 0x12e100 before: 1 001f:trace:ole:CoGetPSClsid () riid={00000131-0000-0000-c000-000000000046}, pclsid=0x33f998 001f:trace:ole:WINE_StringFromCLSID 0x7edcbe40->{00000131-0000-0000-C000-000000000046} 001f:trace:ole:__CLSIDFromString L"{00000320-0000-0000-C000-000000000046}" -> 0x33f998 001f:trace:ole:CoGetPSClsid () Returning CLSID={00000320-0000-0000-c000-000000000046} 001f:trace:ole:CoGetClassObject CLSID: {00000320-0000-0000-c000-000000000046}, IID: {d5f569d0-593b-101a-b569-08002b2dbf7a} 001f:trace:ole:WINE_StringFromCLSID 0x33f998->{00000320-0000-0000-C000-000000000046} 001f:trace:ole:apartment_getclassobject calling ole32!DllGetClassObject 001f:trace:ole:PSFacBuf_CreateStub ({00000131-0000-0000-c000-000000000046},0x12e100,0x33f994) 001f:trace:ole:RemUnkStub_Connect (0x12e1e0)->Connect(0x12e100) 001f:trace:ole:RemUnknown_AddRef 0x12e100 before: 2 001f:trace:ole:get_stub_manager_from_object not found for object 0x12e100 001f:trace:ole:marshal_object constructing new stub manager 001f:trace:ole:RemUnknown_AddRef 0x12e100 before: 3 001f:trace:ole:new_stub_manager Created new stub manager (oid=1) at 0x12e1f8 for object with IUnknown 0x12e100 001f:trace:ole:stub_manager_new_ifstub oid=1, stubbuffer=0x12e1e0, iptr=0x12e100, iid={00000131-0000-0000-c000-000000000046} 001f:trace:ole:RemUnkStub_AddRef (0x12e1e0)->AddRef() 001f:trace:ole:RemUnknown_AddRef 0x12e100 before: 4 001f:trace:ole:stub_manager_new_ifstub ifstub 0x12e298 created with ipid {ffffffff-ffff-ffff-feca-00001e000000} 001f:trace:ole:RemUnkStub_Release (0x12e1e0)->Release() 001f:trace:ole:RemUnknown_Release 0x12e100 after: 4 001f:trace:ole:stub_manager_ext_addref added 5 refs to 0x12e1f8 (oid 1), rc is now 5 001f:trace:ole:RPC_RegisterInterface ({00000131-0000-0000-c000-000000000046}) 001f:trace:ole:RPC_RegisterInterface Creating new interface 001f:trace:rpc:RpcServerRegisterIfEx (0x12e2fc,(null),(nil),3,1234,(nil)) 001f:trace:rpc:RpcServerRegisterIf2 (0x12e2fc,(null),(nil),3,1234,4294967295,(nil)) 001f:trace:rpc:RpcServerRegisterIf2 interface id: {00000131-0000-0000-c000-000000000046} 0.0 001f:trace:rpc:RpcServerRegisterIf2 transfer syntax: {00000000-0000-0000-0000-000000000000} 0.0 001f:trace:rpc:RpcServerRegisterIf2 dispatch table: 0x7edddb40 001f:trace:rpc:RpcServerRegisterIf2 dispatch table count: 1 001f:trace:rpc:RpcServerRegisterIf2 entry 0: 0x7eda2870 001f:trace:rpc:RpcServerRegisterIf2 reserved: 0 001f:trace:rpc:RpcServerRegisterIf2 protseq endpoint count: 0 001f:trace:rpc:RpcServerRegisterIf2 default manager epv: (nil) 001f:trace:rpc:RpcServerRegisterIf2 interpreter info: (nil) 001f:trace:rpc:RPCRT4_start_listen orMultipleHandles waiting for rpc completion
(note: the last line got corrupted for some reason)
and
0020:trace:ole:DllMain 0x7ed50000 0x2 (nil) 0020:trace:rpc:RPCRT4_server_thread (the_arg == ^0x12e090) 001f:trace:ole:stub_manager_int_release after 1 001f:trace:ole:RemUnknown_Release 0x12e100 after: 3 001f:trace:ole:CoGetPSClsid () riid={00000001-0000-0000-c000-000000000046}, pclsid=0x33fbb8 001f:trace:ole:WINE_StringFromCLSID 0x7edd04a4->{00000001-0000-0000-C000-000000000046} 001f:trace:ole:__CLSIDFromString L"{00000320-0000-0000-C000-000000000046}" -> 0x33fbb8 001f:trace:ole:CoGetPSClsid () Returning CLSID={00000320-0000-0000-c000-000000000046} 001f:trace:ole:CoGetClassObject CLSID: {00000320-0000-0000-c000-000000000046}, IID: {d5f569d0-593b-101a-b569-08002b2dbf7a} 001f:trace:ole:WINE_StringFromCLSID 0x33fbb8->{00000320-0000-0000-C000-000000000046}
and
001f:trace:ole:PSFacBuf_CreateStub ({00000001-0000-0000-c000-000000000046},0x12db10,0x33fbb4) 001f:trace:ole:get_stub_manager_from_object not found for object 0x12db10 001f:trace:ole:marshal_object constructing new stub manager 001f:trace:ole:new_stub_manager Created new stub manager (oid=2) at 0x12e3f0 for object with IUnknown 0x12db10 001f:trace:ole:stub_manager_new_ifstub oid=2, stubbuffer=0x12e3d8, iptr=0x12db10, iid={00000001-0000-0000-c000-000000000046} 001f:trace:rpc:UuidCreate {3cf033a0-54bc-11dd-e181-000b5dcca6e6} 001f:trace:ole:stub_manager_new_ifstub ifstub 0x12e490 created with ipid {00000001-001f-001e-e181-000b5dcca6e6} 001f:trace:ole:stub_manager_ext_addref added 1 refs to 0x12e3f0 (oid 2), rc is now 1 001f:trace:ole:RPC_RegisterInterface ({00000001-0000-0000-c000-000000000046}) 001f:trace:ole:RPC_RegisterInterface Creating new interface 001f:trace:rpc:RpcServerRegisterIfEx (0x12e4f4,(null),(nil),3,1234,(nil)) 001f:trace:rpc:RpcServerRegisterIf2 (0x12e4f4,(null),(nil),3,1234,4294967295,(nil)) 001f:trace:rpc:RpcServerRegisterIf2 interface id: {00000001-0000-0000-c000-000000000046} 0.0 001f:trace:rpc:RpcServerRegisterIf2 transfer syntax: {00000000-0000-0000-0000-000000000000} 0.0 001f:trace:rpc:RpcServerRegisterIf2 dispatch table: 0x7edddb40 001f:trace:rpc:RpcServerRegisterIf2 dispatch table count: 1 001f:trace:rpc:RpcServerRegisterIf2 entry 0: 0x7eda2870 001f:trace:rpc:RpcServerRegisterIf2 reserved: 0 001f:trace:rpc:RpcServerRegisterIf2 protseq endpoint count: 0 001f:trace:rpc:RpcServerRegisterIf2 default manager epv: (nil) 001f:trace:rpc:RpcServerRegisterIf2 interpreter info: (nil) 001f:trace:rpc:RPCRT4_start_listen 001f:trace:ole:stub_manager_int_release after 1 001f:trace:ole:CoMarshalInterface completed with hr 0x00000000
and
0021:trace:ole:DllMain 0x7ed50000 0x2 (nil) 0021:trace:ole:local_server_thread Starting threader for {a5b020fd-e04b-4e67-b65a-e7deed25b2cf}. 0021:trace:ole:WINE_StringFromCLSID 0x12e020->{A5B020FD-E04B-4E67-B65A-E7DEED25B2CF}
and
0022:trace:ole:CoInitializeEx ((nil), 0) 0022:trace:ole:apartment_get_or_create entering the multithreaded apartment 1e0000cafe 0022:trace:ole:apartment_addref 1e0000cafe: before = 1 0022:fixme:winstation:OpenInputDesktop (0,0,2000000): stub
After the last failing call to CoWaitForMultipleHandles the same thread (0019) of Explorer (which was in wait) starts doing some unmarshalling:
0019:trace:ole:RPC_GetLocalClassObject waiting for L"\\.\pipe\{A5B020FD-E04B-4E67-B65A-E7DEED25B2CF}" 0021:trace:ole:local_server_thread marshalling IClassFactory to client 0019:trace:ole:RPC_GetLocalClassObject read marshal id from pipe 0019:trace:ole:RPC_GetLocalClassObject unmarshalling classfactory 0019:trace:ole:CoUnmarshalInterface (0x1336d8, {00000001-0000-0000-c000-000000000046}, 0x7e561474) 0019:trace:ole:get_unmarshaler_from_stream Using standard unmarshaling 0019:trace:ole:StdMarshalImpl_UnmarshalInterface (...,{00000001-0000-0000-c000-000000000046},....) 0019:trace:ole:StdMarshalImpl_UnmarshalInterface Treating unmarshal from OXID 1e0000cafe as inter-process 0019:trace:ole:unmarshal_object stdobjref: flags = 0000 cPublicRefs = 0 oxid = 1e0000cafe oid = 2 ipid = {00000001-001f-001e-e181-000b5dcca6e6}
This is followed by a quite long RPC negotiation and communication, which end up in an error at creating instance of a class factory. IID used here stands for ITabletManagerP interface:
0024:trace:ole:apartment_addref 1e0000cafe: before = 3 0024:trace:ole:CFStub_Invoke ->CreateInstance({663c73a5-8715-4499-b809-43689a93086b}) 0024:fixme:ole:CFStub_Invoke Failed to create an instance of {663c73a5-8715-4499-b809-43689a93086b} 0024:trace:ole:ServerRpcChannelBuffer_GetBuffer (0x12e4d0)->(0x12ea88,{00000001-0000-0000-c000-000000000046}) 0024:trace:rpc:I_RpcGetBuffer (0x12ea88): BufferLength=8 0024:trace:rpc:I_RpcGetBuffer Buffer=0x12e7f0 0024:trace:ole:ServerRpcChannelBuffer_GetBuffer -- 0 0024:trace:ole:apartment_release 1e0000cafe: after = 3 0024:trace:ole:apartment_release 1e0000cafe: after = 2 0024:warn:rpc:process_request_packet exception caught with code 0x80004005 = -2147467259 0024:trace:rpc:process_request_packet freeing Buffer=0x12ecd0 0024:trace:rpc:I_RpcFreeBuffer (0x12ea88) Buffer=0x12e7f0 0025:trace:rpc:RPCRT4_ReceiveWithAuth buffer length = 0 0025:err:rpc:I_RpcReceive we got fault packet with status 0x80004005 0025:trace:ole:rpc_sendreceive_thread completed with status 0x80004005 0026:trace:rpc:RPCRT4_ReceiveWithAuth (0x12eb08, 0x7e0c3a28, 0x12eb98, (nil)) 0026:trace:rpc:RPCRT4_receive_fragment (0x12eb08, 0x7e0c3a28, 0x7e0c39c4) 0027:trace:ole:DllMain 0x7eb40000 0x2 (nil) 0019:trace:ole:ClientRpcChannelBuffer_SendReceive RPC call status: 0x80004005 0019:trace:ole:ClientRpcChannelBuffer_SendReceive hrFault = 0x00000000 0019:trace:ole:ClientRpcChannelBuffer_SendReceive -- 0x80004005 0019:fixme:ole:CFProxy_CreateInstance IRpcChannelBuffer_SendReceive failed with 80004005?
After which the test app fails:
0019:fixme:ole:CoCreateInstance no instance created for interface {663c73a5-8715-4499-b809-43689a93086b} of class {a5b020fd-e04b- 4e67-b65a-e7deed25b2cf}, hres is 0x80004005 0009:trace:ole:CoWaitForMultipleHandles (0x00000000, 0xffffffff, 1, 0x560e28, 0x32f62c) 0009:trace:ole:CoWaitForMultipleHandles waiting for rpc completion or window message 0009:trace:ole:CoWaitForMultipleHandles -- 0x00000000 001a:err:ole:CoWaitForMultipleHandles Unexpected wait termination: 192, 0 001a:trace:ole:CoWaitForMultipleHandles -- 0x8000ffff 001a:trace:ole:CoUninitialize () 001a:trace:ole:apartment_release 80000cafe: after = 4 0009:trace:ole:DllMain (0x7e9f0000,0,0x1) 0009:trace:ole:DllMain 0x7eb40000 0x0 0x1
Would someone suggest some ideas on debugging Ink Recognition app further? Rob, anyone? Observed TIDs relation to processes:
0009 - BasicRecognition.exe (test app)
0017 - Explorer.exe 0018, 0019, 001a, 001b, 001c, 001d
001f - Wisptis.exe (Out-of-process COM server) 0020, 0021, 0022, 0023, 0024, 0025, 0026, 0027