1. Introduction

 

This post is about a support call where customer was complaining that the ISA Server was stop answering requests every five days in average. Of course this is too broad statement and we have to narrow it down with more and more questions. The interrogatory started:

·         When you say stop answering requests you are talking about Web Proxy requests?

o   Answer: Internet doesn’t work.

·         Can you access the server using Remote Desktop?

o   Answer: no.

·         Can you logon locally in the server?

o   Answer: yes.

·         Is it slow or doesn’t answer at all?

o   Answer: it is extremely slow.

·         What you do as workaround?

o   Answer: I have to restart the machine.

·         Do you gracefully shutdown/restart?

o   Answer: no, it is so slow that I can’t click in Start/Shutdown.

 

That being said, let’s start gathering data.

 

2. Gathering Data

 

Since the issue was affecting the server itself and we were entering in hang mode it was necessary to get a full memory dump. To prepare the machine to get a full memory dump we follow KB244139 and also reviewed the main points of KB130536.

 

3. Analyzing

 

With the full memory dump in hands we can start to look at the possible root cause for this issue. First thing in this case is to check what locks are held on resources by threads. To do that we need to run the!locks command:

 

0: kd> !locks

**** DUMP OF ALL RESOURCE OBJECTS ****

KD: Scanning for held locks....

 

Resource @ nt!CmpRegistryLock (0x808ad480)    Shared 2 owning threads

    Contention Count = 14

     Threads: 89a30ca8-01<*> 899ef708-01<*>

KD: Scanning for held locks....

 

Resource @ Ntfs!NtfsData (0xf7053590)    Shared 2 owning threads

    Contention Count = 1

     Threads: 8a398020-01<*> 8a398b40-01<*>

KD: Scanning for held locks.

 

* ----- hiding other resources since it were hundreds of them ----- *

 

Resource @ 0x8a045534    Shared 2 owning threads

    Contention Count = 1893

    NumberOfSharedWaiters = 54

    NumberOfExclusiveWaiters = 1

     Threads: 89a30ca8-01<*> 8a127020-01<*> 89883ba8-01    89f5eb50-01   

              8985f020-01    897e3600-01    89ac0ba8-01    89fb9940-01   

              89834db0-01    8978c380-01    897ed020-01    897559d8-01   

              88b40bd0-01    898a7590-01    89a3b700-01    8a398b40-01   

              897c59a8-01    89ffbd48-01    898d4658-01    8983b4c0-01   

              897c8020-01    89a84168-01    8986d020-01    8a179ba8-01   

              899fe7a0-01    8a109db0-01    89a19be0-01    89a26c80-01   

              897c9020-01    88b3e740-01    88b1adb0-01    8a0ca428-01   

              89727b18-01    8a1d55a0-01    8a0d7db0-01    897ff7c8-01   

              8a0c0ba0-01    8a0c3b28-01    88aec960-01    88b17020-01   

              8971f020-01    88b14db0-01    88ae3890-01    88ae0aa0-01   

              88b0b430-01    88ada840-01    88b052d0-01    88b034d8-01   

              88ace738-01    88ac9020-01    8a106a20-01    88ac4b60-01   

              88abb350-01    88ab4db0-01    88aaeca8-01    8a14eb18-01   

     Threads Waiting On Exclusive Access:

              898a2db0      

 

 

The resource in red is the one that has more contention count (1893). Reviewing the threads 89a30ca8 and 8a127020 we have:

 

0: kd> !thread 8a127020

THREAD 8a127020  Cid 12d4.172c  Teb: 00000000 Win32Thread: 00000000 WAIT: (WrResource) KernelMode Non-Alertable

    8a25d110  SynchronizationEvent

    8a127098  NotificationTimer

IRP List:

    8a1279f0: (0006,01fc) Flags: 00000884  Mdl: 00000000

Not impersonating

DeviceMap                 e1433fd0

Owning Process            8972f2e0       Image:         wepmcoll.exe

Wait Start TickCount      2658502        Ticks: 84 (0:00:00:01.312)

Context Switch Count      2096                 LargeStack

UserTime                  00:00:00.0015

KernelTime                00:00:00.0015

Win32 Start Address 0x00401846

Start Address 0x77e6b5ff

Stack Init b85ed000 Current b85ec054 Base b85ed000 Limit b85e9000 Call 0

Priority 14 BasePriority 8 PriorityDecrement 6

ChildEBP RetAddr  Args to Child             

b85ec06c 8083e6a2 8a127098 8a127020 8a1270c8 nt!KiSwapContext+0x26

b85ec098 8083f164 8a127020 899bf900 00000000 nt!KiSwapThread+0x284

b85ec0e0 80818613 8a25d110 0000001b 00000000 nt!KeWaitForSingleObject+0x346

b85ec11c 80841266 00000000 e16d8008 88b2dc20 nt!ExpWaitForResource+0xd5

b85ec13c f7038438 899bf900 88b2dc01 b85ec170 nt!ExAcquireResourceExclusiveLite+0x8d

b85ec14c f706a3dc 88b2dc20 e16d8008 88b2dc01 Ntfs!NtfsAcquireResourceExclusive+0x20

b85ec170 f706c59b 88b2dc01 e16d8008 00000000 Ntfs!NtfsAcquireExclusiveFcb+0x42

b85ec19c f70553d9 88b2dc20 e16d8008 00000000 Ntfs!NtfsAcquireFcbWithPaging+0x7f

b85ec1d0 f706b903 88b2dc20 8a045260 e145f948 Ntfs!NtfsFindPrefixHashEntry+0x35c

b85ec320 f706c1e5 88b2dc20 8a1279f0 b85ec360 Ntfs!NtfsCommonCreate+0xaff

b85ec424 8083f9d0 8a045020 8a1279f0 8a1279f0 Ntfs!NtfsFsdCreate+0x17d

b85ec438 f71ef51e b85ec4dc 8a127ba4 8a2bef38 nt!IofCallDriver+0x45

b85ec468 8083f9d0 8a3ab530 8a1279f0 8a127bc8 fltmgr!FltpCreate+0x1aa

b85ec47c ba5f76f1 8a127ba4 8a127bc8 b85ec4dc nt!IofCallDriver+0x45

WARNING: Stack unwind information not available. Following frames may be wrong.

b85ec4a4 ba5fe740 8a3ab530 00000000 b85ec4dc SYMEVENT+0x76f1

b85ec4c0 ba5f7769 b85ec4dc 8082b0b9 ba5f782a SYMEVENT+0xe740

b85ec4fc 8083f9d0 8a1146d0 8a1279f0 8a1279f0 SYMEVENT+0x7769

b85ec510 f71e1b43 00000000 8a1279f0 8a127bc8 nt!IofCallDriver+0x45

b85ec534 f71ef5af b85ec554 89d43620 00000000 fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x20b

b85ec570 8083f9d0 89d43620 8a1279f0 8a1279f0 fltmgr!FltpCreate+0x23b

b85ec584 8092e269 b85ec72c 8a34e910 00000000 nt!IofCallDriver+0x45

b85ec66c 80936caa 8a34e928 00000000 88b23cb0 nt!IopParseDevice+0xa35

b85ec6ec 80936aa5 00000000 b85ec72c 00000240 nt!ObpLookupObjectName+0x5a9

b85ec740 80936f27 00000000 00000000 83da0600 nt!ObOpenObjectByName+0xea

b85ec7bc 80936ff8 b85ec8ec 00100080 b85ec89c nt!IopCreateFile+0x447

b85ec818 ba2dec67 b85ec8ec 00100080 b85ec89c nt!IoCreateFile+0xa3

b85ec8bc ba2def24 b85ecdf0 b85e9000 00000007 SPBBCDrv+0x2c67

b85ec8f0 ba2df451 b85ec914 b85ec924 b85ec91c SPBBCDrv+0x2f24

b85ec93c ba2eb6d6 e14e5378 e305bb40 00000000 SPBBCDrv+0x3451

b85ec978 ba2fa603 b85ecaec 00000005 0000000b SPBBCDrv+0xf6d6

b85ec9a8 ba2fa2e8 b85eca74 e352f678 00000000 SPBBCDrv+0x1e603

b85ec9e4 ba2eb335 00000001 b85eca74 e365b6c0 SPBBCDrv+0x1e2e8

b85eca44 ba2ec67e b85ecbb8 005ecb8c 00000001 SPBBCDrv+0xf335

b85ecb08 8083f893 0000005f b85ecb3c e1920e14 SPBBCDrv+0x1067e

ba32df50 ba2f9fe4 ba2e7852 ba2e7870 ba2e7852 nt!ExReleaseResourceLite+0x8c

ba32df54 ba2e7852 ba2e7870 ba2e7852 ba2fa006 SPBBCDrv+0x1dfe4

ba32df58 ba2e7870 ba2e7852 ba2fa006 ba2e7852 SPBBCDrv+0xb852

ba32df5c ba2e7852 ba2fa006 ba2e7852 ba2f9f72 SPBBCDrv+0xb870

ba32df60 ba2fa006 ba2e7852 ba2f9f72 ba2fa05e SPBBCDrv+0xb852

ba32df64 ba2e7852 ba2f9f72 ba2fa05e ba2e787e SPBBCDrv+0x1e006

 

This thread has an I/O request packet (IRP), let’s see what we have in this IRP using the !irp command:

 

0: kd> !irp 8a1279f0

Irp is active with 11 stacks 9 is current (= 0x8a127b80)

 No Mdl: No System Buffer: Thread 8a127020:  Irp stack trace. 

     cmd  flg cl Device   File     Completion-Context

 [  0, 0]   0  0 00000000 00000000 00000000-00000000   

 

                     Args: 00000000 00000000 00000000 00000000

 [  0, 0]   0  0 00000000 00000000 00000000-00000000   

 

                     Args: 00000000 00000000 00000000 00000000

 [  0, 0]   0  0 00000000 00000000 00000000-00000000   

 

                     Args: 00000000 00000000 00000000 00000000

 [  0, 0]   0  0 00000000 00000000 00000000-00000000   

 

                     Args: 00000000 00000000 00000000 00000000

 [  0, 0]   0  0 00000000 00000000 00000000-00000000   

 

                     Args: 00000000 00000000 00000000 00000000

 [  0, 0]   0  0 00000000 00000000 00000000-00000000   

 

                     Args: 00000000 00000000 00000000 00000000

 [  0, 0]   0  0 00000000 00000000 00000000-00000000   

 

                     Args: 00000000 00000000 00000000 00000000

 [  0, 0]   0  0 00000000 00000000 00000000-00000000   

 

                     Args: 00000000 00000000 00000000 00000000

>[  0, 0]   1 e0 8a045020 897c27a0 ba5f7640-b85ec490 Success Error Cancel Pending

              \FileSystem\Ntfs    SYMEVENT

                     Args: b85ec5b0 01000021 00070000 00000000

 [  0, 0]   1 e0 8a1146d0 897c27a0 f71e0fac-88af0480 Success Error Cancel

              \Driver\SymEvent    fltmgr!FltpGeneralCompletion

                     Args: b85ec5b0 01000021 00070000 00000000

 [  0, 0]   1  0 89d43620 897c27a0 00000000-00000000   

              \FileSystem\FltMgr

                     Args: b85ec5b0 01000021 00070000 00000000

 

The IRP is pending during a file access (FileSystem\NTFS) for the filter driver SYMEVENT. Let’s see which NTFS object this drive was accessing during the time that the issue was happening:

 

0: kd> !object 897c27a0

Object: 897c27a0  Type: (8a3be560) File

    ObjectHeader: 897c2788

    HandleCount: 0  PointerCount: 1

    Directory Object: 00000000  Name: \urlcache\dir1.cdat

 

Great, looks like the Antivirus is scanning the ISA Server cache file. Let’s see the version of the 3rd party drivers that were in the stack:

 

0: kd> lmvm SYMEVENT

start    end        module name

ba5f0000 ba612000   SYMEVENT   (no symbols)          

    Loaded symbol image file: SYMEVENT.SYS

    Image path: \??\C:\Program Files\Symantec\SYMEVENT.SYS

    Image name: SYMEVENT.SYS

    Timestamp:        Mon Jan 16 14:53:50 2006 (43CC07DE)

    CheckSum:         0001A8D7

    ImageSize:        00022000

    Translations:     0000.04b0 0000.04e0 0409.04b0 0409.04e0

 

0: kd> lmvm SPBBCDrv

start    end        module name

ba2dc000 ba33e000   SPBBCDrv   (no symbols)          

    Loaded symbol image file: SPBBCDrv.sys

    Image path: \??\C:\Program Files\Common Files\Symantec Shared\SPBBC\SPBBCDrv.sys

    Image name: SPBBCDrv.sys

    Timestamp:        Mon Feb 06 14:34:12 2006 (43E7B2C4)

    CheckSum:         0006C4AB

    ImageSize:        00062000

    Translations:     0000.04b0 0000.04e0 0409.04b0 0409.04e0

 

 

4. Conclusion

 

This was one of many examples that I see in daily basis when I’m working with customers that have Antivirus installed on ISA Server. Fortunately we published in the Tales from the Edge site the official statement about having Antivirus installed in ISA Server. So, if you really need to have an Antivirus on ISA Server, follow the guidelines of the article Considerations when using antivirus software on ISA Server. This particular issue was fixed after update the Antivirus filter driver and excludes the ISA Server folders from the real time scan.