Antivirus and ISA Server


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.


 

Comments (0)