How I Shot My Own Self in the Foot with Semaphores….

…and the lessons I’ve learned. (Seemed like it needed a continuation, yeah?)

So, one of my many (now backlogged) personal projects is to write a Windows Service that copies files from a source directory to a target directory (or directories) and then encrypts the files via the LSA account (if so configured in the app config file). The idea was bourne out of two premises:

  1. As someone who doesn’t currently have a cloud provider, I still need disaster recovery and, if I’m in this position, surely there’s at least one other person in the world in the same boat. Maybe.
  2. This is, perhaps, the more crucial part. We take for granted that we have pretty fat pipes with which to fit all of the cats that we could ever want into the tubes and still have room left over. Other areas of the world still don’t have this luxury. What opportunities are available to them, now that we’re in a mobile-first, cloud-first world?

So, since we’re dealing with disks, I wanted to prevent it being an attack surface and/or prevent disk queuing or thrashing. If you’ve ever seen my project for the Windows Service to download the Bing Images, then you’re already familiar with my preferred route of semaphore use, which is the SemaphoreSlim.

So, I write my service, compile it (via Visual Studio), and install on my machine (via InstallUtil). I fire it up and drop a file into the source folder and, when the timer hits, it copies and encrypts the files to the destinations. O.k., so far, so good. I add a second file and nothing happens. Wait a few more minutes, still nothing.

O.k., I shot myself in the foot, somewhere, but nowhere I need to solve the crime, where I’m also the murderer; which isn’t, necessarily, the easiest task in the world.

So, I check task manager. The service is still running, so we didn’t hit a second-chance exception and the service terminated. O.k., I’m not a total idiot, at least (I hope).

I check the Wait Chain Traversal in Task Manager and it says the process is running fine, nothing is blocked.

O.k…. That makes even less sense. Time to debug it. I create a dump of the process in task manager and crack it open in WinDbg.

I’m using a tool called PDE, which you can get from the public OneDrive shared by Andrew Richards here. I’ll be using it to look for a thread with the most amount of frames. Why? Well, just because nothing is happening, it doesn’t mean that nothing is actually happening.

And, wouldn’t you know it, it looks like a dead-lock:

0:000> !pde.deep 50

6 TID:0718 kb kbn kbnL kn knL kpn kPn
# Child-SP RetAddr Call Site
00 00000040`6d9fd158 00007ff8`a198c7ee ntdll!NtWaitForMultipleObjects+0x14
01 00000040`6d9fd160 00007ff8`9720264e KERNELBASE!WaitForMultipleObjectsEx+0xfe
02 00000040`6d9fd460 00007ff8`972024a8 clr!WaitForMultipleObjectsEx_SO_TOLERANT+0x62
03 00000040`6d9fd4c0 00007ff8`972022a1 clr!Thread::DoAppropriateWaitWorker+0x1e4
04 00000040`6d9fd5c0 00007ff8`971ed336 clr!Thread::DoAppropriateWait+0x7d
05 00000040`6d9fd640 00007ff8`9717703f clr!CLREventBase::WaitEx+0xc4
06 00000040`6d9fd6d0 00007ff8`9717700c clr!Thread::Block+0x27
07 00000040`6d9fd700 00007ff8`97176db1 clr!SyncBlock::Wait+0x19d
08 00000040`6d9fd840 00007ff8`8a05bd08 clr!ObjectNative::WaitTimeout+0xe1
09 00000040`6d9fd9c0 00007ff8`8a05bac9 mscorlib_ni!System.Threading.SemaphoreSlim.WaitUntilCountOrTimeout(Int32, UInt32, System.Threading.CancellationToken)+0x68
0a 00000040`6d9fda10 00007ff8`8a05b872 mscorlib_ni!System.Threading.SemaphoreSlim.Wait(Int32, System.Threading.CancellationToken)+0x149
0b 00000040`6d9fdaa0 00007ff8`37a41a12 mscorlib_ni!System.Threading.SemaphoreSlim.Wait()+0x12
0c 00000040`6d9fdad0 00007ff8`8a071333 Felsokning_Services_ShadowService!Felsokning.Services.ShadowService.ShadowService+<>c__DisplayClass35_2.b__4(System.String)+0x3d2
0d 00000040`6d9fdc40 00007ff8`8a060680 mscorlib_ni!System.Threading.Tasks.Parallel+<>c__DisplayClass17_0`1[[System.__Canon, mscorlib]].b__1()+0x293
0e 00000040`6d9fdd00 00007ff8`8a12a540 mscorlib_ni!System.Threading.Tasks.Task.InnerInvokeWithArg(System.Threading.Tasks.Task)+0x20
0f 00000040`6d9fdd30 00007ff8`896a5ab3 mscorlib_ni!System.Threading.Tasks.Task+<>c__DisplayClass176_0.b__0(System.Object)+0x110
10 00000040`6d9fdda0 00007ff8`896a5944 mscorlib_ni!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+0x163
11 00000040`6d9fde70 00007ff8`896ef565 mscorlib_ni!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+0x14
12 00000040`6d9fdea0 00007ff8`896eec93 mscorlib_ni!System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef)+0x215
13 00000040`6d9fdf50 00007ff8`896f3011 mscorlib_ni!System.Threading.Tasks.Task.ExecuteEntry(Boolean)+0x73
14 00000040`6d9fdf90 00007ff8`896f2eee mscorlib_ni!System.Threading.Tasks.ThreadPoolTaskScheduler.TryExecuteTaskInline(System.Threading.Tasks.Task, Boolean)+0x31
15 00000040`6d9fdfe0 00007ff8`8a05f8d7 mscorlib_ni!System.Threading.Tasks.TaskScheduler.TryRunInline(System.Threading.Tasks.Task, Boolean)+0x19e
16 00000040`6d9fe080 00007ff8`8a06c938 mscorlib_ni!System.Threading.Tasks.Task.InternalRunSynchronously(System.Threading.Tasks.TaskScheduler, Boolean)+0xa7
17 00000040`6d9fe110 00007ff8`8a06dbb7 mscorlib_ni!System.Threading.Tasks.Parallel.ForWorker[[System.__Canon, mscorlib]](Int32, Int32, System.Threading.Tasks.ParallelOptions, System.Action`1, System.Action`2, System.Func`4, System.Func`1, System.Action`1)+0x428
18 00000040`6d9fe1f0 00007ff8`8a06d46e mscorlib_ni!System.Threading.Tasks.Parallel.ForEachWorker[[System.__Canon, mscorlib],[System.__Canon, mscorlib]](System.Collections.Generic.IEnumerable`1, System.Threading.Tasks.ParallelOptions, System.Action`1, System.Action`2, System.Action`3, System.Func`4, System.Func`5, System.Func`1, System.Action`1)+0xd7
19 00000040`6d9fe2b0 00007ff8`37a4155a mscorlib_ni!System.Threading.Tasks.Parallel.ForEach[[System.__Canon, mscorlib]](System.Collections.Generic.IEnumerable`1, System.Action`1)+0x9e
1a 00000040`6d9fe350 00007ff8`8a071333 Felsokning_Services_ShadowService!Felsokning.Services.ShadowService.ShadowService.b__35_3(System.String)+0xea
1b 00000040`6d9fe3e0 00007ff8`8a060680 mscorlib_ni!System.Threading.Tasks.Parallel+<>c__DisplayClass17_0`1[[System.__Canon, mscorlib]].b__1()+0x293
1c 00000040`6d9fe4a0 00007ff8`8a12a540 mscorlib_ni!System.Threading.Tasks.Task.InnerInvokeWithArg(System.Threading.Tasks.Task)+0x20
1d 00000040`6d9fe4d0 00007ff8`896a5ab3 mscorlib_ni!System.Threading.Tasks.Task+<>c__DisplayClass176_0.b__0(System.Object)+0x110
1e 00000040`6d9fe540 00007ff8`896a5944 mscorlib_ni!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+0x163
1f 00000040`6d9fe610 00007ff8`896ef565 mscorlib_ni!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+0x14
20 00000040`6d9fe640 00007ff8`896eec93 mscorlib_ni!System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef)+0x215
21 00000040`6d9fe6f0 00007ff8`896f3011 mscorlib_ni!System.Threading.Tasks.Task.ExecuteEntry(Boolean)+0x73
22 00000040`6d9fe730 00007ff8`896f2eee mscorlib_ni!System.Threading.Tasks.ThreadPoolTaskScheduler.TryExecuteTaskInline(System.Threading.Tasks.Task, Boolean)+0x31
23 00000040`6d9fe780 00007ff8`8a05f8d7 mscorlib_ni!System.Threading.Tasks.TaskScheduler.TryRunInline(System.Threading.Tasks.Task, Boolean)+0x19e
24 00000040`6d9fe820 00007ff8`8a06c938 mscorlib_ni!System.Threading.Tasks.Task.InternalRunSynchronously(System.Threading.Tasks.TaskScheduler, Boolean)+0xa7
25 00000040`6d9fe8b0 00007ff8`8a06dc4f mscorlib_ni!System.Threading.Tasks.Parallel.ForWorker[[System.__Canon, mscorlib]](Int32, Int32, System.Threading.Tasks.ParallelOptions, System.Action`1, System.Action`2, System.Func`4, System.Func`1, System.Action`1)+0x428
26 00000040`6d9fe990 00007ff8`8a06d46e mscorlib_ni!System.Threading.Tasks.Parallel.ForEachWorker[[System.__Canon, mscorlib],[System.__Canon, mscorlib]](System.Collections.Generic.IEnumerable`1, System.Threading.Tasks.ParallelOptions, System.Action`1, System.Action`2, System.Action`3, System.Func`4, System.Func`5, System.Func`1, System.Action`1)+0x16f
27 00000040`6d9fea50 00007ff8`37a41376 mscorlib_ni!System.Threading.Tasks.Parallel.ForEach[[System.__Canon, mscorlib]](System.Collections.Generic.IEnumerable`1, System.Action`1)+0x9e
28 00000040`6d9feaf0 00007ff8`896a5ab3 Felsokning_Services_ShadowService!Felsokning.Services.ShadowService.ShadowService.StartShadowCopyWork(System.Object)+0x246
29 00000040`6d9fec00 00007ff8`896a5944 mscorlib_ni!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+0x163
2a 00000040`6d9fecd0 00007ff8`896db0ba mscorlib_ni!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+0x14
2b 00000040`6d9fed00 00007ff8`896daeb7 mscorlib_ni!System.Threading.TimerQueueTimer.CallCallback()+0xba
2c 00000040`6d9fed60 00007ff8`89695b05 mscorlib_ni!System.Threading.TimerQueueTimer.Fire()+0x87
2d 00000040`6d9fedd0 00007ff8`97046da3 mscorlib_ni!System.Threading.TimerQueue.FireNextTimers()+0x75
2e 00000040`6d9fee50 00007ff8`97046c58 clr!CallDescrWorkerInternal+0x83
2f 00000040`6d9fee90 00007ff8`9704751d clr!CallDescrWorkerWithHandler+0x4e
30 00000040`6d9feed0 00007ff8`97049d14 clr!MethodDescCallSite::CallTargetWorker+0xf8
31 00000040`6d9fefd0 00007ff8`97047ce1 clr!AppDomainTimerCallback_Worker+0x34
32 00000040`6d9ff0c0 00007ff8`97047c50 clr!ManagedThreadBase_DispatchInner+0x39
33 00000040`6d9ff100 00007ff8`97047b8d clr!ManagedThreadBase_DispatchMiddle+0x6c
34 00000040`6d9ff200 00007ff8`97047d1f clr!ManagedThreadBase_DispatchOuter+0x75
35 00000040`6d9ff290 00007ff8`97049cb6 clr!ManagedThreadBase_FullTransitionWithAD+0x2f
36 00000040`6d9ff2f0 00007ff8`97049c16 clr!AppDomainTimerCallback+0x7c
37 00000040`6d9ff350 00007ff8`9704975f clr!ThreadpoolMgr::AsyncTimerCallbackCompletion+0x7e
38 00000040`6d9ff3a0 00007ff8`9704835c clr!UnManagedPerAppDomainTPCount::DispatchWorkItem+0x1bc
39 00000040`6d9ff440 00007ff8`97048105 clr!ThreadpoolMgr::ExecuteWorkRequest+0x64
3a 00000040`6d9ff470 00007ff8`971fefef clr!ThreadpoolMgr::WorkerThreadStart+0xf5
3b 00000040`6d9ff510 00007ff8`a43181f4 clr!Thread::intermediateThreadProc+0x86
3c 00000040`6d9ffbd0 00007ff8`a538a251 kernel32!BaseThreadInitThunk+0x14
3d 00000040`6d9ffc00 00000000`00000000 ntdll!RtlUserThreadStart+0x21

Threads: 1 of 13
Frames : 50
Command: knL

Right, so what’s the state of the SemaphoreSlim, itself?

0:006> !mdt 000001f45a4f3200
000001f45a4f3200 (System.Threading.SemaphoreSlim)
    m_currentCount:0x0 (System.Int32)
    m_maxCount:0x7fffffff (System.Int32)
    m_waitCount:0x6 (System.Int32)
    m_lockObj:000001f45a4f3240 (System.Object)
    m_waitHandle:NULL (System.Threading.ManualResetEvent)
    m_asyncHead:NULL (System.Threading.SemaphoreSlim+TaskNode)
    m_asyncTail:NULL (System.Threading.SemaphoreSlim+TaskNode)

The properties that we care about are the m_currentCount and the m_waitCount. We can look at the source code for SemaphoreSlim and see that these signify what the problem is:

m_currentCount – The semaphore count, initialized in the constructor to the initial value, every release call increments it and every wait call decrements it as long as its value is positive otherwise the wait will block. Its value must be between the maximum semaphore value and zero.

m_waitCount – The number of synchronously waiting threads, it is set to zero in the constructor and increments before blocking the threading and decrements it back after that. It is used as flag for the release call to know if there are waiting threads in the monitor or not.

So, here’s what happened: I leveraged Parallel.ForEach and for each disk action I required the caller to request wait on the semaphore, until it completes and releases the semaphore. The Semaphore’s initial value was stupid-low: 10. So, as soon as the second file was added, we created a condition in which multiple threads (because of parallelization) were requesting locks on the Semaphore and starving it out of being available for any further work.

In theory, this would be 1 lock for the source directory, 2 locks for the two target directories, 1 lock per file (so 2x2x2)… You can quickly see why this was a bad approach, even though it had the best intentions, at heart.

So, now, I’m refactoring the code to leverage threadpooling (or async tasks) and have definitely learned my lesson on resource starvation. 🙂

Thanks for coming to this TEDTalk and happy debugging!

Debugging One of the World’s Worst Error Messages

So, for a project for a friend with cancer, I was setting up something leveraging NextCloud (which another friend set up an account for me on their local instance for). It isn’t important who the friends were or what the project was but it’s slight backdrop into why I didn’t just use another program.

So, I installed the NextCloud desktop client on a Win10 (x64) machine and went to fire it up. Then came this gloriously (and mundanely) generic error message:


Very descriptive and actionable, yeah? (hint: LoadLibrary actually hints as to what’s going on, if you’ve run into assembly referencing before, but we’ll cover that later in this post.)

Well, the first thought is to go to the Event Viewer to see what happened. Only problem is: No events were logged. Anywhere. It never happened. It never even existed.

O.k., time to get medieval on this. Since the window never renders for the application and this seems to happen on initialisation, we’ll have to hook into the application to catch the event[s] in question.

Enter ADPlus. ADPlus has been around for hot-minute and isn’t, precisely, my go-to for debugging puposes; however, it’s definitely handy when you want to catch things happening on start-up.

So, we need to tell adplus to start and to monitor for an instance of the nextcloud application to loaded/referenced/scheduled by the kernel. (Littletid-bit here: The load happens before it’s reference is available in the process list, which is why we get the results you’ll see later-on.)

To tell adplus to “listen” for an instance of this application, we’ll do something like the following:

PS C:\Program Files (x86)\Windows Kits\10\Debuggers\x64> .\adplus.exe -Crash -pmn "nextcloud.exe" -o "C:\Dumps\NextCloud\"
Starting ADPlus
* *
* ADPLus Flash V 7.01.007 08/11/2011 *
* *
* For ADPlus documentation see ADPlus.doc *
* New command line options: *
* -pmn  - process monitor *
* waits for a process to start *
* -po  - optional process *
* won't fail if this process isn't running *
* -mss  *
* Sets Microsoft's symbol server *
* -r   *
* Runs -hang multiple times *
* *
* ADPlusManager - an additional tool to facilitate *
* the use of ADPlus in distributed environments like *
* computer clusters. *
* Learn about ADPlusManager in ADPlus.doc *
* *

Logs and memory dumps will be placed in C:\Dumps\NextCloud\\20190303_105927_Crash_Mode
Starting to monitor the following processes:
Press Enter to stop Monitoring...

Now, that we’ve set adplus to monitor, we fire-up nextcloud.exe. Adplus will attach and create a dump file for the first-chance exception (you can configure it for second-chance only).

So, now we have our dump file. We crack it open in Windbg and let’s look at the stack:

0:000> kncL
# Child-SP RetAddr Call Site
00 000000e2`704fdcc8 00007ff8`5c056db8 ntdll!NtTerminateProcess+0x14
01 000000e2`704fdcd0 00007ff8`5b35d3ba ntdll!RtlExitUserProcess+0xb8
02 000000e2`704fdd00 00007ff8`39a04e48 kernel32!ExitProcessImplementation+0xa
03 000000e2`704fdd30 00007ff8`39a0526e atig6pxx+0x4e48
04 000000e2`704fdef0 00007ff8`1289866c atig6pxx!DrvValidateVersion+0x16
05 000000e2`704fdf20 00007ff8`12898a7d opengl32!pgldrvLoadAndAllocDriverInfo+0x23c
06 000000e2`704fdfb0 00007ff8`128b2ca9 opengl32!LoadAvailableDrivers+0x39d
07 000000e2`704fe630 00007ff8`128b2055 opengl32!wglDescribePixelFormat+0x139
08 000000e2`704fe760 00007ff8`584d4c79 opengl32!wglChoosePixelFormat+0x85
09 000000e2`704fe810 00007ff8`1588eeb0 gdi32full!ChoosePixelFormat+0x39
0a 000000e2`704fe840 00007ff8`1588d540 qwindows+0x3eeb0
0b 000000e2`704fe990 00007ff8`1588eba6 qwindows+0x3d540
0c 000000e2`704fec50 00007ff8`1585c48b qwindows+0x3eba6
0d 000000e2`704fecf0 00007ff8`1585cdba qwindows+0xc48b
0e 000000e2`704fed50 00007ff8`1585ba5c qwindows+0xcdba
0f 000000e2`704fed80 00007ff8`11724d20 qwindows+0xba5c
10 000000e2`704fedf0 00007ff8`019b7770 Qt5Gui!QOpenGLContext::create+0x30
11 000000e2`704fee20 00007ff8`12d012da Qt5WebEngineCore!QtWebEngineCore::initialize+0x120
12 000000e2`704fee70 00007ff8`116ebd4d Qt5Core!QCoreApplicationPrivate::init+0x52a
13 000000e2`704fef30 00007ff8`131035cf Qt5Gui!QGuiApplicationPrivate::init+0x3d
14 000000e2`704ff190 00007ff8`130ff8bb Qt5Widgets!QApplicationPrivate::init+0xf
15 000000e2`704ff1c0 00007ff7`b1db1aa7 Qt5Widgets!QApplication::QApplication+0x5b
16 000000e2`704ff1f0 00007ff7`b1d039d4 nextcloud+0xc1aa7
17 000000e2`704ff300 00007ff7`b1cf1878 nextcloud+0x139d4
18 000000e2`704ff630 00007ff7`b1dc6524 nextcloud+0x1878
19 000000e2`704ff880 00007ff7`b1dc59c2 nextcloud+0xd6524
1a 000000e2`704ff910 00007ff8`5b3581f4 nextcloud+0xd59c2
1b 000000e2`704ff950 00007ff8`5c05a251 kernel32!BaseThreadInitThunk+0x14
1c 000000e2`704ff980 00000000`00000000 ntdll!RtlUserThreadStart+0x21

Normally, you might have to go frame by frame to understand what’s going on but since we don’t have the symbols for nextcloud or qwindow, we can kind of wing it and still figure out what’s going.

As the frames are read from bottom to top (in terms of processing order), the frames of interest to us will be 09 to 02 (which are in bold above). This shows us that GDI and/or OpenGL are looking for a driver that maps to a specific pixel format. We hit a frame in the ATI driver code that we can’t resolve to a method but then we see the call to terminate the process; so, we can probably discern that this is where the error screen is shown (the one with the LoadLibrary error).

So, if we going perusing around the interwebs, we should be able to confirm our suspicions and we’ll find this on MSDN, which has the following notation: “If the function fails, the return value is NULL. To get extended error information, call GetLastError.” Since this happens in native code and we’re unable to ascertain the method called in the ATI driver, it’s safe for us to assume that the ATI driver attempts to load a specified assembly and that assembly doesn’t exist. Also, since the exception is trapped and throw into the window, this is why the .excr record doesn’t exist on the stack. (Yay for native and scopes.)

Easiest solution: Install the nextcloud client on a different machine and do what I need to do or attempt to update the ATI video driver and hope that it resolves the issue. The former is a much more assured way to resolve it, though, so that’s what I did.

When developing programs, it’s important to consider that exceptions might occur in third-party dependencies. This mightn’t be the most productive error messages for users to figure out what’s going on. In fact, I whole-heartedly believe that if I hadn’t ever dealt with loading libraries or debugging, I’d have no clue as to why the program was broken.

This makes the error message one of the world’s crappiest error messages simply because it is inactionable by a user, if a user hasn’t the necessary tools and experience explained above.

So, then, what is the point of the error message?

I get the point, don’t get me wrong, in that lets someone know something went wrong. However, the general nature of the error message, itself, leads much to be desired. What library was it trying to load? Why did it fail? I’m sure I could eventually find a mapping for the NT Status errors that relate to this but why should I, as an end-user, have to resort to that level of depth just to figure out the problem?

The problem is shared between the application writers (nextcloud), GDI, OpenGL, and ATI. Each layer should expect an exception to be possible and to trap and raise it with the requisite information to make it actionable.

This is just… “Something happened. Good luck!”

Thanks for coming to this TEDTalk and I hope that it hasn’t bored you to death, despite it’s brevity.

Debugging: When Recursive Becomes Recursively Too Much

NOTE: This post – drafted, composed, written, and published by me – originally appeared on and is potentially (c) Microsoft.

Recently, I had a problem with a build environment and, specifically, I was receiving a StackOverflowException.

This is what the exception information looked like from the Application Log perspective:

Faulting application name: <redacted>, version: <redacted>, time stamp: 0x5347902e

Faulting module name: clr.dll, version: 4.0.30319.34014, time stamp: 0x52e0b784

Exception code: 0xc00000fd

Fault offset: 0x00002cf4

Faulting process id: 0x1848

Faulting application start time: 0x01cf815776173165

Faulting application path: <redacted>

Faulting module path: C:\Windows\Microsoft.NET\Framework\v4.0.30319\clr.dll

Report Id: b5a7c204-ed4a-11e3-825f-6c3be5144bba

Faulting package full name:

Faulting package-relative application ID:

Not much to go on, right?

I attached adplus (via pmn) and caught the First Chance Exception and process exit dumps. Using the first chance exception dump, I could see (via the stack back-trace) that thread 0 (1eb8) was well over 7,000 frames and that the same objects were repeating on the thread-stack (!dso).

Using this information, I went to the developers of the internal application and they had a compiled fix for me to test and run.

Needless to say, it’s a lot easier to get work done without the StackOverException haunting me

Attached, you’ll find a (heavily-redacted) text file (sort-of) illustrating the recursion in the thread.

Happy debugging! 🙂