C# + AD: Dump COM and Use System.DirectoryServices.Protocols with LINQ to Query AD

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 back, I posted about using ADSI COM to get the data that you wanted. I want to show you how you can do this 10 times faster, using System.DirectoryServices.Protocols and LINQ.

Class for the actual AD query being performed:

    /// <summary>
    /// Initializes a new instance of the <see cref="LdapSearcher"/> class.
    /// </summary>
    internal class LdapSearcher
    {
        /// <summary>
        /// Initializes a new instance of the <see cref="SearchTheForestTask"/> method.
        /// </summary>
        /// <param name="filter">The filter to use for the LDAP query.</param>
        /// <param name="sizeLimit">The limit of return objects for the query.</param>
        /// <param name="configContainer"></param>
        /// <returns></returns>
        public static async Task<SearchResponse> SearchTheForestTask(string filter, int? sizeLimit, bool configContainer)
        {
            // More information on the return statement can be found here: https://msdn.microsoft.com/en-us/library/1h3swy84.aspx
            // More information on the async/await keywords can be found here: https://msdn.microsoft.com/en-us/library/hh191443.aspx
            // More information on the Task<TResult>.Run() method can be found here: https://msdn.microsoft.com/en-us/library/hh160382(v=vs.110).aspx
            return await Task.Run(async /* Run on asynchronous thread so we don't block. */
                () =>
                {
                    // More information on the return statement can be found here: https://msdn.microsoft.com/en-us/library/1h3swy84.aspx
                    // More information on the async/await keywords can be found here: https://msdn.microsoft.com/en-us/library/hh191443.aspx
                    // More information on the Task<TResult>.Run() method can be found here: https://msdn.microsoft.com/en-us/library/hh160382(v=vs.110).aspx
                    return await Task.Run(() => SearchTheForest(filter, sizeLimit, configContainer));
                });
        }

        /// <summary>
        /// Initializes a new instance of the <see cref="SearchTheForest"/> method.
        /// </summary>
        /// <param name="filter">The filter to use for the LDAP query.</param>
        /// <param name="sizeLimit">The limit of return objects for the query.</param>
        /// <param name="configContainer"></param>
        /// <returns></returns>
        private static SearchResponse SearchTheForest(string filter, int? sizeLimit, bool configContainer)
        {
            string targetServer = Domain.GetComputerDomain().FindDomainController().Name;

            // We can't await a Task to get RootDSE via async or it may execute AFTER we need it.
            DirectoryEntry rootDse = new DirectoryEntry("LDAP://RootDSE")
            {
                // More information on the DirectoryEntry.AuthenticationType property can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.directoryentry.authenticationtype(v=vs.110).aspx
                // More information on the AuthenticationTypes enumeration can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.authenticationtypes(v=vs.110).aspx
                AuthenticationType = AuthenticationTypes.Encryption
            };

            string searchRoot = AdMethods.GetSearchRootTask(rootDse, configContainer).Result;

            // We instantiate the object to clear data.
            Ad.NewSearchResponse = null;

            // If the size limit isn't defined, we set it to 1k.
            int pageSize = sizeLimit ?? 1000;

            // We specify the page size so that we don't break all the things.
            // More information on the PageResultRequestControl class can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.pageresultrequestcontrol(v=vs.100).aspx
            PageResultRequestControl newPageResultRequestControl = new PageResultRequestControl(pageSize);

            // We include deleted objects in the search.
            // More information on the ShowDeletedControl class can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.showdeletedcontrol(v=vs.110).aspx
            ShowDeletedControl newShowDeletedControl = new ShowDeletedControl();
            
            // Establish connection to the Directory.
            LdapConnection newLdapConnection = new LdapConnection(targetServer);

            // Create the Search Request.
            // More information on the SearchRequest class be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.searchrequest(v=vs.110).aspx
            SearchRequest newSearchRequest = new SearchRequest
            {
                // More information on the SearchRequest.Filter property can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.searchrequest.filter(v=vs.110).aspx
                Filter = filter,

                // We specify the search root for the query. Don't let the documentation lie to you,
                // this property does not specify the object to query FOR.
                // More information on the SearchRequest.DistinguishedName property can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.searchrequest.distinguishedname(v=vs.110).aspx
                DistinguishedName = searchRoot,

                // More information on the SearchRequest.Scope property can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.searchrequest.scope(v=vs.110).aspx
                // More information on the SearchScope enumeration can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.searchscope(v=vs.110).aspx
                Scope = System.DirectoryServices.Protocols.SearchScope.Subtree,

                // More information on the SearchRequest.TimeLimit property can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.searchrequest.timelimit(v=vs.110).aspx
                TimeLimit = TimeSpanConstants.OneMinuteTimeSpan,

                // More information on the SearchRequest.RequestId property can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.directoryrequest.requestid(v=vs.110).aspx
                RequestId = GuidConstants.RequestGuid.ToString(),

                // More information on the SearchRequest.Aliases property can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.searchrequest.aliases(v=vs.110).aspx
                // More information on the DereferenceAlias enumeration can be found there: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.dereferencealias(v=vs.100).aspx
                Aliases = System.DirectoryServices.Protocols.DereferenceAlias.Never,

                // More information on the SearchRequest.TypesOnly property can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.searchrequest.typesonly(v=vs.110).aspx
                TypesOnly = false,

                // More information on the SearchRequest.Controls property can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.directoryrequest.controls(v=vs.110).aspx
                Controls = { newPageResultRequestControl, newShowDeletedControl }
            };
            if (sizeLimit.HasValue)
            {
                // More information on the SearchRequest.SizeLimit property can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.searchrequest.sizelimit(v=vs.110).aspx
                newSearchRequest.SizeLimit = sizeLimit.Value;
            }

            // Since we're entering a critical section, let's lock so we block further calls.
            // More information on the lock keyword can be found here: https://msdn.microsoft.com/en-us/library/c5kehkcz.aspx
            lock (ObjectConstants.NewLock)
            {
                // Enter the critical section.
                // More information on the try keyword can be found here: https://msdn.microsoft.com/en-us/library/6dekhbbc.aspx
                try
                {
                    // More information on the SearchResponse class can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.searchresponse(v=vs.110).aspx
                    // More information on the LdapConnection.SendRequest(DirectoryRequest) method can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.ldapconnection.sendrequest(v=vs.110).aspx
                    Ad.NewSearchResponse = (SearchResponse) newLdapConnection.SendRequest(newSearchRequest, TimeSpanConstants.OneMinuteTimeSpan);
                }
                catch (LdapException exception)
                {
                    // We throw the base exception so it can be unwound by the calling thread.
                    // More information on the Exception.GetBaseException() method can be found here: https://msdn.microsoft.com/en-us/library/system.exception.getbaseexception(v=vs.110).aspx
                    throw exception.GetBaseException();
                }
            }

            // Since we need to await completion, we pass a value back.
            // More information on the return statement can be found here: https://msdn.microsoft.com/en-us/library/1h3swy84.aspx
            return Ad.NewSearchResponse;
        }
    }

The real magic – taking the return and using LINQ:

           // More information on the TaskFactory class can be found here: https://msdn.microsoft.com/en-us/library/system.threading.tasks.taskfactory(v=vs.110).aspx
            TaskFactory<SearchResponse> newTaskFactory = new TaskFactory<SearchResponse>();

            // More information on the using statement can be found here: https://msdn.microsoft.com/en-us/library/yh598w02.aspx
            // More information on the Task<TResult> class can be found here: https://msdn.microsoft.com/en-us/library/dd321424(v=vs.110).aspx
            // More information on the TaskFactory.StartNew(Action) method can be found here: https://msdn.microsoft.com/en-us/library/dd321439(v=vs.110).aspx
            using (Task<SearchResponse> newTask = newTaskFactory.StartNew(() => LdapSearcher.SearchTheForestTask(filter, null, false).Result))
            {
                // More information on the TaskAwaiter<TResult> class can be found here: https://msdn.microsoft.com/en-us/library/hh138386(v=vs.110).aspx
                // More information on the Task.GetAwaiter() method can be found here: https://msdn.microsoft.com/en-us/library/system.threading.tasks.task.getawaiter(v=vs.110).aspx
                TaskAwaiter<SearchResponse> newTaskAwaiter = newTask.GetAwaiter();

                // More information on the TaskAwaiter.IsCompleted property can be found here: https://msdn.microsoft.com/en-us/library/system.runtime.compilerservices.taskawaiter.iscompleted(v=vs.110).aspx
                while (!newTaskAwaiter.IsCompleted)
                {
                    // More information on the string.Format() method can be found here: https://msdn.microsoft.com/en-us/library/system.string.format(v=vs.110).aspx
                    this.WriteDebug(string.Format("Awaiting task with id'{0}' to finish.", newTask.Id));

                    // Let's wait for task completion.
                    System.Threading.Thread.Sleep(500);
                }

                // More information on the TaskAwaiter.IsCompleted property can be found here: https://msdn.microsoft.com/en-us/library/system.runtime.compilerservices.taskawaiter.iscompleted(v=vs.110).aspx
                if (newTaskAwaiter.IsCompleted)
                {
                    // More information on the string.Format() method can be found here: https://msdn.microsoft.com/en-us/library/system.string.format(v=vs.110).aspx
                    this.WriteDebug(string.Format("Task with Id '{0}' completed.", newTask.Id));

                    // More information on the Task.IsFaulted property can be found here: https://msdn.microsoft.com/en-us/library/system.threading.tasks.task.isfaulted(v=vs.110).aspx
                    if (!newTask.IsFaulted)
                    {
                        // More information on the TaskAwaiter.GetResult() method can be found here: https://msdn.microsoft.com/en-us/library/system.runtime.compilerservices.taskawaiter.getresult(v=vs.110).aspx
                        newTaskAwaiter.GetResult();

                        // More information on the SearchResultEntryCollection class can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.searchresultentrycollection(v=vs.110).aspx
                        SearchResultEntryCollection newSearchResultEntryCollection = Ad.NewSearchResponse.Entries;

                        // More information on the SearchResultEntry class can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.searchresultentry(v=vs.110).aspx
                        SearchResultEntry newSearchResultEntry = newSearchResultEntryCollection[0];

                        // More information on the SearchResultAttributeCollection class can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.searchresultattributecollection(v=vs.110).aspx
                        SearchResultAttributeCollection newSearchResultAttributeCollection = newSearchResultEntry.Attributes;

                        // Validate we don't hit the System.NullReferenceException
                        // More information on the SearchResultAttributeCollection.Values property can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.searchresultattributecollection.values(v=vs.110).aspx
                        if (newSearchResultAttributeCollection.Values != null)
                        {
                            // To save overhead from iterating through each attribute on the object, we need to convert it into a queryable.
                            // This takes some magic but the overall result is the same data, just slightly faster.

                            // More information on the SearchResultAttributeCollection.Values property can be found here: https://msdn.microsoft.com/en-us/library/system.directoryservices.protocols.searchresultattributecollection.values(v=vs.100).aspx
                            ICollection newCollection = newSearchResultAttributeCollection.Values;

                            // More information on the Enumerable.Cast<TResult>() method can be found here: https://msdn.microsoft.com/en-us/library/bb341406(v=vs.110).aspx
                            IEnumerable newDirectoryAttributesCollection = newCollection.Cast<DirectoryAttribute>();

                            // More information on the Queryable.AsQueryable() method can be found here: https://msdn.microsoft.com/en-us/library/bb353734(v=vs.110).aspx
                            IQueryable<DirectoryAttribute> newQueryable = (IQueryable<DirectoryAttribute>) newDirectoryAttributesCollection.AsQueryable();

                            // More information on the Where() method can be found here: https://msdn.microsoft.com/en-us/library/bb546161.aspx
                            // More information on the Select() method can be found here: https://msdn.microsoft.com/en-us/library/bb546168.aspx
                            IQueryable<object[]> newQueryableObjectUno = newQueryable.Where(x => x.Name.Equals("msExchMailboxSecurityDescriptor")).Select(x => x.GetValues(typeof (byte[])));

                            // More information on the FirstOrDefault() method can be found here: https://msdn.microsoft.com/en-us/library/bb546140.aspx
                            object[] newObjectsUno = newQueryableObjectUno.FirstOrDefault();

                            // If the data is null, we went wrong somewhere but it's best to prevent System.NullReferenceException.
                            if (newObjectsUno != null)
                            {
                                byte[] newByteArrayBytes = (byte[]) newObjectsUno[0];

                                // We decode the string.
                                CommonSecurityDescriptor newCommonSecurityDescriptor = new CommonSecurityDescriptor(true, true, newByteArrayBytes, 0);
                                string attrValue = newCommonSecurityDescriptor.GetSddlForm(AccessControlSections.All);

                                this.WriteObject(attrValue);
                            }
                        }
                    }
                }
            }

While this isn’t quite straight-forward, what’s happening is that we’re obtaining all of the properties for the object in AD, in byte format, and then performing a select against the specific property that we want to see.

Happy coding! ūüôā

Debugging: When Recursive NDRs Bring the FSC to It’s Knees And Causes Queuing

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 back (circa July 2015), we had alerting for queuing for a Dedicated customer. When we went and looked, the messages were just sitting in the Submission queue.

We dumped the EdgeTransport process and I cracked it open. When I looked at the dump, only 4 threads were at or above 30 frames and those threads had the same stack[s] (redacted for readability):

# Child-SP          RetAddr           Call Site
00 00000000`3587d298 000007fe`ff2e74f6 ntdll!ZwAlpcSendWaitReceivePort+0xa
01 00000000`3587d2a0 000007fe`ff2e1c32 rpcrt4!LRPC_CCALL::SendReceive+0x156
02 00000000`3587d360 000007fe`fdf228c0 rpcrt4!I_RpcSendReceive+0x42
03 00000000`3587d390 000007fe`fdf2282f ole32!ThreadSendReceive+0x40
04 00000000`3587d3e0 000007fe`fdf2265b ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0xa3
05 00000000`3587d480 000007fe`fddddaaa ole32!CRpcChannelBuffer::SendReceive2+0x11b
06 00000000`3587d640 000007fe`fdddda0c ole32!CAptRpcChnl::SendReceive+0x52
07 00000000`3587d710 000007fe`fdf2205d ole32!CCtxComChnl::SendReceive+0x68
08 00000000`3587d7c0 000007fe`ff38fd61 ole32!NdrExtpProxySendReceive+0x45
09 00000000`3587d7f0 000007fe`fdf1f82f rpcrt4!NdrpClientCall2+0x9ea
0a 00000000`3587df60 000007fe`fdddd8a2 ole32!ObjectStublessClient+0x1ad
0b 00000000`3587e2f0 000007fe`f839a8b7 ole32!ObjectStubless+0x42
0c 00000000`3587e340 000007ff`0042901d mscorwks!DoCLRToCOMCall+0x177
0d 00000000`3587e3f0 000007ff`00424efc DomainBoundILStubClass.IL_STUB(System.Object, UInt32, UInt32 ByRef, UInt32 ByRef, System.Array ByRef)+0x15d
0e 00000000`3587e540 000007ff`001af3ec FSEAgent_8_0_685!Antigen.Scanner.Scan()+0x45c
0f 00000000`3587e640 000007fe`f74f2bbb FSEAgent_8_0_685!Antigen.Scanner.ScannerThread()+0x13c
10 00000000`3587e6e0 000007fe`f758aadd mscorlib_ni!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+0x9b
11 00000000`3587e730 000007fe`f839c6a2 mscorlib_ni!System.Threading.ThreadHelper.ThreadStart()+0x4d
12 00000000`3587e780 000007fe`f825ff03 mscorwks!CallDescrWorker+0x82
13 00000000`3587e7d0 000007fe`f877a291 mscorwks!CallDescrWorkerWithHandler+0xd3
14 00000000`3587e870 000007fe`f81c37b9 mscorwks!MethodDesc::CallDescr+0x2b1
15 00000000`3587eab0 000007fe`f831d298 mscorwks!ThreadNative::KickOffThread_Worker+0x191
16 00000000`3587edd0 000007fe`f8230945 mscorwks!ManagedThreadBase_DispatchInner+0x2c
17 00000000`3587ee20 000007fe`f81fe52d mscorwks!ManagedThreadBase_DispatchMiddle+0x9d
18 00000000`3587eef0 000007fe`f835a2b5 mscorwks!ManagedThreadBase_DispatchOuter+0x31
19 00000000`3587ef30 000007fe`f832825b mscorwks!ManagedThreadBase_FullTransitionWithAD+0x35
1a 00000000`3587ef90 000007fe`f8320134 mscorwks!ThreadNative::KickOffThread+0xd3
1b 00000000`3587f070 00000000`779959dd mscorwks!Thread::intermediateThreadProc+0x78
1c 00000000`3587fc40 00000000`77aca651 kernel32!BaseThreadInitThunk+0xd
1d 00000000`3587fc70 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

All of those aforementioned threads were passing to COM:

!findstack mscorwks!DoCLRToCOMCall
Thread 064, 1 frame(s) match
        * 12 000000003587e3e0 000007ff0042901d mscorwks!DoCLRToCOMCall+0x177

Thread 066, 1 frame(s) match
        * 12 0000000051cfe240 000007ff0042901d mscorwks!DoCLRToCOMCall+0x177

Thread 068, 1 frame(s) match
        * 12 0000000051dfddb0 000007ff0042901d mscorwks!DoCLRToCOMCall+0x177

Thread 070, 1 frame(s) match
        * 12 000000005205e250 000007ff0042901d mscorwks!DoCLRToCOMCall+0x177

And the messages that were being processed were NDRs that have been around the block or two (sorry for the wall of text):

0:064> !mdt 00000000e074c8b0
00000000e074c8b0 (System.String) Length=12515, String="Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undelivered Mail Returned to Sender"
0:070> !mdt 0000000100776d88
0000000100776d88 (System.String) Length=11719, String="Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Undeliverable: Delayed Mail (still being retried)"

The message details (in redacted form) were:

0:064> !mdt 0000000081097f30
0000000081097f30 (Antigen.AntigenMessage)
    m_folder:00000000810a01f0 (System.String) Length=36, String="C:\forefront\data\\Archive\Internal\"
    m_fileObject:0x250e0 (System.UInt32)
    m_bcc:00000000e0754c50 (System.String) Length=43, String="<recipient>;"
    m_flags:0x0 (System.Int32)
    m_smtpSenderAddress:00000000907eb738 (System.String) Length=21, String=""Sender""
    m_smtpExternalIP:NULL (System.String)
    m_onlyTreatIfPurge:0x0 (System.UInt32)
    m_isSystemMessage:0x1 (System.UInt32)
    m_smtpExternalHostName:NULL (System.String)
    m_MessageDateTimeReceived:00000000e0754990 (System.String) Length=20, String="2015-07-21T08:41:46Z"
    m_MessageDateTimeSent:00000000e07549d8 (System.String) Length=20, String="2015-07-21T08:26:23Z"
    m_EHSBypassVirusScan:0x0 (System.UInt32)
    m_PremiumEngineSet:0x0 (System.UInt32)
    m_IsTransportDecrypted:0x0 (System.UInt32)
    m_ReplayHeaders:00000000810a0428 (System.String) Length=172, String="X-Receiver: <recipient> ORCPT=rfc822;<recipient>
X-Sender: <sender>
X-CreatedBy: MSExchange12"

When I checked message tracking, this was a partial indicator of what introduced the problem:

$msgTrk = @()
$hubz = Get-TransportServer
foreach($hub in $hubz)
{
     $msgTrk += Get-MessageTrackingLog -Server $hub.Name -Recipients <recipient> -ResultSize Unlimited
}

$msgTrk.Count
1491474

In the words of Strongbad, “That is not a small number! That’s a very big number!

This was a limitation in the Forefront hook in Transport that caused it to consume a lot of resources on the heap, which was exacerbated by a mail-storm from the customer’s on-premises.

Debugging: Incremental Mailbox Sync Move Requests Cause ‘StopAll’ to be called on the Assistants Infrastructure Which Causes CalendarNotificationAssistant to Stop Processing Text Message (SMS) Notifications

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

Not too long ago, I debugged an issue with the Calendar Notification Assistant (CNA), wherein the Assistant would stop processing text message (SMS) notifications for events. The affected end-users noted that if they enabled text message (SMS) notifications in Outlook Web Access (OWA), the notifications would work for around 24 hours and then they would fall back into reproduction of the issue, in which the notifications stop altogether.

When I went looking in PowerShell, I could verify (via the Admin Audit Log) that the commands to set the configuration for SMS were ran and that it was enabled:

Search-AdminAuditLog -Cmdlets Set-TextMessagingAccount | Where{$_.ObjectModified -contains '<objectId>'} | FL


RunspaceId         : c7683058-b25c-4557-818d-546cf5f178c6
ObjectModified     : <objectId>
CmdletName         : Set-TextMessagingAccount
CmdletParameters   : {CountryRegionId, MobileOperatorId, NotificationPhoneNumber, Identity}
ModifiedProperties : {}
Caller             : <callerObjectId>
ExternalAccess     :
Succeeded          : True
Error              : None
RunDate            : 12/22/2015 1:15:17 PM
OriginatingServer  : <serverName>
Identity           : <identity>
IsValid            : True
ObjectState        : New

We could also see the messages being sent via the Message Tracking Log (MTL):

$MsgTrk | Sort TimeStamp | FT EventId,Source,Sender,Recipients,MessageSubject,TimeStamp -AutoSize

EventId Source      Sender                       Recipients                                  MessageSubject 	Timestamp
------- ------      ------                       ----------                                  -------------- 	---------
RECEIVE STOREDRIVER <senderEmailAddress> 	{[email protected]}                		12/17/2015 13:18:34
SEND    AGENT       <senderEmailAddress> 	{[email protected]}                		12/17/2015 13:18:34
RECEIVE STOREDRIVER <senderEmailAddress> 	{[email protected]}                		12/17/2015 13:19:46
SEND    AGENT       <senderEmailAddress> 	{[email protected]}                		12/17/2015 13:19:46
RECEIVE STOREDRIVER <senderEmailAddress> 	{[email protected]}                		12/17/2015 16:15:02
SEND    AGENT       <senderEmailAddress> 	{[email protected]}                		12/17/2015 16:15:02

Using this, I could tell the originator of the message: The Mailbox Assistants. This was done by the seeing that the client and the server were the same:

$MsgTrk[0] | FL


RunspaceId              : 13ad4581-25d9-4136-8ed1-a284b7e979db
Timestamp               : 12/21/2015 15:40:31
ClientIp                : <ipAddress>
ClientHostname          : <serverName>
ServerIp                : <ipAddress>
ServerHostname          : <serverName>
SourceContext           : 08D30340C2F43943
ConnectorId             :
Source                  : STOREDRIVER
EventId                 : RECEIVE
InternalMessageId       : 2429739
MessageId               : <messageId>
Recipients              : {[email protected]}
RecipientStatus         : {To}
TotalBytes              : 6386
RecipientCount          : 1
RelatedRecipientAddress :
Reference               :
MessageSubject          :
Sender                  : <emailAddress>
ReturnPath              : <emailAddress>
MessageInfo             : 04I:
MessageLatency          :
MessageLatencyType      : None
EventData               : {[MailboxDatabaseGuid, 347a971c-e8f5-45de-8e01-870ed4dc6901], [ItemEntryId, 00-00-00-00-1E-95-32-44-0A-EA-D6-47-A5-98-9B-F0-5F-89-B9-09-07-00-BE-9B-24-68-00-23-66-49-95-41-BB-56-C6-02-E3-D0-00-00-00-03-71-5C-00-00-75-FB-A6-9E-77-CF-BE-43-A8-2A-B9-7F-C1-34-9A-01-00-00-1C-C-91-D1-00-00]}

Once I knew this, I checked the Database Event Watermarks for any backlog:

<databaseName>\<serverName> CalendarNotificationAssistant             977234167 989106153    11871986

I now had enough data to assert that a dump of the process was necessary in order to see what’s going on.

At the time of the dump, despite the fact that the user was no longer receiving text message (SMS) notifications, the process was processing (for lack of a better turn-of-phrase at the moment) a two week old message in thread 21 in the stack:

0:021> !mdt 00000000036e1088
00000000036e1088 (Microsoft.Exchange.MailboxAssistants.Assistants.CalendarNotification.CalendarEvent)
    <CalendarItemIdentity>k__BackingField:00000000036e1208 (Microsoft.Exchange.Data.Storage.StoreObjectId)
    <CalendarItemOccurrenceIdentity>k__BackingField:00000000036e1048 (Microsoft.Exchange.Data.Storage.OccurrenceStoreObjectId)
    <CalendarItemType>k__BackingField:0x1 (Microsoft.Exchange.Data.Storage.CalendarItemType)
    <NormalizedSubject>k__BackingField:00000000036e0880 (System.String) Length=5, String="Lunch"
    <Location>k__BackingField:00000000036e0860 (System.String) 
    <ReminderIsSet>k__BackingField:true (System.Boolean)
    <ReminderTime>k__BackingField:(Microsoft.Exchange.ExchangeSystem.ExDateTime) VALTYPE (MT=000007ff002c5cb0, ADDR=00000000036e10d0)
    <ReminderMinutesBeforeStart>k__BackingField:0xf (System.Int32)
    <StartTime>k__BackingField:(Microsoft.Exchange.ExchangeSystem.ExDateTime) VALTYPE (MT=000007ff002c5cb0, ADDR=00000000036e10f0)
    <EndTime>k__BackingField:(Microsoft.Exchange.ExchangeSystem.ExDateTime) VALTYPE (MT=000007ff002c5cb0, ADDR=00000000036e1110)
    <FreeBusyStatus>k__BackingField:0x2 (Microsoft.Exchange.Data.Storage.BusyType)
    <ChangeHighlight>k__BackingField:0x0 (Microsoft.Exchange.Data.Storage.ChangeHighlightProperties)
    <AppointmentState>k__BackingField:0x0 (Microsoft.Exchange.Data.Storage.AppointmentStateFlags)
    <CreationRequestTime>k__BackingField:(Microsoft.Exchange.ExchangeSystem.ExDateTime) VALTYPE (MT=000007ff002c5cb0, ADDR=00000000036e1130)
    <ResponseType>k__BackingField:0x0 (Microsoft.Exchange.Data.Storage.ResponseType)
    <OldStartTime>k__BackingField:(System.Nullable`1) VALTYPE (MT=000007fef6207cc8, ADDR=00000000036e1150)
    <OldEndTime>k__BackingField:(System.Nullable`1) VALTYPE (MT=000007fef6207cc8, ADDR=00000000036e1178)

We can see the date of the item from the backing field:

0:021> !mdt 000007ff002c5cb0 00000000036e10d0
(Microsoft.Exchange.ExchangeSystem.ExDateTime) VALTYPE (MT=000007ff002c5cb0, ADDR=00000000036e10d0)
    timeZone:00000000014bb040 (Microsoft.Exchange.ExchangeSystem.ExTimeZone)
    universalTime:(System.DateTime) 2015/12/23 16:15:00.000 VALTYPE (MT=000007fef62482d0, ADDR=00000000036e10d8)
    localTime:(System.Nullable`1) VALTYPE (MT=000007fef6207cc8, ADDR=00000000036e10e0)

And we can see that it’s processing the item for the same user that lodged the complaint:

0:021> !mdt 0000000003761ad0
0000000003761ad0 (System.String) Length=129, String="<sameUserFromAbove>"

Finally, after perusing the dump for an hour or more, I found what I believed to be introducing the issue:

<ContextInfo>k__BackingField:00000000032fe908 (System.String) Length=7, String="StopAll"

Given this, it was time to go to the devs and figure out what was going on. After some back-and-forth and a conference call with both the Store and Calendaring devs, we arrived at what was causing the issue.

First, it’s important to understand that an incremental sync was created for the user but had not – as of the time of debugging – been completed:

Get-MoveRequestStatistics 957ca0a9-f84f-425e-a263-5b468e90d574 | FL *increm*


EffectiveIncrementalSyncInterval  : 1.00:00:00
ConfiguredIncrementalSyncInterval : 1.00:00:00

Since it syncs once a day, this aligns with the end-user’s statement regarding reconfiguration but we needed proof.

When we went and looked at the Mailbox Database Events for the mailbox in question, we saw the ‘MailboxMoveStarted’ event fire:

$eventz | FT Counter,ItemType,EventName,ObjectClass,Mailbox,CreateTime -AutoSize

  Counter ItemType   EventName          ObjectClass Mailbox CreateTime
  ------- --------   ---------          ----------- ------- ----------
974015558 MAPI_STORE MailboxMoveStarted                     1/25/2016 21:32:01
974683553 MAPI_STORE MailboxMoveStarted                     1/26/2016 21:41:10
975414298 MAPI_STORE MailboxMoveStarted                     1/27/2016 21:44:00
976136834 MAPI_STORE MailboxMoveStarted                     1/28/2016 21:52:10
976842768 MAPI_STORE MailboxMoveStarted                     1/29/2016 22:02:30
977056359 MAPI_STORE MailboxMoveStarted                     1/30/2016 22:03:45
977195259 MAPI_STORE MailboxMoveStarted                     1/31/2016 22:15:01

What’s important to note as a side-comment/take-away is that the 24-hour interval doesn’t initiate from the same start time. This is because the counter for the 24-hour interval starts when the last sync stopped.

When we matched this against a trace of the Assistant, we saw the following:

"2016/01/13-03:06:05.279","9444","2480","Assistants","EventDispatcher","Dispatcher for <userDisplayName> (957ca0a9-f84f-425e-a263-5b468e90d574) and Calendar Notification Assistant: Event handled successfully: Counter: 0x3B331E14; MailboxID: 957ca0a9-f84f-425e-a263-5b468e90d574; Mask: MailboxMoveStarted; Flags: Source; ExtendedFlags: None;Object Class: ; Created Time: 1/13/2016 11:06:04 AM;Item Type: MAPI_STOREItem EntryId: Parent entryId: Old Item entryId: Old parent entryId: SID: S-1-5-21-276227223-3107228690-1043224028-159164Client Type: MigrationDocument ID: 0" 
"85868820"        020B591B          Debug 2016/01/13-02:01:49.777 9444     2480            MailboxAssistants.Assistants.CalendarNotification Assistant           rmd----- caller: StopAll, subj: <subject>, usr: <objectId>c1, calItemId: RgAAAAAelTJECurWR6WYm/BfibkJBwC+myRoACNmSZVBu1bGAuPQAAAAA3FaAAB1+6aed8++Q6gquX/BNJoBAAAcyVmOAAAP, calItemOccId: , event_t: 01/13/2016 16:15:00, rmd_t: 01/13/2016 19:45:00, s_t: 01/13/2016 20:00:00, e_t: 01/13/2016 21:30:00
"8326743"         006B5AB0          Debug 2016/01/13-03:06:05.277 9444     2480            MailboxAssistants.Assistants.CalendarNotification UserSettings      Processing Disabling event for mailbox <objectId> on database 347a971c-e8f5-45de-8e01-870ed4dc6901

To elaborate on this bug and explain it further: Recall back in Exchange 2007 (E12) that mailbox moves caused the mailbox to be locked. When this occurred, it would’ve been necessary for any code that attempts to open the message store to stop processing the mailbox until the move is complete. Fast-forward a few years (nigh to a decade) and incremental sync move requests are a common, every day occurrence. When the incremental sync starts, there is no delineation between it and a regular move request, so a database event fires and this signals the assistant to stop processing the mailbox. When the text message (SMS) notification is reconfigured, it signals the Assistant to start processing on the mailbox. This explains the behavior seen by the end-users.

For those of you concerned about hitting this bug in the wild, we’ve only see it happen once and we’re using that instance to drive a change in the Assistant logic in all versions of Exchange (assuming all have the same bug in the logic).

PowerShell + C#: Accessing the Current Runspace And Adding a Snap-In

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

I’ve been coding an assembly for import into the Exchange Management Shell (EMS) in C# for some time. One of the problems that I ran into was how to load the Support assembly, since it’s not imported into the RunSpace by default. After a while of testing/trying/failing and repeat ad nauseam, I found the answer in the form of what I consider to be a cheat.

You see, when the module is loaded, I’m depending on the current runspace as it exists to execute commands. There’s no proper way to access the runspace that you’re currently executing to modify it’s configuration by adding the snap-in.

So, we arrive at the “cheat”:

// We use the current runspace to cast our calls into.
// This grants us access to the current runspace, instead of instantiating a new one.
// More information on the PowerShell.Create method can be found here: https://msdn.microsoft.com/en-us/library/system.management.automation.powershell.create(v=vs.85).aspx
// More information on the RunspaceMode.CurrentRunspace enumeration value can be found here: https://msdn.microsoft.com/en-us/library/system.management.automation.runspacemode(v=vs.85).aspx
PowerShell initialPowerShell = PowerShell.Create(RunspaceMode.CurrentRunspace);

// More information on the PowerShell.AddScript method can be found here: https://msdn.microsoft.com/en-us/library/dd182436(v=vs.85).aspx
initialPowerShell.Commands.AddScript("Add-PSSnapin Microsoft.Exchange.Management.Powershell.Support");

// More information on the PowerShell.Invoke method can be found here: https://msdn.microsoft.com/en-us/library/dd182449(v=vs.85).aspx
initialPowerShell.Invoke();

If you’re wondering about the code comments: One of the ways that people learn is by searching for examples or questions related to the problem they’re trying to solve. This is something that I – admittedly – used to do. Once they find what they think might be the answer, they look at the methods/class in the documentation (at least, that’s what I used to do). So, I figured why not shorten the effort down for those who want to learn? ūüôā

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.

Exchange 2013: Understanding the Room Finder function in OWA

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

In Exchange 2013, when you use OWA to book a room, there can be two methods that get called for this to occur. Both of these methods start workflows against service.svc and you can see this in the client behavior via the following URLs:

https://<vanityDomain>/owa/service.svc?action=GetRoomLists&ID=-<ID>&AC=1
https://<vanityDomain>/owa/service.svc?action=GetRoomsInternal&ID=-<ID>&AC=1

The first method, GetRoomLists, returns all rooms found in room lists (Get-DistributionGroup -Filter {RecipientTypeDetails -eq “RoomList”}) and this is called when you select ‘Add Room’. Once a user selects a room list, that selection is remembered (read: cached) for subsequent uses in OWA to make the fetch of the list faster.

The second method, GetRoomsInternal, returns the first 100 rooms found in the GAL (Get-Recipient -RecipientPreviewFilter $allRoomsAddrList.RecipientFilter -ResultSize Unlimited)* and is called when you use the Scheduling Assistant to find rooms.

*$allRoomsAddrList = Get-AddressList “All Rooms”

OAB: BITS Provides Data for Troubleshooting

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

At certain times, it may become necessary to troubleshoot OAB downloads from the client-perspective. This has been used for both internal and external customer issues with OAB and I thought would prove useful to discuss.

We can get a general, overall view of what is occurring on the client machine, according to BITS, via Windows PowerShell:

Get-BitsTransfer ‚ÄďAllUsers | Where{$_.DisplayName -ilike ‘Microsoft Outlook Offline Address Book*’} | FT -AutoSize

JobId                                DisplayName                                                             TransferType JobState OwnerAccount
—–¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬† ———–¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬†¬† ———— ——– ————
a0f7b061-ac0d-4032-8310-65744c2a136b Microsoft Outlook Offline Address Book 029229376bac9a44b09855c03dcebef6 Download     Error    <REDACTED>\johnbai
daf20558-f80e-46f1-92e1-fcf3557f2eb9 Microsoft Outlook Offline Address Book 029229376bac9a44b09855c03dcebef6 Download     Error    <REDACTED>\johnbai
697758cd-22c9-4cd2-ad7b-749a0a673b20 Microsoft Outlook Offline Address Book 029229376bac9a44b09855c03dcebef6 Download     Error    <REDACTED>\johnbai
9fc762e3-64a7-4d74-a302-9695982330fc Microsoft Outlook Offline Address Book 029229376bac9a44b09855c03dcebef6 Download     Error    <REDACTED>\johnbai
02b619ce-28da-41a7-a7f7-b1537859e24e Microsoft Outlook Offline Address Book 029229376bac9a44b09855c03dcebef6 Download     Error    <REDACTED>\johnbai
3fcb0305-b6b4-49e4-ab7c-2d0b8d05b4cc Microsoft Outlook Offline Address Book 029229376bac9a44b09855c03dcebef6 Download     Error    <REDACTED>\johnbai
18dc84c8-563e-4fd3-8715-63dbedc04bc0 Microsoft Outlook Offline Address Book 029229376bac9a44b09855c03dcebef6 Download     Error    <REDACTED>\johnbai
b5bbbb4f-c5cc-4c72-9ab3-79268e49c26e Microsoft Outlook Offline Address Book 029229376bac9a44b09855c03dcebef6 Download     Error    <REDACTED>\johnbai
f29e4b69-46fc-4ca7-9c0c-759165b0f94a Microsoft Outlook Offline Address Book 029229376bac9a44b09855c03dcebef6 Download     Error    <REDACTED>\johnbai
c58fec18-d563-424b-ba47-f0dcf3d9c202 Microsoft Outlook Offline Address Book 029229376bac9a44b09855c03dcebef6 Download     Error    <REDACTED>\johnbai
89ac88cb-3b4d-47b6-b6d2-d2c877d8028b Microsoft Outlook Offline Address Book 029229376bac9a44b09855c03dcebef6 Download     Error    <REDACTED>\johnbai

We can also deep-dive into the issue, as far as BITS reporting goes via the command ‘bitsadmin /list /verbose’:

So, in this case, the user (myself) was receiving a 401 when attempting to download the OAB.

Exchange: Non-Discriminant Mailbox Moves

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

I had to rebuild my lab and in one of the invariable problems of doing this is that the default database is created and by the time you do any administration in Exchange, mailboxes exist on it.

I had to come up with a sure-fire way to balance moves between the two mount-points I had created, so as to not really favor one over the other (plus, manually alternating isn’t much fun).

Enter PowerShell. First, I had to make script to test if the iteration I was on was even or odd:

function Check-IfEvenOrOdd ($digit) {[bool]!($digit%2)}

Once I had the function, the next step was to iterate:

$MBXs = @()
$MBXs += Get-Mailbox -Database “Mailbox Database 1750300935”
$MBXs += Get-Mailbox -Database “Mailbox Database 1750300935” -Monitoring
$MBXs += Get-Mailbox -Database “Mailbox Database 1750300935” -Arbitration
$MBXs += Get-Mailbox -Database “Mailbox Database 1909919934” -Monitoring
$MBXs += Get-Mailbox -Database “Mailbox Database 1909919934” -Arbitration
($MBXs | Measure-Object).Count

for([int]$y = 0; $y -le 18; $y++)
{
 if(Check-IfEvenOrOdd $y = $true)
 {
  New-MoveRequest $MBXs[$y].Identity -TargetDatabase EURPROD01-db001
 }
 else
 {
  New-MoveRequest $MBXs[$y].Identity -TargetDatabase EURPROD01-db002
 }
}

And there you have it: Easy ‘balancing’ of mailbox moves to evacuate databases.

Exchange: Recovering a Database from Dirty Shutdown (the Easy Way)

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

In testing (and production), we invariably run into problems where the database will be in a ‘bad state’. In my case, I pulled Store service out from under it (disabled and stopped the service) and this caused the database to go into dirty shutdown:

eseutil.exe /mh “C:\Databases\EMEA-SWEEX15-01 Store 001\EMEA-SWEEX15-01 Store 001.EDB”

Extensible Storage Engine Utilities for Microsoft(R) Exchange Server
Version 15.00
Copyright (C) Microsoft Corporation. All Rights Reserved.

Initiating FILE DUMP mode…
         Database: C:\Databases\EMEA-SWEEX15-01 Store 001\EMEA-SWEEX15-01 Store 001.EDB

DATABASE HEADER:
Checksum Information:
Expected Checksum: 0x65021d61
  Actual Checksum: 0x65021d61

Fields:
        File Type: Database
         Checksum: 0x65021d61
   Format ulMagic: 0x89abcdef
   Engine ulMagic: 0x89abcdef
 Format ulVersion: 0x620,20
 Engine ulVersion: 0x620,20
Created ulVersion: 0x620,20
     DB Signature: Create time:05/05/2014 13:08:25.805 Rand:306694709 Computer:
         cbDbPage: 32768
           dbtime: 10263756 (0x9c9ccc)
            State: Dirty Shutdown
     Log Required: 12131-12194 (0x2f63-0x2fa2)
    Log Committed: 0-12195 (0x0-0x2fa3)
   Log Recovering: 12195 (0x2fa3)
  GenMax Creation: 10/14/2014 07:55:56.052
         Shadowed: Yes
       Last Objid: 56187
     Scrub Dbtime: 0 (0x0)
       Scrub Date: 00/00/1900 00:00:00
     Repair Count: 0
      Repair Date: 00/00/1900 00:00:00.000
 Old Repair Count: 0
  Last Consistent: (0x263B,8B,19C)  08/28/2014 08:55:57.153
      Last Attach: (0x263C,2,268)  08/28/2014 08:55:57.294
      Last Detach: (0x0,0,0)  00/00/1900 00:00:00.000
    Last ReAttach: (0x2DEA,2,0)  10/11/2014 04:46:44.436
             Dbid: 1
    Log Signature: Create time:05/05/2014 13:08:25.649 Rand:2111075525 Computer:
       OS Version: (6.2.9200 SP 0 NLS ffffffff.ffffffff)

Previous Full Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00.000

Previous Incremental Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00.000

Previous Copy Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00.000

Previous Differential Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00.000

Current Full Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00.000

Current Shadow copy backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00.000

     cpgUpgrade55Format: 0
    cpgUpgradeFreePages: 0
cpgUpgradeSpaceMapPages: 0

       ECC Fix Success Count: none
   Old ECC Fix Success Count: none
         ECC Fix Error Count: none
     Old ECC Fix Error Count: none
    Bad Checksum Error Count: none
Old bad Checksum Error Count: none

  Last checksum finish Date: 10/14/2014 08:02:23.469
Current checksum start Date: 00/00/1900 00:00:00.000
      Current checksum page: 0

Operation completed successfully in 0.187 seconds.

Using eseutil (and assuming the log is still available) we can recover from such a state like the following:

eseutil /r “E01” /l “C:\Databases\EMEA-SWEEX15-01 Store 001\Logs” /d “C:\Databases\EMEA-SWEEX15-01 Store 001”

Extensible Storage Engine Utilities for Microsoft(R) Exchange Server
Version 15.00
Copyright (C) Microsoft Corporation. All Rights Reserved.

Initiating RECOVERY mode…
    Logfile base name: E01
            Log files: C:\Databases\EMEA-SWEEX15-01 Store 001\Logs
         System files: <current directory>
   Database Directory: C:\Databases\EMEA-SWEEX15-01 Store 001

Performing soft recovery…
                      Restore Status (% complete)

          0    10   20   30   40   50   60   70   80   90  100
¬†¬†¬†¬†¬†¬†¬†¬†¬† |—-|—-|—-|—-|—-|—-|—-|—-|—-|—-|
¬†¬†¬†¬†¬†¬†¬†¬†¬† ……………………………………………

Operation completed successfully in 13.140 seconds.

And, once we’ve completed said step, we can verify if the database is – indeed – in clean shutdown:

eseutil.exe /mh “C:\Databases\EMEA-SWEEX15-01 Store 001\EMEA-SWEEX15-01 Store 001.EDB”

Extensible Storage Engine Utilities for Microsoft(R) Exchange Server
Version 15.00
Copyright (C) Microsoft Corporation. All Rights Reserved.

Initiating FILE DUMP mode…
         Database: C:\Databases\EMEA-SWEEX15-01 Store 001\EMEA-SWEEX15-01 Store 001.EDB

DATABASE HEADER:
Checksum Information:
Expected Checksum: 0x758dd2a3
  Actual Checksum: 0x758dd2a3

Fields:
        File Type: Database
         Checksum: 0x758dd2a3
   Format ulMagic: 0x89abcdef
   Engine ulMagic: 0x89abcdef
 Format ulVersion: 0x620,20
 Engine ulVersion: 0x620,20
Created ulVersion: 0x620,20
     DB Signature: Create time:05/05/2014 13:08:25.805 Rand:306694709 Computer:
         cbDbPage: 32768
           dbtime: 13412964 (0xccaa64)
            State: Clean Shutdown
     Log Required: 0-0 (0x0-0x0)
    Log Committed: 0-0 (0x0-0x0)
   Log Recovering: 0 (0x0)
  GenMax Creation: 00/00/1900 00:00:00.000
         Shadowed: Yes
       Last Objid: 66933
     Scrub Dbtime: 0 (0x0)
       Scrub Date: 00/00/1900 00:00:00
     Repair Count: 0
      Repair Date: 00/00/1900 00:00:00.000
 Old Repair Count: 0
  Last Consistent: (0x2FA4,1,31)  10/14/2014 08:10:54.954
      Last Attach: (0x263C,2,268)  08/28/2014 08:55:57.294
      Last Detach: (0x2FA4,1,31)  10/14/2014 08:10:54.954
    Last ReAttach: (0x2DEA,2,0)  10/11/2014 04:46:44.436
             Dbid: 1
    Log Signature: Create time:05/05/2014 13:08:25.649 Rand:2111075525 Computer:
       OS Version: (6.2.9200 SP 0 NLS ffffffff.ffffffff)

Previous Full Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00.000

Previous Incremental Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00.000

Previous Copy Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00.000

Previous Differential Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00.000

Current Full Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00.000

Current Shadow copy backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00.000

     cpgUpgrade55Format: 0
    cpgUpgradeFreePages: 0
cpgUpgradeSpaceMapPages: 0

       ECC Fix Success Count: none
   Old ECC Fix Success Count: none
         ECC Fix Error Count: none
     Old ECC Fix Error Count: none
    Bad Checksum Error Count: none
Old bad Checksum Error Count: none

  Last checksum finish Date: 10/14/2014 08:02:23.469
Current checksum start Date: 00/00/1900 00:00:00.000
      Current checksum page: 0

Operation completed successfully in 0.235 seconds.

And, now, the database is safe to mount, again.

C#: Returning an Object via System.Threading.Tasks.Task

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

In programming something (in EWS), discovered the joys of what I believe was ‘lock contention’. To explain, first we need to cover Tasks.

Async Tasks (which call ‘await’ against other tasks) will only perform the action requested, if you do not specify a managed object to handle. For example, if I call an async for a string and do not specify that I am expecting an object in return, this is what the code will look like (and will introduce our problem):

string noDataReturns = await System.Threading.Tasks.Task.Run(() => this.GetMeTheStringAsync().Result);

private async Task GetMeTheStringAsync()

{

return await System.Threading.Tasks.Task.Run(() => this.GetMeTheString());

}

private string GetMeTheString()

{

return “This is not the string you’re looking for.”;

}

If, instead, I tell the task what object I expect to get in return, when the task completes, the result will be object that is passed back – instead of the result of the task:

string dataReturns = await System.Threading.Tasks.Task<string>.Run(() => this.GetMeTheStringAsync().Result);

private async Task<string> GetMeTheStringAsync()

{

return await System.Threading.Tasks.Task<string>.Run(() => GetMeTheString());

}

private string GetMeTheString()

{

return “This is the string you’re looking for.”;

}

This is probably common-place parlance in the .NET developer’s world but I had discovered this when I was spawning a Task that would return a DataTable object but did not specify that I expecting an object in return. As such, the windows form was rendered useless/locked, as I placed the DataTable’s data source as the result of the Task but there was no data to put in the data table.