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<*>
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] 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
[ 0, 0] 1 0 89d43620 897c27a0 00000000-00000000
\FileSystem\FltMgr
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
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
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.