I have been debugging a service stop hang. The simple conclusion is that my service had RPC clients hanging around. This is a little how to for how to use windbg to figure out who the offending client is.
The first thing is obvious, the SCM is blocked on thread 0 because my service main has not exited, so let's find that thread. Obviously it is thread 1. What is that thread blocked on? It is trying to close out its RPC server interfaces.
What is RPC waiting for? Normally it is outstanding clients.
==========================================================
0:001> ~* kn
0 Id: 1668.17fc Suspend: 1 Teb: 00331000 Unfrozen
# ChildEBP RetAddr
00 0008fc74 775bddba ntdll!KiFastSystemCallRet [d:\rs1\minkernel\ntos\rtl\i386\userdisp.asm @ 818]
01 0008fc78 749533d0 ntdll!NtWaitForSingleObject+0xa [d:\rs1.obj.x86fre\minkernel\ntdll\daytona\objfre\i386\usrstubs.asm @ 217]
WARNING: Stack unwind information not available. Following frames may be wrong.
02 0008fcec 74953312 KERNELBASE!WaitForSingleObjectEx+0xb0
03 0008fd00 76b5214c KERNELBASE!WaitForSingleObject+0x12
04 0008fdc0 76b5deb1 sechost!StartServiceW+0x1dc
05 0008fe70 76b5102c sechost!RpcClientCapabilityCheck+0x851
06 0008feac 00ab32c0 sechost!StartServiceCtrlDispatcherW+0x5c
07 0008fed0 76aba954 myhost+0x32c0
08 0008fee4 7759a16a KERNEL32!BaseThreadInitThunk+0x24
09 0008ff2c 7759a139 ntdll!__RtlUserThreadStart+0x2b [d:\rs1\minkernel\ntdll\rtlstrt.c @ 997]
0a 0008ff3c 00000000 ntdll!_RtlUserThreadStart+0x1b [d:\rs1\minkernel\ntdll\rtlstrt.c @ 914]
1 Id: 1668.400 Suspend: 1 Teb: 00336000 Unfrozen
# ChildEBP RetAddr
00 0087f480 775c04ca ntdll!KiFastSystemCallRet [d:\rs1\minkernel\ntos\rtl\i386\userdisp.asm @ 818]
01 0087f484 7495dc38 ntdll!NtDelayExecution+0xa [d:\rs1.obj.x86fre\minkernel\ntdll\daytona\objfre\i386\usrstubs.asm @ 2769]
WARNING: Stack unwind information not available. Following frames may be wrong.
02 0087f4ec 7495db8f KERNELBASE!SleepEx+0x98
03 0087f4fc 76c111d0 KERNELBASE!Sleep+0xf
04 (Inline) -------- RPCRT4!PauseExecution+0xb [d:\rs1\minio\rpc\runtime\mtrt\threads.cxx @ 88]
05 0087f538 76be2609 RPCRT4!RPC_SERVER::UnregisterIf+0x2f996 [d:\rs1\minio\rpc\runtime\mtrt\hndlsvr.cxx @ 4838]
06 0087f574 76be2318 RPCRT4!RPC_SERVER::DeactivateInterfaceGroup+0xf3 [d:\rs1\minio\rpc\runtime\mtrt\hndlsvr.cxx @ 11256]
07 0087f5a0 69d78b0b RPCRT4!RPC_SERVER::CloseInterfaceGroup+0xe5 [d:\rs1\minio\rpc\runtime\mtrt\hndlsvr.cxx @ 10484]
08 0087f5b0 69d7c04d my_svc!DestroyRpcServices+0x1b [s:\epix_dev\onecore\base\devices\my_svc\rpcif.cpp @ 540]
09 0087f658 69d7ca5a my_svc!MySvcStop+0x27d [s:\epix_dev\onecore\base\devices\my_svc\srventry.cpp @ 198]
0a 0087f660 77584eee my_svc!MySvcStopThreadProc+0xa [s:\epix_dev\onecore\base\devices\my_svc\srventry.cpp @ 350]
0b 0087f6c4 77575cc2 ntdll!TppSimplepExecuteCallback+0x6e [d:\rs1\minkernel\threadpool\ntdll\simple.c @ 376]
0c 0087f8c8 76aba954 ntdll!TppWorkerThread+0x902 [d:\rs1\minkernel\threadpool\ntdll\worker.c @ 1075]
0d 0087f8dc 7759a16a KERNEL32!BaseThreadInitThunk+0x24
0e 0087f924 7759a139 ntdll!__RtlUserThreadStart+0x2b [d:\rs1\minkernel\ntdll\rtlstrt.c @ 997]
0f 0087f934 00000000 ntdll!_RtlUserThreadStart+0x1b [d:\rs1\minkernel\ntdll\rtlstrt.c @ 914]
2 Id: 1668.1118 Suspend: 1 Teb: 00337000 Unfrozen
# ChildEBP RetAddr
00 008efc68 775bdd9a ntdll!KiFastSystemCallRet [d:\rs1\minkernel\ntos\rtl\i386\userdisp.asm @ 818]
01 008efc6c 77575666 ntdll!NtWaitForWorkViaWorkerFactory+0xa [d:\rs1.obj.x86fre\minkernel\ntdll\daytona\objfre\i386\usrstubs.asm @ 209]
02 008efe7c 76aba954 ntdll!TppWorkerThread+0x2a6 [d:\rs1\minkernel\threadpool\ntdll\worker.c @ 876]
WARNING: Stack unwind information not available. Following frames may be wrong.
03 008efe90 7759a16a KERNEL32!BaseThreadInitThunk+0x24
04 008efed8 7759a139 ntdll!__RtlUserThreadStart+0x2b [d:\rs1\minkernel\ntdll\rtlstrt.c @ 997]
05 008efee8 00000000 ntdll!_RtlUserThreadStart+0x1b [d:\rs1\minkernel\ntdll\rtlstrt.c @ 914]
3 Id: 1668.dc0 Suspend: 1 Teb: 00338000 Unfrozen
# ChildEBP RetAddr
...
==========================================================
Lets figure out what is going on with unregistering the interface. So, we jump to frame 5. Well it looks like some of the locals are optimized out.
==========================================================
0:001> .frame 5
05 0087f538 76be2609 RPCRT4!RPC_SERVER::UnregisterIf+0x2f996 [d:\rs1\minio\rpc\runtime\mtrt\hndlsvr.cxx @ 4838]
0:001> ?? RpcInterface
class RPC_INTERFACE * 0x00000000
0:001> dv -v
@ebx this = 0x0087f4c8
0087f540 RpcInterfaceInformation = 0x69d22450
@edi ManagerTypeUuid = 0x00000000
0087f548 WaitForCallsToComplete = 1
0087f54c FromIfGroup = 0x005f4be0
0087f518 cursor = 0
@esi RpcInterface = 0x00000000
0087f524 NullUUID = {00000000-0000-0000-0000-000000000000}
==========================================================
But, the stack tells me that thread 1 is sleep spinning, waiting for something. Let's see what RPC calls are outstanding.
Looks like there is MyIf RPC context hanging out still.
==========================================================
0:001> !rpcexts.listcalls
RPC_SERVER at 0x5e3180
&RpcAddressDictionary(RPC_SIMPLE_DICT) - 0x5e31b4
Printing 1 items in dictionary: 5e31b4 with 4 slots
(0): 0x5f6e60 - LRPC_ADDRESS
Printing 1 items in dictionary: 5f6ee8 with 4 slots
(0): 0x5f8c10 - LRPC_SMYIF_TYPE
0:001> !obj 0x5f8c10
Dumping LRPC_SMYIF...
LpcServerPort(HANDLE) - 0x174
Address - 0x5f6e60
&Bindings(LRPC_SBINDING_DICT) - 0x5f8c34
&MyIfMutex - 0x5f8c50
&SContextDict - 0x5f8c68
0:001> dt RPCRT4!LRPC_SMYIF 0x5f8c10
+0x000 __VFN_table : 0x76ba9500
+0x004 MagicLong : 0x89abcdef
+0x008 ObjectType : 0n32768
+0x00c RefCount : INTERLOCKED_INTEGER (0x1)
+0x010 MyIfID : 1
+0x014 CtxCollection : 0x005f1a80 ContextCollection
+0x018 TableIndex : 0
+0x01c LpcServerPort : 0x00000174 Void
+0x020 Address : 0x005f6e60 LRPC_ADDRESS
+0x024 Bindings : LRPC_SBINDING_DICT
+0x040 MyIfMutex : MUTEX
+0x058 SContextDict : LRPC_SCONTEXT_DICT
+0x078 MsgNumbers : tagLrpcMessageNumbers
+0x080 CloseMessageNumber : 4
+0x084 IoTarget : tagLRPC_IO_TARGET
+0x090 BindingsCollectionLock : RPC_SRWLOCK
+0x094 ActiveCallsListHead : _LIST_ENTRY [ 0x5f89ec - 0x5f89ec ]
+0x09c CausalFlowsTable : GenericTable
+0x0e0 CachedCalls : LRPC_CACHED_SCALLS
+0x0f0 Flags : (0x0)
+0x0f8 SectionCache : LRPC_SECTION_CACHE
+0x158 PipeHistoryData : (null)
+0x15c CancelHistoryInformation : LRPC_CANCEL_HISTORY_INFORMATION
+0x170 CorrelationId : 0x1124cb
+0x174 DisconnectNotificationEvent : (null)
Lets figure out what outstanding calls there are for that context by looking at the active calls list from above.
Let's take a look at the first one.
==========================================================
0:001> ?0x5f8c10 +94
Evaluate expression: 6261924 = 005f8ca4
0:001> !obj 0x5f89ec
0:001> dt rpcrt4!LRPC_SCALL
+0x000 __VFN_table : Ptr32
+0x004 MagicLong : Uint4B
+0x008 ObjectType : Int4B
+0x00c RefCount : INTERLOCKED_INTEGER
+0x010 pAsync : Ptr32 _RPC_ASYNC_STATE
+0x014 AsyncStatus : Int4B
+0x018 CallingThread : Ptr32 THREAD
+0x01c ReservedNotificationsLock : CSpinLock
+0x020 CachedNotificationInfo : RPC_RESERVED_NOTIFICATION_INFO
+0x03c CachedNotificationInfoAvailable : Int4B
+0x04!opj 0 ReservedNotifications : RPC_RESERVED_NOTIFICATION_INFO_DICT2
+0x06c ActivityID : _GUID
+0x07c DispatchBuffer : Ptr32 Void
+0x080 Flags : SCALL_CompositeFlags
+0x084 SubscribeInfo : Ptr32 NotificationSubscriptionInformation
+0x088 ActiveContextHandles : ServerContextHandle_DICT
+0x0a4 AsyncCallbackState : Ptr32 ASYNC_SEC_CALLBACK_STATE
+0x0a8 Association : Ptr32 LRPC_SASSOCIATION
+0x0ac SBinding : Ptr32 LRPC_SBINDING
+0x0b0 DebugCell : Ptr32 tagDebugCallInfo
+0x0b4 DebugCellTag : Int4B
+0x0b8 RpcMessage : _RPC_MESSAGE
+0x0e4 RuntimeInfo : _RPC_RUNTIME_INFO
+0x0f0 ClientPrincipalName : Ptr32 Wchar
+0x0f4 ClientRequest : Ptr32 _LRPC_REQUEST_MESSAGE
+0x0f8 Response : Ptr32 _LRPC_RESPONSE_MESSAGE
+0x0fc AlpcPortSection : Ptr32 Void
+0x100 LargeReplyDataBuffer : Ptr32 Void
+0x104 LargeRequestDataBuffer : Ptr32 Void
+0x108 LargeReplyDataSize : Uint4B
+0x10c LargeReplyViewSize : Uint4B
+0x110 ClientId : _CLIENT_ID
+0x118 ObjectUuidFlag : Int4B
+0x11c ObjectUuid : RPC_UUID
+0x12c CallId : Uint4B
+0x130 SContext : Ptr32 LRPC_SCONTEXT
+0x134 ActiveCallsEntry : _LIST_ENTRY
+0x13c CausalFlowEntry : _LIST_ENTRY
+0x144 CallCausalFlowNumber : Uint4B
+0x148 AdditionalCallData : LRPC_SCALL::
+0x14c SystemHandles : LRPC_SYSTEM_HANDLE_DATA
+0x15c TokenAttributes : RPCP_ALPC_TOKEN_ATTR
0:001> ?0x5f89ec -134
Evaluate expression: 6260920 = 005f88b8
0:001> !obj 005f88b8
Dumping LRPC_SCALL ...
AsyncStatus - 0x0
pAsync - 0x5f21b0
CallingThread - 0x0
&ActiveContextHandles(ServerContextHandle_DICT) - 0x5f8940
DispatchBuffer - 0x5fff78
pMyIf(LRPC_MYIF) - 0x5f8c10
pSBinding(LRPC_SBINDING) - 0x5e9a10
ObjectUuidFlag - 0x1
ObjectUuid - 49541cea-a719-4e75-8d58-a3a7bfff960e
CallId - 0x2
ClientId.UniqueProcess(CLIENT_ID.HANDLE) - 0x730
ClientId.UniqueThread (CLIENT_ID.HANDLE) - 0x1580
RefCount - 0x1
SContext - 0x0
==========================================================
That is very useful. We now know the thread and process ID of the caller. You can now go crazy with !process and !thread. You can even use WinDbg to attach and debug the caller directly if you want.
This is also useful. It tells you which method in your interface it is actually calling.
==========================================================
0:001> !dict 0x5f8940
Printing 1 items in dictionary: 5f8940 with 4 slots
(0): 0x5e0a40
0:001> dt rpcrt4!ServerContextHandle 0x5e0a40
+0x000 ContextChain : _LIST_ENTRY [ 0x0 - 0x0 ]
+0x008 UserContext : 0x008aad58 Void
+0x00c UserRunDown : 0x69d6b930 void MySvc!HDMYIF_rundown+0
+0x010 ClientId : RPC_CLIENT_TRANSPORT_SEC_IDENTIFIER
+0x018 RpcInterface : 0x005f6580 RPC_INTERFACE
+0x01c CtxGuard : CTXT_HANDLE_INFO
+0x028 Node : GenericTable
+0x04c UserStrict : 0n0
+0x050 Lock : SWMRLock
+0x064 OwnerSID : (null)
+0x068 ReferenceCount : 0n2
+0x06c Flags : 1
+0x070 DeadlockTag : 0n0
0:001> !teb
TEB at 00336000
ExceptionList: 0087f4dc
StackBase: 00880000
StackLimit: 0087c000
SubSystemTib: 00000000
FiberData: 00001e00
ArbitraryUserPointer: 00000000
Self: 00336000
EnvironmentPointer: 00000000
ClientId: 00001668 . 00000400
RpcHandle: 00000000
Tls Storage: 0033602c
PEB Address: 00330000
LastErrorValue: 0
LastStatusValue: 0
Count Owned Locks: 0
HardErrorMode: 0
0:001> dt rpcrt4!LRPC_SCALL 005f88b8
+0x000 __VFN_table : 0x76ba9150
+0x004 MagicLong : 0x89abcdef
+0x008 ObjectType : 0n8192
+0x00c RefCount : INTERLOCKED_INTEGER (0x1)
+0x010 pAsync : 0x005f21b0 _RPC_ASYNC_STATE
+0x014 AsyncStatus : 0n0
+0x018 CallingThread : (null)
+0x01c ReservedNotificationsLock : CSpinLock
+0x020 CachedNotificationInfo : RPC_RESERVED_NOTIFICATION_INFO
+0x03c CachedNotificationInfoAvailable : 0n1
+0x040 ReservedNotifications : RPC_RESERVED_NOTIFICATION_INFO_DICT2
+0x06c ActivityID : _GUID {00000000-0000-0000-0000-000000000000}
+0x07c DispatchBuffer : 0x005fff78 Void
+0x080 Flags : AssocClose+0x8000 (0x8800)
+0x084 SubscribeInfo : 0x005f5ae8 NotificationSubscriptionInformation
+0x088 ActiveContextHandles : ServerContextHandle_DICT
+0x0a4 AsyncCallbackState : (null)
+0x0a8 Association : 0x005f8c10 LRPC_SMYIF
+0x0ac SBinding : 0x005e9a10 LRPC_SBINDING
+0x0b0 DebugCell : (null)
+0x0b4 DebugCellTag : 0n0
+0x0b8 RpcMessage : _RPC_MESSAGE
+0x0e4 RuntimeInfo : _RPC_RUNTIME_INFO
+0x0f0 ClientPrincipalName : (null)
+0x0f4 ClientRequest : 0x005fff20 _LRPC_REQUEST_MESSAGE
+0x0f8 Response : 0x005ecd70 _LRPC_RESPONSE_MESSAGE
+0x0fc AlpcPortSection : (null)
+0x100 LargeReplyDataBuffer : (null)
+0x104 LargeRequestDataBuffer : (null)
+0x108 LargeReplyDataSize : 0
+0x10c LargeReplyViewSize : 0
+0x110 ClientId : _CLIENT_ID
+0x118 ObjectUuidFlag : 0n1
+0x11c ObjectUuid : RPC_UUID
+0x12c CallId : 2
+0x130 SContext : (null)
+0x134 ActiveCallsEntry : _LIST_ENTRY [ 0x5f8ca4 - 0x5f8ca4 ]
+0x13c CausalFlowEntry : _LIST_ENTRY [ 0x0 - 0x0 ]
+0x144 CallCausalFlowNumber : 1
+0x148 AdditionalCallData : LRPC_SCALL::
+0x14c SystemHandles : LRPC_SYSTEM_HANDLE_DATA
+0x15c TokenAttributes : RPCP_ALPC_TOKEN_ATTR
0:001> dx -r1 (*((RPCRT4!_RPC_MESSAGE *)0x5f8970))
(*((RPCRT4!_RPC_MESSAGE *)0x5f8970)) [Type: _RPC_MESSAGE]
[+0x000] Handle : 0x5f88b8 [Type: void *]
[+0x004] DataRepresentation : 0x10 [Type: unsigned long]
[+0x008] Buffer : 0x5fff78 [Type: void *]
[+0x00c] BufferLength : 0x1c [Type: unsigned int]
[+0x010] ProcNum : 0x2 [Type: unsigned int]
[+0x014] TransferSyntax : 0x5f65c4 [Type: _RPC_SYNTAX_IDENTIFIER *]
[+0x018] RpcInterfaceInformation : 0x5f65ac [Type: void *]
[+0x01c] ReservedForRuntime : 0x5f899c [Type: void *]
[+0x020] ManagerEpv : 0x0 [Type: void *]
[+0x024] ImportContext : 0x404 [Type: void *]
[+0x028] RpcFlags : 0x9000 [Type: unsigned long]
0:001> dx -r1 (*((RPCRT4!_RPC_SYNTAX_IDENTIFIER *)0x5f65c4))
(*((RPCRT4!_RPC_SYNTAX_IDENTIFIER *)0x5f65c4)) [Type: _RPC_SYNTAX_IDENTIFIER]
[+0x000] SyntaxGUID : {8A885D04-1CEB-11C9-9FE8-08002B104860} [Type: _GUID]
[+0x010] SyntaxVersion [Type: _RPC_VERSION]
0:001> dt RPCRT4!RPC_CLIENT_INTERFACE 0x5f65ac
+0x000 Length : 0x44
+0x004 InterfaceId : _RPC_SYNTAX_IDENTIFIER
+0x018 TransferSyntax : _RPC_SYNTAX_IDENTIFIER
+0x02c DispatchTable : 0x69d22444 RPC_DISPATCH_TABLE
+0x030 RpcProtseqEndpointCount : 0
+0x034 RpcProtseqEndpoint : (null)
+0x038 Reserved : 0
+0x03c InterpreterInfo : 0x69d22424 Void
+0x040 Flags : 0x4000000
0:001> dx -r1 (*((RPCRT4!_RPC_SYNTAX_IDENTIFIER *)0x5f65b0))
(*((RPCRT4!_RPC_SYNTAX_IDENTIFIER *)0x5f65b0)) [Type: _RPC_SYNTAX_IDENTIFIER]
[+0x000] SyntaxGUID : {850CEE52-3038-4277-B9B4-E05DB8B2C35C} [Type: _GUID]
[+0x010] SyntaxVersion [Type: _RPC_VERSION]
0:001> dx -r1 (*((RPCRT4!RPC_DISPATCH_TABLE *)0x69d22444))
(*((RPCRT4!RPC_DISPATCH_TABLE *)0x69d22444)) [Type: RPC_DISPATCH_TABLE]
[+0x000] DispatchTableCount : 0xe [Type: unsigned int]
[+0x004] DispatchTable : 0x69d217bc [Type: void (**)(_RPC_MESSAGE *)]
[+0x008] Reserved : 0 [Type: long]
No comments:
Post a Comment