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!

Exchange 2010: AD Recipient Cache and Locking Threads in EdgeTransport – Or How We Figured Out Something Wasn’t Right With Mail Stuck in Submission Queue

NOTE: This post – drafted, composed, written, and published by me – originally appeared on https://blogs.technet.microsoft.com/johnbai and is potentially (c) Microsoft.

A while ago we had an issue, wherein SCOM fired for message queue length for messages in Submission. When we went to take a look, the messages were stuck in Submission and weren’t really going anywhere. Took a dump of EdgeTransport, paused Transport, and the queues eventually flushed.

Opened Windbg against the dump and here’s what was going on: Every time a flood of email would come, Transport would see that the local recipient cache for a group was out of date. Threads would spin-up (typically, per message) to update the recipient cache. Since this is an AD call, a lock is used. The lock is owned by the thread until it’s released, which means we need to wait for the LDAP call to complete before the next thread can enter the critical section. Repeat ad infinim. The issue that complicated this matter is that the refresh was for the same group of sixteen-thousand-plus users, each time.

In the dump, this is how I went down the rabbit hole. First, I checked for any locks that may be blocking in the process:

 

!locks

 

CritSec Wldap32!SelectLock1+0 at 000007fefdd5ada0

WaiterWoken        No

LockCount          0

RecursionCount     1

OwningThread       2a18

EntryCount         0

ContentionCount    2

*** Locked

 

I then checked the another thread to see if it was aware that there was contention (it was):

 

00 00000000`2b8fd4f8 000007fe`fd991430 ntdll!ZwWaitForMultipleObjects+0xa

01 00000000`2b8fd500 00000000`77731723 KERNELBASE!WaitForMultipleObjectsEx+0xe8

02 00000000`2b8fd600 000007fe`f830d0a5 kernel32!WaitForMultipleObjectsExImplementation+0xb3

03 00000000`2b8fd690 000007fe`f8311aa9 mscorwks!WaitForMultipleObjectsEx_SO_TOLERANT+0xc1

04 00000000`2b8fd730 000007fe`f8344e95 mscorwks!Thread::DoAppropriateAptStateWait+0x41

05 00000000`2b8fd790 000007fe`f8427d94 mscorwks!Thread::DoAppropriateWaitWorker+0x191

06 00000000`2b8fd890 000007fe`f83ee48a mscorwks!Thread::DoAppropriateWait+0x5c

07 00000000`2b8fd900 000007fe`f82f077d mscorwks!CLREvent::WaitEx+0xbe

08 00000000`2b8fd9b0 000007fe`f843e6ea mscorwks!AwareLock::EnterEpilog+0xc9

09 00000000`2b8fda80 000007fe`f83336db mscorwks!AwareLock::Enter+0x72

0a 00000000`2b8fdab0 000007fe`f88b308f mscorwks!AwareLock::Contention+0x1fb

0b 00000000`2b8fdb80 000007fe`f2ff2beb mscorwks!JITutil_MonContention+0xdf

0c 00000000`2b8fdd30 000007fe`f2ff318f Microsoft_Exchange_Data_Directory_ni!Microsoft.Exchange.Data.Directory.IsMemberOfProvider.AutoRefreshCache`3[[System.__Canon, mscorlib],[System.__Canon, mscorlib],[System.__Canon, mscorlib]].CreateAndCache(System.__Canon, System.__Canon, Boolean)+0x16cb

0d 00000000`2b8fddf0 000007fe`f324dd16 Microsoft_Exchange_Data_Directory_ni!Microsoft.Exchange.Data.Directory.IsMemberOfProvider.AutoRefreshCache`3[[System.__Canon, mscorlib],[System.__Canon, mscorlib],[System.__Canon, mscorlib]].GetValue(System.__Canon, System.__Canon)+0x192f

0e 00000000`2b8fdeb0 000007fe`f324e2a0 Microsoft_Exchange_Data_Directory_ni!Microsoft.Exchange.Data.Directory.IsMemberOfProvider.IsMemberOfResolver`1[[System.__Canon, mscorlib]].IsMemberOf(Microsoft.Exchange.Data.Directory.Recipient.ADRecipientSession, System.Guid, System.Guid)+0x25b6a6

0f 00000000`2b8fe090 000007fe`f0940c15 Microsoft_Exchange_Data_Directory_ni!Microsoft.Exchange.Data.Directory.IsMemberOfProvider.IsMemberOfResolver`1[[System.__Canon, mscorlib]].IsMemberOf(Microsoft.Exchange.Data.Directory.Recipient.ADRecipientSession, Microsoft.Exchange.Data.Directory.ADObjectId, System.__Canon)+0x25bfd0

10 00000000`2b8fe180 000007fe`e0fc7267 Microsoft_Exchange_Transport_ni!Microsoft.Exchange.Transport.RecipientAPI.AddressBookImpl.IsMemberOf(Microsoft.Exchange.Data.Transport.RoutingAddress, Microsoft.Exchange.Data.Transport.RoutingAddress)+0x135

11 00000000`2b8fe200 000007fe`f245c46a Microsoft_Exchange_MessagingPolicies_Rules_ni!Microsoft.Exchange.MessagingPolicies.Rules.MembershipChecker.Equals(System.String, System.String)+0x47

12 00000000`2b8fe250 000007fe`e0fd5584 Microsoft_Exchange_Net_ni!Microsoft.Exchange.MessagingPolicies.Rules.RuleUtils.CompareStringValues(System.Object, System.Object, Microsoft.Exchange.MessagingPolicies.Rules.IStringComparer)+0x7a

13 00000000`2b8fe2a0 000007fe`f2459efe Microsoft_Exchange_MessagingPolicies_Rules_ni!Microsoft.Exchange.MessagingPolicies.Rules.IsMemberOfPredicate.Evaluate(Microsoft.Exchange.MessagingPolicies.Rules.RulesEvaluationContext)+0x74

14 00000000`2b8fe2e0 000007fe`f2459efe Microsoft_Exchange_Net_ni!Microsoft.Exchange.MessagingPolicies.Rules.OrCondition.Evaluate(Microsoft.Exchange.MessagingPolicies.Rules.RulesEvaluationContext)+0x6e

15 00000000`2b8fe360 000007fe`f246a157 Microsoft_Exchange_Net_ni!Microsoft.Exchange.MessagingPolicies.Rules.OrCondition.Evaluate(Microsoft.Exchange.MessagingPolicies.Rules.RulesEvaluationContext)+0x6e

16 00000000`2b8fe3e0 000007fe`e0fd839f Microsoft_Exchange_Net_ni!Microsoft.Exchange.MessagingPolicies.Rules.RulesEvaluator.Run()+0x1b7

 

O.k., so if we’re update the cache, how many times are we doing it? Oh, I see…:

 

0:086> !findstack Microsoft_Exchange_Data_Directory_ni!Microsoft.Exchange.Data.Directory.IsMemberOfProvider.AutoRefreshCache`3 0

Thread 023, 2 frame(s) match

Thread 024, 2 frame(s) match

Thread 025, 2 frame(s) match

Thread 034, 2 frame(s) match

Thread 035, 2 frame(s) match

Thread 036, 2 frame(s) match

Thread 037, 2 frame(s) match

Thread 038, 2 frame(s) match

Thread 039, 2 frame(s) match

Thread 040, 2 frame(s) match

Thread 050, 2 frame(s) match

Thread 051, 2 frame(s) match

Thread 052, 2 frame(s) match

Thread 053, 2 frame(s) match

Thread 054, 2 frame(s) match

Thread 055, 2 frame(s) match

Thread 056, 2 frame(s) match

Thread 057, 2 frame(s) match

Thread 058, 2 frame(s) match

Thread 059, 2 frame(s) match

Thread 060, 2 frame(s) match

Thread 061, 2 frame(s) match

Thread 062, 2 frame(s) match

Thread 063, 2 frame(s) match

Thread 064, 2 frame(s) match

Thread 065, 2 frame(s) match

Thread 066, 2 frame(s) match

Thread 067, 2 frame(s) match

Thread 068, 2 frame(s) match

Thread 069, 2 frame(s) match

Thread 070, 2 frame(s) match

Thread 071, 2 frame(s) match

Thread 072, 2 frame(s) match

Thread 073, 2 frame(s) match

Thread 074, 2 frame(s) match

Thread 075, 2 frame(s) match

Thread 076, 2 frame(s) match

Thread 077, 2 frame(s) match

Thread 078, 2 frame(s) match

Thread 079, 2 frame(s) match

Thread 080, 2 frame(s) match

Thread 081, 2 frame(s) match

Thread 082, 2 frame(s) match

Thread 083, 2 frame(s) match

Thread 084, 2 frame(s) match

Thread 085, 2 frame(s) match

Thread 086, 2 frame(s) match

Thread 087, 2 frame(s) match

 

The thread with the lock has an LDAP call being made:

 

00 00000000`5443cfc8 000007fe`fce91e35 ntdll!ZwWaitForSingleObject+0xa

01 00000000`5443cfd0 000007fe`fce91f96 mswsock!SockWaitForSingleObject+0xe145

02 00000000`5443d050 000007fe`ff1f4efc mswsock!WSPSelect+0xac26

03 00000000`5443d1f0 000007fe`ff1f4e7d ws2_32!DPROVIDER::WSPSelect+0x3c

04 00000000`5443d230 000007fe`fdd13a19 ws2_32!select+0x75a

05 00000000`5443d330 000007fe`fdd199b5 Wldap32!DrainWinsock+0x417

06 00000000`5443d3c0 000007fe`fdd136ec Wldap32!LdapWaitForResponseFromServer+0x646

07 00000000`5443d480 000007fe`fdd1d967 Wldap32!ldap_result_with_error+0x279

08 00000000`5443d520 000007fe`f84abec7 Wldap32!ldap_result+0x74

*** WARNING: Unable to verify checksum for System.DirectoryServices.Protocols.ni.dll

09 00000000`5443d580 000007fe`f1c453ff mscorwks!DoNDirectCall__PatchGetThreadCall+0x7b

0a 00000000`5443d630 000007fe`f1c5c61b System_DirectoryServices_Protocols_ni!DomainBoundILStubClass.IL_STUB(IntPtr, Int32, Int32, System.DirectoryServices.Protocols.LDAP_TIMEVAL, IntPtr ByRef)+0x8f

0b 00000000`5443d720 000007fe`f1c59f79 System_DirectoryServices_Protocols_ni!System.DirectoryServices.Protocols.LdapConnection.ConstructResponse(Int32, System.DirectoryServices.Protocols.LdapOperation, System.DirectoryServices.Protocols.ResultAll, System.TimeSpan, Boolean)+0x2cb

 

It looks like we’re performing this query, at the time of the dump:

 

000000005443d538  00000000e0188bf8  System.String  “(&(memberOf=<GUID=20ff7cf3-3b7e-4767-8669-d2295d6fb0f3>)(!(msExchCU=*)))”

 

0:086> !do 00000000e0188bf8

Name: System.String

MethodTable: 000007fef7747d90

EEClass: 000007fef734e560

Size: 170(0xaa) bytes

GC Generation: 2

(C:\Windows\assembly\GAC_64\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)

String: (&(memberOf=<GUID=20ff7cf3-3b7e-4767-8669-d2295d6fb0f3>)(!(msExchCU=*)))

Fields:

              MT            Field           Offset                 Type VT             Attr            Value Name

000007fef774f000  4000096        8         System.Int32  1 instance               73 m_arrayLength

000007fef774f000  4000097        c         System.Int32  1 instance               72 m_stringLength

000007fef77497d8  4000098       10          System.Char  1 instance               28 m_firstChar

000007fef7747d90  4000099       20        System.String  0   shared           static Empty

                                 >> Domain:Value  00000000004e5e50:000000015fff0370 <<

000007fef7749688  400009a       28        System.Char[]  0   shared           static WhitespaceChars

                                 >> Domain:Value  00000000004e5e50:000000015fff0b90 <<

 

O.k., how many calls against this object are we making?:

 

0:086> !refs 00000000e0188bf8

This command will work faster with an SOSEX heap index.  To build an index, run !bhi.

Objects referenced by 00000000e0188bf8 (System.String):

NONE

 

Objects referencing 00000000e0188bf8 (System.String):

follow 00000000c0393040        80   System.Object[]

follow 00000000c0393108        96   System.Object[]

follow 00000000c04a1928        80   System.DirectoryServices.Protocols.SearchRequest

follow 00000000c04a2960        72   System.Object[]

follow 00000000c0689800        80   System.Object[]

follow 00000000c06898c8        96   System.Object[]

follow 00000000c07c3e68        80   System.DirectoryServices.Protocols.SearchRequest

follow 00000000c07c4de0        72   System.Object[]

follow 00000000c08ba200        80   System.Object[]

follow 00000000c08ba2c8        96   System.Object[]

follow 00000000c0976870        80   System.DirectoryServices.Protocols.SearchRequest

follow 00000000c09777e8        72   System.Object[]

follow 00000000c0fbaf58        80   System.Object[]

follow 00000000c0fbb020        96   System.Object[]

follow 00000000c103fa40        80   System.DirectoryServices.Protocols.SearchRequest

follow 00000000c1046fd0        72   System.Object[]

follow 00000000c113a868        80   System.Object[]

follow 00000000c113a930        96   System.Object[]

follow 00000000c11e75a0        80   System.DirectoryServices.Protocols.SearchRequest

follow 00000000c11e8518        72   System.Object[]

follow 00000000c13b1068        80   System.Object[]

follow 00000000c13b1130        96   System.Object[]

follow 00000000c1547260        80   System.DirectoryServices.Protocols.SearchRequest

follow 00000000c15481d8        72   System.Object[]

follow 00000000c1669338        80   System.Object[]

follow 00000000c1669400        96   System.Object[]

follow 00000000c175b778        80   System.DirectoryServices.Protocols.SearchRequest

follow 00000000c175c6f0        72   System.Object[]

follow 00000000c1904c80        80   System.Object[]

follow 00000000c1904d48        96   System.Object[]

follow 00000000c1acba70        80   System.DirectoryServices.Protocols.SearchRequest

follow 00000000c1acc9e8        72   System.Object[]

follow 00000000c1d03f08        80   System.Object[]

follow 00000000c1d03fd0        96   System.Object[]

follow 00000000c1f8f398        80   System.DirectoryServices.Protocols.SearchRequest

follow 00000000c1f90310        72   System.Object[]

follow 00000000c21bd2f0        80   System.Object[]

follow 00000000c21bd3b8        96   System.Object[]

follow 00000000c243d8a0        80   System.DirectoryServices.Protocols.SearchRequest

follow 00000000c243e818        72   System.Object[]

follow 00000000e0188510       176   Microsoft.Exchange.Data.Directory.ADPagedReader`1[[Microsoft.Exchange.Data.Directory.ADRawEntry, Microsoft.Exchange.Data.Directory]]

follow 00000000f096aea8        80   System.DirectoryServices.Protocols.SearchRequest

follow 00000001106ce9f8        80   System.DirectoryServices.Protocols.SearchRequest

 

CLR Thread 0x49

stack:000000005443d538

stack:000000005443d5d0

stack:000000005443d970

  

O.k., how many threads do we have waiting on this?:

 

0:086> !syncblk

Index         SyncBlock MonitorHeld Recursion Owning Thread Info          SyncBlock Owner

  148 000000004ef62350           95         1 000000004ef6a070  2a18  86   0000000080074a08 System.Object

            Waiting threads: 23 24 25 34 35 36 37 38 39 40 50 51 52 53 54 55 56 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 87

—————————–

Total           1548

CCW             0

RCW             0

ComClassFactory 0

Free            0

 

In the words of Strongbad: That is not a very small number. That is a very BIG number!

 

For those of you wondering what this means in common, everyday production use of Exchange:

 

Mail would come in, destined for ‘x’ recipient. Transport would see a rule that has the condition, IsMemberOf. Then, Transport would see that the local recipient cache for the group it needs to verify that the recipient is a member of is out-of-date. It would call a thread to update it. Since threads aren’t context-aware, this would occur for many of the recipients currently in the Submission Queue. The thread making the LDAP call would own the lock, as it entered the critical section. The other threads had to wait for the lock to be released to make their AD call. Since only one thread in the process’ bounds can own a lock, at a time, this means the threads could only complete in a one-by-one scenario. This is also why the mail couldn’t be categorized because the lock prevented the thread from validating IsMemberOf without a current cache.

 

For those of you concerned if you’ll run into this issue: This condition only reproduces in a single instance and that instance has only recurred twice, so far, during the timespan of a year. Rest assured, that even though the perceivable affected footprint of this issue is small, it is being investigated by the Transport developers.