In a recent case, I dealt with an Outlook MAPI connection failure problem through direct access tunnel (configured with UAG 2010) and I’ll be talking about how I troubleshooted this issue in this post.

The problem was reported as Outlook 2010 clients were failing to access Exchange 2010 servers that run behind a UAG 2010 server. We decided to collect the following logs to better understand the root cause of the problem:

 

=> On the direct access client:

netsh wfp capture start

netsh trace start scenario=directaccess capture=yes tracefile=darepro.etl maxsize=350

nmcap /network * /capture /file DAClient.chn:100M

 

=> On the UAG 2010 server:

nmcap /network * /capture /file DAServer.chn:100M

 

Note 1: You have to install Network Monitor 3.4 to run the nmcap command

http://www.microsoft.com/downloads/details.aspx?displaylang=en&FamilyID=983b941d-06cb-4658-b7f6-3088333d062f

Note 2: “netsh wfp capture start” command collects WFP (windows filtering platform) and Ikeext (ipsec negotiation) etl traces

Note 3: “netsh trace start scenario=directaccess” command collects direct access related component ETL traces (like ip helper service, tcpip, afd, dns, winhttp, wininet etc). You can see the ETL traces for which components are collected for the “directaccess” scenario by running “netsh trace show scenario directaccess)

Note 4: Please note that all such commands need to be run from an elevated command prompt. And all the commands (except nmcap) are supported on Windows 7/2008 R2 onwards.

 

After starting the logs as given above, we reproduced the problem and stopped collecting logs as below:

- CTRL + C stops nmcap

- netsh wfp capture stop (for WFP tracing)

- netsh trace stop (for Directaccess related tracing)

 

Troubleshooting:

From the ETL trace (collected as a result of netsh trace start scenario=directaccess), I was able to see that the Outlook client was failing to resolve MAPI interface endpoint information (IP:port) from the remote Exchange 2010 server which is done via RPC endpoint mapper:

31508      15:37:26.9645379   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (Family=IPV6 PID=5788 (0x169C)) created.

31509      15:37:26.9645392   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint 0x00000000042E4CF0 (Family=IPV6, PID=5788 (0x169C)) created with status = Success.

31512      15:37:26.9647035   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint/connection 0x00000000042E4CF0 acquired port number 61581 (0xF08D).

31513      15:37:26.9647172   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (sockaddr=0:0:0:0:0:0:0:0:61581 (0xF08D)) bound.

31517      15:37:26.9647660   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 transition from ClosedState to SynSentState, SndNxt = 0 (0x0).

31518      15:37:26.9648157   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 attempted to acquire weak reference on port number 61581 (0xF08D) inherited from endpoint 0x00000000042E4CF0. Successful = TRUE.

31519      15:37:26.9648191   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: Tcb 0x00000000042E0AE0 (local=2001:0:0A0B:86E8:388E:FCB:4337:1876:61581 (0xF08D) remote=2002:0A01:86E8:8001:0:0:A0B:0202:135 (0x87)) requested to connect.

=> A0B:0202:135 is the internal IP address (10.11.2.2) of Exchange 2010 CAS server and the target port (135)

31520      15:37:26.9648319   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: Inspect Connect has been completed on Tcb 0x00000000042E0AE0 with status = Success.

31521      15:37:26.9648452   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: Tcb 0x00000000042E0AE0 is going to output SYN with ISN = 2258039006 (0x8696F0DE), RcvWnd = 8192 (0x2000), RcvWndScale = 8 (0x8).

31522      15:37:26.9648469   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 (local=2001:0:C32A:86E8:388E:FCB:4337:1876:61581 (0xF08D) remote=2002:C32A:86E8:8001:0:0:A0B:9522:135 (0x87)) connect proceeding.

31523      15:37:26.9648542   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0: Sent data with number of bytes = 1 (0x1) and Sequence number = 2258039006 (0x8696F0DE).

31541      15:37:27.0024371   System (4)                                              TCPIP_MicrosoftWindowsTCPIP             TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 transition from SynSentState to EstablishedState, SndNxt = 2258039007 (0x8696F0DF).

31542      15:37:27.0024392   System (4)                                              TCPIP_MicrosoftWindowsTCPIP             TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0: Received data with number of bytes = 1 (0x1). ThSeq = 3786409003 (0xE1B0042B).

31543      15:37:27.0024439   System (4)                                              TCPIP_MicrosoftWindowsTCPIP             TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 (local=2001:0:0A0A:2222:1111:FCB:4337:1876:61581 (0xF08D) remote=2002:0A0A:86E8:8001:0:0:A0B:9522:135 (0x87)) connect completed. PID = 5788 (0x169C).

=> TCP 3-way handshake has been finished here.

31547      15:37:27.0027145   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0, delivery 0x00000000042E0C40, Request 0x000000000408C6B0  posted for 0x0000000000000400 bytes, flags = 0 (0x0). RcvNxt = 3786409003 (0xE1B0042B).

31550      15:37:27.0027367   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 send posted posted 72 (0x48) bytes at 2258039007 (0x8696F0DF).

=> We send the RPC map request to the Exchange 2010 server here. (frame #31550)

31552      15:37:27.0027949   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0: Sent data with number of bytes = 72 (0x48) and Sequence number = 2258039007 (0x8696F0DF).

31556      15:37:27.0427894   System (4)                                              TCPIP_MicrosoftWindowsTCPIP             TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0: Cumulative ACK updated cwnd = 2300 (0x8FC).

31557      15:37:27.0428317   System (4)                                              TCPIP_MicrosoftWindowsTCPIP             TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 delivery 0x00000000042E0C40 satisfied 0x0000000000000018 bytes 0x0000000000000400 requested. IsFullySatisfied = 0 (0x0). RcvNxt = 3786409003 (0xE1B0042B).

31559      15:37:27.0428553   System (4)                                              TCPIP_MicrosoftWindowsTCPIP             TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0: Received data with number of bytes = 24 (0x18). ThSeq = 3786409003 (0xE1B0042B).

=> We get RPC map response from Exchange 2010 server here (frame #31559), it's just 24 bytes. Normally it should have been some 150 bytes or so.

31563      15:37:27.0430051   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 transition from EstablishedState to FinWait1State, SndNxt = 2258039079 (0x8696F127).

31564      15:37:27.0430171   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0: Sent data with number of bytes = 1 (0x1) and Sequence number = 2258039079 (0x8696F127).

31565      15:37:27.0432076   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (sockaddr=0:0:0:0:0:0:0:0:61581 (0xF08D)) closed.

31566      15:37:27.0432123   OUTLOOK.EXE (5788)                                             TCPIP_MicrosoftWindowsTCPIP                TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint/connection 0x00000000042E4CF0 released port number 61581 (0xF08D). WeakReference = FALSE.

31590      15:37:27.0458327   System (4)                                              TCPIP_MicrosoftWindowsTCPIP             TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0: Received data with number of bytes = 1 (0x1). ThSeq = 3786409027 (0xE1B00443).

31591      15:37:27.0458588   System (4)                                              TCPIP_MicrosoftWindowsTCPIP             TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 transition from FinWait1State to ClosingState, SndNxt = 2258039080 (0x8696F128).

31592      15:37:27.0458605   System (4)                                              TCPIP_MicrosoftWindowsTCPIP             TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x00000000042E0AE0 delivery 0x00000000042E0C40 delivering FIN. RcvNxt = 3786409028 (0xE1B00444).

=> TCP session has been gracefully terminated here.

(Note: The ETL trace could be opened with Network Monitor 3.4)

 

- In the above trace, Outlook client establishes a TCP connection TCP port 135 at Exchange 2010 server.

- But the session is terminated gracefully quickly after it’s established. Most likely we didn't receive the response we expected (where the endpoint information would be seen). Since this is through direct access tunnel, we cannot see the packet in clear, we're making comments based on TCPIP driver ETL trace.

Then I decided to check UAG server to Exchange server activity from the UAG server side network trace. In that network trace, I saw that Exchange server was successfully responding to map requests sent through RPC endpoint mapper connection to Exchange server:

Note: Please note that all IP addresses are deliberately changed.

 

=> Endpoint mapper request sent from UAG server to Exchange 2010 server:

Internet Protocol Version 4, Src: 10.1.1.1 (10.1.1.1), Dst: 10.11.2.2(10.11.2.2)

Transmission Control Protocol, Src Port: 33654 (33654), Dst Port: 135 (135), Seq: 2005198912, Ack: 3769475906, Len: 156

Distributed Computing Environment / Remote Procedure Call (DCE/RPC) Request, Fragment: Single, FragLen: 156, Call: 2 Ctx: 0, [Resp: #32049]

DCE/RPC Endpoint Mapper, Map

    Operation: Map (3)

    [Response in frame: 32049]

    UUID pointer:

        Referent ID: 0x00000001

        UUID: 00000000-0000-0000-0000-000000000000

    Tower pointer:

        Referent ID: 0x00000002

        Length: 75

        Length: 75

        Number of floors: 5

        Floor 1  UUID: MAPI

        Floor 2  UUID: Version 1.1 network data representation protocol

        Floor 3  RPC connection-oriented protocol

        Floor 4  TCP Port:135

        Floor 5  IP:0.0.0.0

    Handle: 0000000000000000000000000000000000000000

    Max Towers: 15

 

=> Endpoint mapper response sent from Exchange 2010 server to UAG server:

Internet Protocol Version 4, Src: 10.11.2.2(10.11.2.2), Dst: 10.1.1.1 (10.1.1.1)

Transmission Control Protocol, Src Port: 135 (135), Dst Port: 33654 (33654), Seq: 3769475906, Ack: 2005199068, Len: 152

Distributed Computing Environment / Remote Procedure Call (DCE/RPC) Response, Fragment: Single, FragLen: 152, Call: 2 Ctx: 0, [Req: #32046]

DCE/RPC Endpoint Mapper, Map

    Operation: Map (3)

    [Request in frame: 32046]

    Handle: 0000000000000000000000000000000000000000

    Num Towers: 1

    Tower array:

        Max Count: 15

        Offset: 0

        Actual Count: 1

        Tower pointer:

            Referent ID: 0x00000003

            Length: 75

            Length: 75

            Number of floors: 5

            Floor 1  UUID: MAPI

            Floor 2  UUID: Version 1.1 network data representation protocol

            Floor 3  RPC connection-oriented protocol

            Floor 4  TCP Port:41376

            Floor 5  IP:10.11.2.7

    Return code: 0x00000000

 

I realized something weird in the map response coming back from RPC endpoint mapper on Exchange 2010 server:

            Floor 5  IP:10.11.2.7

 

Actually I would expect to see  10.11.2.2 as the endpoint IP address in the RPC map response header (the IP header still has the source IP address 10.11.2.2) but it wasn’t. It was set to 10.11.2.7. Actually that happens when Exchange (or other servers that expose RPC interfaces) run behind a HW load balancer. So in this scenario:

10.11.2.2 is the VIP (virtual IP) or load balanced IP address of the Exchange 2010 CAS array. 10.11.2.7 is the dedicated IP address of the Exchange 2010 server that is responding to UAG server’s RPC map request (sent to discover the MAPI RPC endpoint information)

HW load balancer modifies the IP headers (in map request or in map response) but it doesn’t touch the RPC header buried inside the IP packet.

 

OK, so far so good. Even though we get endpoint information with a different IP address than we expected, we still get an RPC map response succesfully. So why is that processing still failing?

Well, this was the key point J . Please remember that UAG server uses TMG server to protect itself and RPC filter as part of TMG server by default doesn’t allow such RPC responses due to security reasons. (the endpoint IP address is different than the one RPC map request sent to)

 

The resolution here was to apply the script mentioned in the below article on the TMG server (which is the same box with UAG 2010 server):

FIX: The TMG remote management console does not display the status of the TMG 2010 server if certain Group Policy preferences settings are set

http://support.microsoft.com/kb/982604

 

Actually the article itself is unrelated here but by running this script, we instruct the RPC filter not to drop RPC responses when RPC endpoint IP address given in the RPC header is different than the IP address to which the RPC request was sent.

You might be wondering how the RPC map request was sent to Exchange 2010 with IPv4 address whereas the original request was sent with IPv6 by the direct access client. Well the answer is DNS64/NAT64 functionality present in UAG 2010 server (and now present in Windows Server 2012 consumer preview). You can find more details about how DNS64/NAT64 works at the following article:

http://blogs.technet.com/b/edgeaccessblog/archive/2009/09/08/deep-dive-into-directaccess-nat64-and-dns64-in-action.aspx

 

Hope this helps

Thanks,

Murat