Side Effects of Incorrect DNS configuration on ISA Server: 10060 Connection Timeout Scenario

1. Introduction

 

Although this topic might sounds “basic stuff”, we still see many cases where DNS is the culprit. There are cases where DNS is not answering properly, not correctly configured on ISA Server and in some cases the DNS Server is actually down (easy one to fix it J). The fact that matters is that if your DNS gets sick, ISA will be ill too. ISA Server rely as a core component on name resolution, although ISA Server has its own DNS cache that runs under the firewall service process context (wsprsrv.exe), ISA is still using the OS DNS client as well.

 

The goal of this article is to go through a scenario where clients were complaining that they were unable to access some web sites when passing through ISA Server. However, before we start the scenario that explains one common side effect of having an incorrect DNS configuration on ISA Server take a look in the following article as the main recommendation for DNS Configuration on ISA Server:

http://technet.microsoft.com/en-us/library/cc302590.aspx

 

2. Sample Scenario

 

To make it easier to understand the root cause of this problem, let’s take a look in the topology used by this environment:

 

Figure 1 – Topology used on this scenario.

 

In this scenario the error message that the client workstation was receiving was 10060 (timeout) when trying to browse www.fourthcoffee.com and the error message below was showing up on ISA Server Logging as:

 

 

Figure 2 – Error while browsing www.fourthcoffee.com.

 

I bet that if you look closely on figure 1 and 2 you already identify the possible cause of this issue, didn’t you? Probably you did and don’t realize yet. Notice that the client workstation is part of the fourthcoffee.com domain, it is trying to browse an intranet site called www.fourthcoffee.com and ISA Server instead of sending the packet to the internal network is actually thinking that the destination belongs to the external network. If you look it to Figure to you will see that the destination on ISA perspective is 192.168.0.189, which is an external host (based on the topology showed on figure 1). Why this happens in first place?

 

For this particular scenario, when looking to the netmon trace of the internal network I couldn’t see any DNS Query to resolve www.fourthcoffee.com, there are three assumptions at that point: ISA Server is using cache information, ISA Server is sending the DNS Query to another interface or client already resolved the name and is sending directly to the destination IP. Looking the netmon trace on the external interface it was possible to see the following request

 

192.168.0.1 192.168.0.10 DNS DNS:QueryId = 0xF5C5, QUERY (Standard query), Query for www.fourthcoffee.com of type Host Addr on class Internet

 

192.168.0.10 192.168.0.1 DNS DNS:QueryId = 0xF5C5, QUERY (Standard query), Response - Success, 192.168.0.189

 

After ISA Server resolves the name it tries to establish the TCP Handshake on port 80 on the destination host and guess what? This host doesn’t answer as shown below:

 

192.168.0.1 192.168.0.189 TCP TCP:Flags=......S., SrcPort=9496, DstPort=HTTP(80), PayloadLen=0, Seq=3490482351, Ack=0, Win=65535 ( ) = 65535

192.168.0.1 192.168.0.189 TCP TCP:[SynReTransmit #5]Flags=......S., SrcPort=9496, DstPort=HTTP(80), PayloadLen=0, Seq=3490482351, Ack=0, Win=65535 ( ) = 65535

192.168.0.1 192.168.0.189 TCP TCP:[SynReTransmit #5]Flags=......S., SrcPort=9496, DstPort=HTTP(80), PayloadLen=0, Seq=3490482351, Ack=0, Win=65535 ( ) = 65535

192.168.0.1 192.168.0.189 TCP TCP:[SynReTransmit #8]Flags=......S., SrcPort=9498, DstPort=HTTP(80), PayloadLen=0, Seq=1596124610, Ack=0, Win=65535 ( ) = 65535

192.168.0.1 192.168.0.189 TCP TCP:[SynReTransmit #12]Flags=......S., SrcPort=9499, DstPort=HTTP(80), PayloadLen=0, Seq=3838730273, Ack=0, Win=65535 ( ) = 65535

192.168.0.1 192.168.0.189 TCP TCP:[SynReTransmit #12]Flags=......S., SrcPort=9499, DstPort=HTTP(80), PayloadLen=0, Seq=3838730273, Ack=0, Win=65535 ( ) = 65535

 

Lots of retransmissions without answer and after that ISA Server sends the HTTP 504 Time out to the client workstation.

 

3. Root Cause

 

The problem here was that ISA Server was using DNS on both adapters, internal and external. According to the ISA Server DNS Best Practices this shouldn’t be done because can cause behaviors like that. Here again the statement from the article that was mentioned in the beginning of this post:

 

Always point DNS to either internal servers or external servers, never to both.

From http://technet.microsoft.com/en-us/library/cc302590.aspx

Clearly using DNS on both adapters can cause you many problems, here is another example of a problem that can happen (from the same TechNet article):

 

Q: Why not point the external ISA NIC to the ISP for DNS?

A:   The problem here is that ISA doesn’t know what is internal or external when trying to resolve names. This means ISA can end up trying to resolve internal names to the external ISP. Once it receives “name not found”, the ISA Server computer won’t look for the internal name again and you will fail to participate in the domain.

 

4. Under the Hood

 

If you understood the above scenario and is aware that you shouldn’t do that then the goal of this article was achieved. However if you want to go under the hood and see how wspsrv.exe behaves in such circumstance, take a look in this kernel mode dump while this problem was happening:

 

- First thing to do is to type !process 0 0 to identify the process if of wspsrv.exe. Since the output for this command is long in a kernel mode dump (due the amount of process running) I will go to the next command which is to change the context to wspsrv.exe process:

 

0: kd> .process /p / r 89468b70

Implicit process is now 89468b70

- At this point we can dump all the threads running within this process by using the command !process 89868b70. The output for this can be also huge, depending how busy wsprsv.exe is. The output of this command revealed also that there are some threads were waiting for an LPC call to complete, such as this one below:

 

        THREAD 88903020 Cid 071c.07bc Teb: 7ffa5000 Win32Thread: e2059078 WAIT: (WrLpcReply) UserMode Non-Alertable

            8890320c Semaphore Limit 0x1

        Waiting for reply to LPC MessageId 00083100:

        Current LPC port e203d118

        IRP List:

            87e12aa8: (0006,0190) Flags: 00000000 Mdl: 87dd05c0

            88953008: (0006,0190) Flags: 00000000 Mdl: 88196218

            87a4ade0: (0006,0190) Flags: 00000000 Mdl: 878a4660

         87827008: (0006,0190) Flags: 00000000 Mdl: 8819a590

            879f74f8: (0006,0190) Flags: 00000000 Mdl: 881ec498

            8772ba40: (0006,0190) Flags: 00000000 Mdl: 8819bf88

            881b6b88: (0006,0190) Flags: 00000000 Mdl: 87e5c7c8

     880a2cf8: (0006,0190) Flags: 00000000 Mdl: 88282b88

            87a5c008: (0006,0190) Flags: 00000000 Mdl: 8933ad00

            87e34938: (0006,0190) Flags: 00000000 Mdl: 881f11c8

            8890b318: (0006,0094) Flags: 00000000 Mdl: 00000000

  885d5008: (0006,0190) Flags: 00000000 Mdl: 89969740

            885e8290: (0006,0190) Flags: 00000000 Mdl: 883aa4a0

            89465bf0: (0006,0094) Flags: 00000800 Mdl: 00000000

            8931b730: (0006,0190) Flags: 00000000 Mdl: 89e39e48

            89505008: (0006,0190) Flags: 00000000 Mdl: 898b1108

        Not impersonating

        DeviceMap e1630f98

        Owning Process 89468b70 Image: wspsrv.exe

        Wait Start TickCount 70669 Ticks: 56 (0:00:00:00.875)

        Context Switch Count 22391 LargeStack

        UserTime 00:00:05.218

        KernelTime 00:00:01.578

        Win32 Start Address wspsrv!CtrlThrdRtn (0x00456baa)

   Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

        Stack Init f7557000 Current f7556c08 Base f7557000 Limit f7553000 Call 0

        Priority 13 BasePriority 8 PriorityDecrement 0

        ChildEBP RetAddr

        f7556c20 80833485 nt!KiSwapContext+0x26
f7556c4c 80829a82 nt!KiSwapThread+0x2e5

        f7556c94 8091ec18 nt!KeWaitForSingleObject+0x346

        f7556d50 808897bc nt!NtRequestWaitReplyPort+0x776 <== Waiting for a reply (RPC over LPC)

        f7556d50 7c8285ec nt!KiFastCallEntry+0xfc

        01c3eb78 7c82787b ntdll!KiFastSystemCallRet

        01c3eb7c 77c80a6e ntdll!NtRequestWaitReplyPort+0xc

        01c3ebc8 77c7fcf0 RPCRT4!LRPC_CCALL::SendReceive+0x230

        01c3ebd4 77c80673 RPCRT4!I_RpcSendReceive+0x24 <= RPC Call

        01c3ebe8 77ce315a RPCRT4!NdrSendReceive+0x2b

        01c3efd0 76ed5049 RPCRT4!NdrClientCall2+0x22e

        01c3efe8 76ed4f69 DNSAPI!R_ResolverQuery+0x1c

        01c3f044 76ed6f5d DNSAPI!Query_PrivateExW+0x187

        01c3f078 76ee9d0c DNSAPI!Query_Shim+0x48

        01c3f0a0 62ea7442 DNSAPI!DnsQuery_A+0x20 <= DNS Query

        01c3f0ec 62ea789e MSPHLPR!QueryDnsCache+0x3a

        01c3f110 62ea6583 MSPHLPR!gethosttlbyname+0x6e

        01c3f458 647484a2 MSPHLPR!ProxyGetHostByName+0x32c

        01c3f498 64748e4e w3filter!+0x2cc

        01c3f4e0 6476676f w3filter!+0x306

        01c3f530 64773614 w3filter!+0x19a

        01c3f56c 647746d4 w3filter!+0x112

        01c3f580 64729101 w3filter!+0x18

        01c3f58c 64727a4e w3filter!+0x3b

        01c3fe1c 6472829a w3filter!+0xc23

       01c3fe90 0046d838 w3filter!+0x3dd

        01c3fefc 0046e598 wspsrv!+0x15f

        01c3ff14 004c5c7e wspsrv!+0x8a

        01c3ff20 0046e69f wspsrv!+0x37

        01c3ff30 0046d5f1 wspsrv!+0x31

        01c3ff50 00455fed wspsrv!+0x23

        01c3ff7c 00456d12 wspsrv!+0x44

        01c3ffb8 77e64829 wspsrv!+0x168

        01c3ffec 00000000 kernel32!BaseThreadStart+0x34

 

- According to this we are lead to believe that wspsrv.exe is waiting for a LPC call to complete in order to continue.

- Some additional notes about this output:

 

· WAIT: (WrLpcReply) : This tells us that the thread is waiting for a LPC reply. This information called as the “Wait Reason” is passed to KeWaitForSingleObject( ) as a parameter. This is retrieved from the _KTHREAD.WaitReason field.

· Waiting for reply to LPC MessageId 00083100: This line gives the message ID of the LPC message that was sent to the server thread.

· Current LPC port e203d118: The port number listed is the client communication port.

· 8890320c Semaphore Limit 0x1 : The semaphore that the thread is waiting for is signaled when a reply message is posted to the client communication ports message queue. NtRequestWaitReplyPort( ) waits on this semaphore.

 

Note: Reference for those definitions - http://blogs.msdn.com/ntdebugging/archive/2007/09/10/lpc-part-3-debugging-a-real-world-lpc-scenario.aspx

 

- Let’s switch the context to the thread 88903020 now by using the command .thread 88903020 and after that we can dump the stack with the command kv 25 (in this case 25 will give us the complete call stack since the BaseThreadStart function).

 

0: kd> .thread 88903020

Implicit thread is now 88903020

0: kd> kv 25

ChildEBP RetAddr Args to Child

f7556c20 80833485 88903020 889030c8 00000001 nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])

f7556c4c 80829a82 8890320c 889031e0 88903020 nt!KiSwapThread+0x2e5 (FPO: [Non-Fpo])

f7556c94 8091ec18 8890320c 00000011 00000001 nt!KeWaitForSingleObject+0x346

f7556d50 808897bc 00000ca8 18611128 18611128 nt!NtRequestWaitReplyPort+0x776

f7556d50 7c8285ec 00000ca8 18611128 18611128 nt!KiFastCallEntry+0xfc

01c3eb78 7c82787b 77c80a6e 00000ca8 18611128 ntdll!KiFastSystemCallRet

01c3eb7c 77c80a6e 00000ca8 18611128 18611128 ntdll!NtRequestWaitReplyPort+0xc

01c3ebc8 77c7fcf0 01c3ec04 01c3ebe8 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230

01c3ebd4 77c80673 01c3ec04 76ed42d8 01c3eff0 RPCRT4!I_RpcSendReceive+0x24

01c3ebe8 77ce315a 01c3ec30 186111a4 00000000 RPCRT4!NdrSendReceive+0x2b

01c3efd0 76ed5049 76ed42d8 76ed421c 01c3eff0 RPCRT4!NdrClientCall2+0x22e

01c3efe8 76ed4f69 00000000 1ed800e8 00000001 DNSAPI!R_ResolverQuery+0x1c

01c3f044 76ed6f5d 1ed800e8 00000001 00000000 DNSAPI!Query_PrivateExW+0x187

01c3f078 76ee9d0c 00000003 01c3f354 00000001 DNSAPI!Query_Shim+0x48

01c3f0a0 62ea7442 01c3f354 00000001 00000000 DNSAPI!DnsQuery_A+0x20

01c3f0ec 62ea789e 01c3f354 00000001 01c3f130 MSPHLPR!QueryDnsCache+0x3a

01c3f110 62ea6583 01c3f354 01c3f130 62ea6257 MSPHLPR!gethosttlbyname+0x6e

01c3f458 647484a2 1c6380a0 1c638120 00000000 MSPHLPR!ProxyGetHostByName+0x32c

01c3f498 64748e4e 1c638120 00000000 00000000 w3filter!+0x2cc (FPO: [Non-Fpo])

... <= Hiding all the wspsrv calls since this is not relevant at this point

01c3ffec 00000000 00456baa 00000001 00000000 kernel32!BaseThreadStart+0x34

 

- The DNSQuery_A function has the following parameters:

 

DNS_STATUS WINAPI DnsQuery(

  __in PCTSTR lpstrName,

  __in WORD wType,

  __in DWORD Options,

  __inout_opt PVOID pExtra,

  __out_opt PDNS_RECORD *ppQueryResultsSet,

  __out_opt PVOID *pReserved

);

From: http://msdn.microsoft.com/en-us/library/ms682016(VS.85).aspx

 

The first parameter is the one that is interesting for us at this point, since we want to know which name is trying to resolve. You can find this parameter in the third column in the stack above, which is 01c3f354. We can use the command da to display the value of this parameter as shown below:

 

0: kd> da 01c3f354

01c3f354 "fourthcoffee.com"

 

- As you can notice we are performing the name resolution for the internal domain and the thread that is performing that is actually waiting a LPC reply. Let's take a look at this LPC message:

 

0: kd> !lpc message 00083100

Searching message 826fe in threads ...

    Server thread 882ee590 is working on message 826fe

Client thread 8846c470 waiting a reply from 826fe

Searching thread 8846c470 in port rundown queues ...

Server communication port 0xe1fe5020

    Handles: 1 References: 1

    The LpcDataInfoChainHead queue is empty

        Connected port: 0xe203d118 Server connection port: 0xe1444ac8

Client communication port 0xe203d118

    Handles: 1 References: 11

    The LpcDataInfoChainHead queue is empty

Server connection port e1444ac8 Name: DNSResolver

    Handles: 1 References: 24

    Server process : 894e8020 (svchost.exe)

    Queue semaphore : 898fe978

    Semaphore state 0 (0x0)

  The message queue is empty

    The LpcDataInfoChainHead queue is empty

Done.

 

- We are waiting for a reply from the DNSResolver which belongs to the svchost.exe (server process id = 894e8020).

- You can still going on to see what the DNSResolve is doing by switching to this process with the command .process 894e8020.

 

0: kd> .process 894e8020

Implicit process is now 894e8020

 

- Next thing to do is to dump all the threads within this process with the command !process 894e8020 f, which will give you also a huge output (since most of the time svchost.exe has lots of threads).

 

- Focus on getting to the point, in other words from this huge output you need to look at the LCP message id that will be exposed in one of the threads. A tip here is to run .cls before run the !process command to clean all your screen, then run the command, copy all the content to clipboard (CTRL+A and CTRL+C), paste on a new notepad file, do a CTRL+F and search for this message id. In this case the message id that we are looking for is 0083100 which you need to search by removing the 00, just search for 83100. Here it is the thread that we are looking for:

 

THREAD 882bf020 Cid 031c.0ab0 Teb: 7ffa7000 Win32Thread: 00000000 WAIT: (Executive) UserMode Non-Alertable

8790287c NotificationEvent

Not impersonating

DeviceMap e1630f98

Owning Process 894e8020 Image: svchost.exe

Wait Start TickCount 70704 Ticks: 21 (0:00:00:00.328)

Context Switch Count 713

UserTime 00:00:00.000

KernelTime 00:00:00.000

Win32 Start Address 0x00083100

LPC Server thread working on message Id 83100

Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

Stack Init b95a4000 Current b95a3bb0 Base b95a4000 Limit b95a1000 Call 0

- From this point on the approach is the same: switch to 882bf020 process and dump the stack and see what is going on. To summarize this particular exercise by the following conclusion:

· ISA was waiting to resolve the name fourthcoffee.com. It was waiting for Windows DNSResolver to perform his job trying to resolve this name.

· Switching context from wsprsrv.exe process to svchost.exe (where dnsresolver runs) we see that the name resolution is taking some time to happen but eventually will happen (at least for this case) but it will return a wrong IP address.

 

At this point is important to emphasize that if wspsrv.exe keep waiting for the DNS for more long time (because maybe DNS is waiting for something else to happen) and more threads within wspsrv.exe process are having the same issue we might have a scenario where ISA stops completely to answer, causing the side effect described in the article below:

ISA Server 2006 stops answering requests
http://blogs.technet.com/isablog/archive/2009/01/12/isa-server-2006-stops-answering-requests.aspx

 

In this case we had a delay to answer but it did answer, unfortunately with the wrong IP address since it was doing an internal name resolution sending to the external interface.

 

5. Conclusion

 

As explained throughout this article name resolution is a MUST HAVE WORKING item when doing a health check on ISA. Many weird behaviors can happen when ISA doesn’t obtain a good answer from the DNS Server leading you to troubleshoot many other things before realize that name resolution is the root cause for the problem.

 

 

Author

Yuri Diogenes

Security Support Engineer

Microsoft CSS Forefront Edge Team

Technical Reviewer

Thomas Detzner

Escalation Engineer

Microsoft CSS Forefront Edge Team

Comments

• Anonymous
  March 05, 2014
  The comment has been removed
• Anonymous
  September 24, 2014
  The comment has been removed