Case of the Unexplained Services exe Termination
Hello Debuggers! This is Ron Stock from the Global Escalation Services team and I recently worked an interesting case dispatched to our team because Services.exe was terminating. Nothing good ever happens when Services.exe exits. In this particular case, client RDP sessions were forcibly disconnected from the server and the server machine was shutting down unexpectedly. This is the message encountered at the console on the server.
The customer was able to trigger the crash by changing anything to do with a particular non-Microsoft service in the Services MMC (e.g. changing the Startup Type, changing the dependencies, stopping the service etc...) To protect our vendor friend, I refer to this service as FriendlyService throughout this article. We could have stopped the investigation right here and implicated the FriendlyService vendor, however as you will see, this service was merely a victim.
Investigation
When investigating a process termination, I routinely gather a process dump to start my investigation. The frustrating thing about this instance was how none of our debugging tools were generating a dump file when Services.exe terminated. I tried the usual toolset including AdPlus, ProcDump and DebugDiag to no avail. Despite the lack of data from a memory dump, I was still able to piece together a stack and attack the problem through a creative approach. Debugging is an art.
First I reviewed the application log which was loaded with entries like this one.
11/29/2012 04:29:05 PM Information HE2NTSP208 1004 Application Error N/A Faulting application services.exe, version 5.2.3790.4455, faulting module msvcr80.dll, version 8.0.50727.6195, fault address 0x000000000001df67.
From the event log entry above I was able to determine the faulting module, msvcr80.dll, and the relative offset, 0x000000000001df67. This address is basically the return address of the faulting call. As you can see from the ln output below, the function name was msvcr80!wcscpy_s. As I noted above, I wasn’t able to gather a dump during process termination so I had the customer use ProcDump to snap a dump of Services.exe during normal process operation (not a crash dump).
0:000> ln 00000000`78130000 + 0x000000000001df67
(00000000`7814ded0) msvcr80!wcscpy_s+0x97 | (00000000`7814df80) msvcr80!wcsncpy_s
Next I needed to determine which DLLs in the Services.exe process were calling msvcr80!wcscpy_s by reviewing the import tables of the binaries loading in the process. I used the !peb command to dump out the Process Environment Block (PEB). This gave me the list of base addresses for each loaded DLL. I focused mainly on non-Microsoft binaries. To protect our vendor friends, I renamed the DLL to ThirdPartyServiceMonitor.Dll in this article.
This is the output from the !peb command with the base addresses in the left column.
0:000> !peb
PEB at 000007fffffde000
InheritedAddressSpace: No
ReadImageFileExecOptions: No
BeingDebugged: Yes
ImageBaseAddress: 0000000100000000
Ldr 0000000077fa9f20
Ldr.Initialized: Yes
Ldr.InInitializationOrderModuleList: 00000000000d2df0 . 00000000001a3600
Ldr.InLoadOrderModuleList: 00000000000d2d20 . 000000000019cbc0
Ldr.InMemoryOrderModuleList: 00000000000d2d30 . 000000000019cbd0
Base TimeStamp Module
100000000 49882047 Feb 03 04:45:27 2009 C:\WINDOWS\system32\services.exe
77ec0000 4ecbcd57 Nov 22 10:27:03 2011 C:\WINDOWS\system32\ntdll.dll
77d40000 49c51cdd Mar 21 11:59:09 2009 C:\WINDOWS\system32\kernel32.dll
7ff7fc00000 45d6ccae Feb 17 03:36:46 2007 C:\WINDOWS\system32\msvcrt.dll
7ff7fee0000 4a61f064 Jul 18 10:55:16 2009 C:\WINDOWS\system32\ADVAPI32.dll
7ff7fd30000 4c6ba77a Aug 18 04:27:22 2010 C:\WINDOWS\system32\RPCRT4.dll
7ff7e9c0000 4a37438e Jun 16 02:02:38 2009 C:\WINDOWS\system32\Secur32.dll
77c20000 45e7c5c2 Mar 02 00:35:46 2007 C:\WINDOWS\system32\USER32.dll
7ff7fc90000 490062ac Oct 23 06:40:28 2008 C:\WINDOWS\system32\GDI32.dll
7ff7c680000 45d6ccab Feb 17 03:36:43 2007 C:\WINDOWS\system32\USERENV.dll
7ff7c450000 45d6cc90 Feb 17 03:36:16 2007 C:\WINDOWS\system32\SCESRV.dll
7ff7e490000 45d6cc04 Feb 17 03:33:56 2007 C:\WINDOWS\system32\AUTHZ.dll
7ff77370000 4fedd464 Jun 29 11:14:28 2012 C:\WINDOWS\system32\NETAPI32.dll
7ff7c410000 45d6cca5 Feb 17 03:36:37 2007 C:\WINDOWS\system32\umpnpmgr.dll
7ff7d4d0000 45d6ccb8 Feb 17 03:36:56 2007 C:\WINDOWS\system32\WINSTA.dll
7ff65470000 45d6cc5c Feb 17 03:35:24 2007 E:\Program Files\ThirdPartyDirectory\ThirdParty2.dll
400000 424360e9 Mar 24 19:52:57 2005 C:\WINDOWS\system32\msvcp60.dll
7ff7d500000 45d6cc3b Feb 17 03:34:51 2007 C:\WINDOWS\system32\IMM32.DLL
e50000 4df9462e Jun 15 18:54:22 2011 E:\Program Files\ThirdPartyDirectory\ThirdPartyServiceMonitor.dll
Using the base address of ThirdPartyServiceMonitor, I dumped the header to find the Import Address Table Directory.
0:000> !dh 00000000`00e50000
1E000 [ 758] address [size] of Import Address Table Directory
Using the dps command I dumped all of the functions in the import table of ThirdPartyServiceMonitor.dll. I found msvcr80!wcscpy_s in the function list. This indicates ThirdPartyServiceMonitor.dll makes calls to the msvcr80!wcscpy_s.
0:000> dps 00000000`00e50000+ 1E000 l758/@$ptrsize
<snippet>
.
.
00000000`00e6e458 00000000`7814d890 msvcr80!_wcsnicmp
00000000`00e6e460 00000000`7814db20 msvcr80!_wcsicmp
00000000`00e6e498 00000000`7814ded0 msvcr80!wcscpy_s
.
.
Since this was the only third party DLL with msvcr80!wcscpy_s in its import table, I was able to continue piecing together my stack. ThirdPartyServiceMonitor.dll was calling msvcr80!wcscpy_s and causing Services.exe to crash. At this point in the investigation, the stack looks like this-
msvcr80!wcscpy_s
ThirdPartyServiceMonitor+<offset>
In my quest to continue building my “conceptual” stack without a crash dump file, I reviewed the status code from the “System Shutdown” dialog displayed when Services.exe terminated. Notice the status code -1073741811 in the error. What the heck does that mean?
Well I easily resolved the cryptic status code by passing 0n-1073741811 to the !error command in the debugger. The “0n” prefix indicates the value should be interpreted as decimal rather than hex by the debugger. I also included the negative symbol “-“ because this also appears in status code.
0:030> !error 0n-1073741811
Error code: (NTSTATUS) 0xc000000d (3221225485) - An invalid parameter was passed to a service or function.
Armed with the status code information, I reviewed the msvcr80!wcscpy_s assembly code to determine if this status code was returned at any point. In the assembly I found a call to a function named msvcr80!_invalid_parameter. In context of the message, “an invalid parameter was passed to a service or function”, this certainly sounds like the code path taken.
0:000> uf msvcr80!wcscpy_s
<snippet>
msvcr80!wcscpy_s+0x1a
18 00000000`7814deea e88184feff call msvcr80!_errno(00000000`78136370)
18 00000000`7814deef 4533c9 xor r9d,r9d
18 00000000`7814def2 4533c0 xor r8d,r8d
18 00000000`7814def5 33d2 xor edx,edx
18 00000000`7814def7 33c9 xor ecx,ecx
18 00000000`7814def9 48c744242000000000 mov qword ptr [rsp+20h],0
18 00000000`7814df02 c70016000000 mov dword ptr[rax],16h
18 00000000`7814df08 e873d1feff call msvcr80!_invalid_parameter (00000000`7813b080)
18 00000000`7814df0d b816000000 mov eax,16h
34 00000000`7814df12 4883c438 add rsp,38h
34 00000000`7814df16 c3 ret
It was reasonable to add this call to my conceptual stack because the call tree makes sense.
msvcr80!_invalid_parameter
msvcr80!wcscpy_s
ThirdPartyServiceMonitor+<offset>
Because I’m a curious kind of guy, I unassembled msvcr80!_invalid_parameter to peel back another layer of the onion. To my surprise I found a call to msvcr80!_imp_TerminateProcess. BOOM! This explains why the debugger wasn’t catching the process crash. The process was terminating ‘organically’ through a TerminateProcess call rather than crashing due to an exception, however it was unexpectedly terminating. In other words, all of the services running on the machine were not expecting Services.exe to terminate.
msvcr80!_invalid_parameter+0xd5
<snippet>
88 00000000`7813b155 ff156d200900 call qword ptr [msvcr80!_imp_GetCurrentProcess (00000000`781cd1c8)]
88 00000000`7813b15b ba0d0000c0 mov edx,0C000000Dh
88 00000000`7813b160 488bc8 mov rcx,rax
88 00000000`7813b163 ff1557200900 call qword ptr [msvcr80!_imp_TerminateProcess(00000000`781cd1c0)]
Now I was able to cobble together a fairly accurate stack without a dump file. At this point I could tell ThirdPartyServiceMonitor.dll was passing bad parameters to msvcr80!wcscpy_s. However, this didn’t explain how FriendlyService (mentioned in the blog introduction) was triggering the issue. I needed to go deeper with a live debug by leveraging the stack information I devised.
msvcr80!_imp_TerminateProcess
msvcr80!_invalid_parameter
msvcr80!wcscpy_s
ThirdPartyServiceMonitor+<offset>
On the customer’s server I attached Windbg to the Services.exe process and set a breakpoint on msvcr80!_invalid_parameter.
0:001> bp msvcr80!_invalid_parameter
Then I had the customer reproduce the issue by changing the startup type on FriendlyService in the Services MMC. As I mentioned above, this was one way to trigger the issue. BOOM! My breakpoint hit and looked exactly like the conceptual stack I pieced together. Now I was able to determine what ThirdPartyServiceMonitor was passing to msvcr80!wcscpy_s while broken in with the debugger.
0:035> k
Child-SP RetAddr Call Site
00000000`105deb00 00000000`7814df67 msvcr80!_invalid_parameter+0xe3
00000000`105df0c0 00000000`00e53045 msvcr80!wcscpy_s+0x97
00000000`105df100 00000000`00e5947e ThirdPartyServiceMonitor+0x3045
00000000`105df130 00000000`00e58405 ThirdPartyServiceMonitor+0x947e
00000000`105df180 000007ff`7fd69c75 ThirdPartyServiceMonitor+0x8405
00000000`105df1b0 000007ff`7fe9ccc9 rpcrt4!Invoke+0x65
00000000`105df200 000007ff`7fe9d58d rpcrt4!NdrStubCall2+0x54d
I reviewed the assembly of ThirdPartyServiceMonitor at the point in which it calls msvcr80!wcscpy_s. I discovered that the vendor hardcoded the size of the destination string buffer with 200 hex (512 decimal) while the size of the source string buffer was greater than 512 decimal.
0:035> ub 00000000`00e53045
ThirdPartyServiceMonitor+0x3020:
00000000`00e53020 898324040000 mov dword ptr [rbx+424h],eax
00000000`00e53026 488b4738 mov rax,qword ptr [rdi+38h]
00000000`00e5302a 4c8b4010 mov r8,qword ptr [rax+10h] <<<< Source Buffer
00000000`00e5302e 4d85c0 test r8,r8
00000000`00e53031 7412 je ThirdPartyServiceMonitor+0x3045 (00000000`00e53045)
00000000`00e53033 488d8b28040000 lea rcx,[rbx+428h] <<<< Destination Buffer
00000000`00e5303a ba00020000 mov edx,200h <<<<< Buffer Size hardcoded to 200 hex
00000000`00e5303f ff1553b40100 call qword ptr [ThirdPartyServiceMonitor!PlugControl+0xff38 (00000000`00e6e498)] <<<< call to msvcr80!wcscpy_s
00000000`00e53045 eb16 jmp ThirdPartyServiceMonitor +0x305d (00000000`00e5305d) <<<< return from msvcr80!wcscpy_s
0:035> .formats 200
Evaluate expression:
Hex: 00000000`00000200
Decimal: 512
Here is the definition of wcscpy_s from MSDN
errno_t wcscpy_s(
wchar_t *strDestination, // Location of destination string buffer
size_t numberOfElements, // Size of the destination string buffer.
const wchar_t *strSource // Null-terminated source string buffer.
);
Here are the parameters passed to msvcr80!wcscpy_s. As a reminder, the x64 compiler uses rcx to pass the first parameter, rdx for the second, and r8 for the third. In this case the buffer size was the second parameter in rdx and the source buffer was in r8, the third parameter.
0:035> dq 00000000`00e6e498 l1
00000000`00e6e498 00000000`7814ded0
0:035> ln 00000000`7814ded0
(00000000`7814ded0) msvcr80!wcscpy_s | (00000000`7814df80) msvcr80!wcsncpy_s
Exact matches:
msvcr80!wcscpy_s
Dumping the source string in r8 showed the string was clearly longer than 512 characters.
0:035> dc 00000000`0103b438
00000000`0103b438 003a0000 0049005c 0074006e 00670065 ..:.\.F.r.e.i.n.
00000000`0103b448 00610072 00690074 006e006f 00670041 d.l.y.S.e.r.v.i.
00000000`0103b458 006e0065 005c0074 0069006c 005c0062 c.e.\.l.i.b.\..
.
.
.
0:035> dc
00000000`0103b738 00650070 002e0072 00700061 002e0070 p.e.r...a.p.p...
00000000`0103b748 00610070 00610072 0065006d 00650074 p.a.r.a.m.e.t.e.
00000000`0103b758 002e0072 003d0031 00770020 00610072 r...1.=. .w.r.a.
00000000`0103b768 00700070 00720065 0061002e 00700070 p.p.e.r...a.p.p.
00000000`0103b778 0070002e 00720061 006d0061 00740065 ..p.a.r.a.m.e.t.
00000000`0103b788 00720065 0032002e 0020003d 00720077 e.r...2.=. .w.r.
00000000`0103b798 00700061 00650070 002e0072 00700061 a.p.p.e.r...a.p.
00000000`0103b7a8 002e0070 00610070 00610072 0065006d p...p.a.r.a.m.e.
0:035> dc
00000000`0103b7b8 00650074 002e0072 003d0033 00770020 t.e.r...3.=. .w.
00000000`0103b7c8 00610072 00700070 00720065 0061002e r.a.p.p.e.r...a.
00000000`0103b7d8 00700070 0070002e 00720061 006d0061 p.p...p.a.r.a.m.
00000000`0103b7e8 00740065 00720065 0034002e 0020003d e.t.e.r...4.=. .
00000000`0103b7f8 00720077 00700061 00650070 002e0072 w.r.a.p.p.e.r...
00000000`0103b808 00700061 002e0070 00610070 00610072 a.p.p...p.a.r.a.
00000000`0103b818 0065006d 00650074 002e0072 003d0035 m.e.t.e.r...5.=.
00000000`0103b828 00770020 00610072 00700070 00720065 .w.r.a.p.p.e.r.
It was not hard to figure out this string was the imagefile path located at HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\FriendlyService. You can see from the string that service takes parameters which increased the size of the image path beyond 512 characters.
FriendlyService\lib\friendly.3\sbin\friendlywindows-x86-32.exe-s E:\ FriendlyService\conf\wrapper.conf set.DATA_APP=apia "set.DATA_APP_LONG= FriendlyServiceVendor" set.DATA_EXE=E:\ FriendlyService\bin\..\lib\friendly.3\bin set.DATA_HOME=E:\ FriendlyService\bin\..\lib\friendly.3 set.INSTALL_DIR=E:\ FriendlyService\bin\.. wrapper.working.dir=E:\ FriendlyService\bin\.. wrapper.app.parameter.1= wrapper.app.parameter.2= wrapper.app.parameter.3= wrapper.app.parameter.4= wrapper.app.parameter.5= wrapper.app.parameter.6= wrapper.app.parameter.7= wrapper.app.parameter.8= wrapper.app.parameter.9=
The ThirdPartyServiceMonitor hooks any changes made to a service (e.g. changing the Startup Type, changing the dependencies, stopping the service etc...). After hooking the change, ThirdPartyServiceMonitor.dll performs a string copy of the service’s image file path. In most cases this works like a champ, however in this instance, the FriendlyService image path from vendor 1 is really long and the ThirdPartyServiceMonitor from vendor 2 doesn’t account for service image paths exceeding 512 characters. This is the perfect storm! ThirdPartyServiceMonitor needs to remove the hardcoded buffer size.
This example occurred on Windows Server 2003. Starting in Windows 7 and Windows Server 2008 R2, Windows has added functionality for catching processes that exit ‘organically’ through a TerminateProcess call. You can find information on this added functionality on MSDN.
Comments
Anonymous
January 30, 2013
This was awesome, more articles like this please! Thanks for sharing Ron.Anonymous
January 30, 2013
Waauw, great work! I love these articles on how to solve these kinds of mistery's :-)Anonymous
January 30, 2013
Wow, amazing article! Especially the brilliant way you created a conceptual stack when faced with the challenge of no memory dump. Thanks for writing this up and sharing it :-)Anonymous
January 31, 2013
Now that was very cool, well done. It also clearly shows the value the Debugger plays when it strings stack dumps together for you.Anonymous
February 01, 2013
The comment has been removedAnonymous
February 02, 2013
?Anonymous
February 05, 2013
Adplus can be configured to create a dump upon TerminateProcess() call, just specify the "-CTCFG" flag. (In our case, it was a 3rd party DLL calling TerminateProcess() without any warning or notice.)Anonymous
March 01, 2013
Great detective work, good read! It's nice for sure to have a function named msvcr80!_invalid_parameter for an "easier" follow-up after that System Shutdown dialog.Anonymous
September 22, 2015
The comment has been removed