In this post, I’ll be talking about a web publishing problem and how I dealt with it. The problem was that external clients were failing to access an internal Web server published on ISA 2004 server with HTTP 500 internal error.

As usual, I asked the following logs from our customer when reproducing the problem:

- Collecting an ISA data packager while reproducing the problem (as part of ISA Best practices Analyzer log). The tool could be downloaded from the below link:

http://www.microsoft.com/en-us/download/details.aspx?id=811

- Collecting a network trace from the internal web server

- Collecting a network trace and Fiddler trace from an external test client. It could be downloaded at the following link:

http://www.fiddler2.com/fiddler2/

Note: Fiddler or similar tools (like HTTPWatch – we also use it) provide useful information even if the connection is clear text HTTP. For HTTPS connections it’s nearly a requirement to collect it to see what’s going on from client’s perspective. Another possibility is collecting WinInet/WinHTTP ETL traces which I plan to discuss in another post.

Troubleshooting:

After collecting the logs, I started troubleshooting the problem

a) I first checked the Web proxy logs (collected as part of Data packager logs) and saw the same problem there: (I included only a part of the log and also changed the names deliberately)

Result code is -2146893022 which is FFFFFFFF80090322 which is SEC_E_WRONG_PRINCIPAL

Actually the web listener used by the given web publishing rule doesn’t have authentication configured. But that error might also be seen when certificate related issues are seen.

b) Then I decided to check the ETL trace that was also collected as part of ISA data packager. Please note that the ETL trace collected as part of data packager could only be converted to human readable format by Microsoft support but we also provide a lightweight version of the same facility as part of the product. You can do that as follows:

(Before reproducing the problem you have to enable logging from “Enable Diagnostic Logging” and once the problem is reproduced you have to disable logging by selecting “Disable Diagnostic Logging”)

When checking ETL traces, one of the key parameters is the filter info which is also a part of Web proxy log. Example:

So I focused on the relevant filter info and have seen the following problem there: (please note that the ETL output is much more detailed than shown below)

…

… Failed - server name doesn't match. local name : web.contoso.com, cert name: *.contoso.com

…

After seeing the error above, I realized that we were hitting the known limitation with ISA 2004 and wildcard certificates used on published servers:

http://technet.microsoft.com/en-us/library/cc302619.aspx Troubleshooting SSL Certificates in ISA Server 2004 Publishing

I am using wildcard certificates and getting the error: 500 Internet Server Error – The target principal name is incorrect.

ISA Server 2004 only supports wildcard certificates on the ISA Server computer. ISA Server 2006 also supports use of wildcard certificates on the published Web server. When using HTTPS to HTTPS bridging, you cannot use wildcard certificates to authenticate the back-end Web server. Instead, on the internal Web server, create a new certificate that matches the name of the internal Web server, as specified on the To tab in the Web publishing rule. For more information about configuring this scenario, see Publishing Multiple Web Sites using a Wildcard Certificate in ISA Server 2004 (www.microsoft.com).

For confirmation purposes, I also checked the network trace collected from the internal Web server and saw that the web server was really sending a wildcard certificate to ISA 2004 server:

=> The relevant frame:

Frame: Number = 8649, Captured Frame Length = 2974, MediaType = ETHERNET

…

- TLS: TLS Rec Layer-1 HandShake: Server Hello. Certificate.

  - TlsRecordLayer: TLS Rec Layer-1 HandShake:

     ContentType: HandShake:

   + Version: TLS 1.0

     Length: 4786 (0x12B2)

   - SSLHandshake: SSL HandShake Certificate(0x0B)

      HandShakeType: ServerHello(0x02)

      Length: 77 (0x4D)

    + ServerHello: 0x1

      HandShakeType: Certificate(0x0B)

      Length: 4697 (0x1259)

    - Cert: 0x1

       CertLength: 4694 (0x1256)

     - Certificates:

        CertificateLength: 1457 (0x5B1)

      + X509Cert: Issuer: ContosoSubCA,contoso,com, Subject: *.contoso.com

…

- The web server has a wildcard certificate assigned (*.contoso.com)

The resolution to this problem is to assign a new certificate to the internal Web server which is not a wildcard certificate. You can find more information below:

http://technet.microsoft.com/library/cc302625.aspx Publishing Multiple Web Sites Using a Wildcard Certificate in ISA Server 2004)

Hope this helps

Thanks,

Murat

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

Recently I dealt with a problem where PDF file downloaded from a certain external web site was always corrupted and I would like to talk about how I troubleshooted that problem. The client was connected to internet through a four node TMG 2010/SP2 array.

We decided to collect the following logs to better understand why the file was corrupted:

- Network trace on the internal client

- TMG data packager on one of the TMG servers

(Since the problem was reproducible by setting any of the TMG servers as the proxy server, we set one of the array members as a proxy server to collect less logs)

Note: TMG data packager is installed as part of TMG Best practices Analyzer installation

http://www.microsoft.com/en-us/download/details.aspx?id=17730

Microsoft Forefront Threat Management Gateway Best Practices Analyzer Tool

The results from the log analysis were as below:

- There weren’t any connectivity problems present in the TCP sessions (through which the file was downloaded) in the network trace collected on the client, internal and external interfaces of TMG server

- The error code for the given file download was 13: (taken from Web proxy log)

Note: IP addresses/links/proxy names etc are deliberately changed

Error 13 is “The data is invalid”:

C:\>net helpmsg 13

The data is invalid.

So TMG server thinks that the received data was invalid. That also explains why the downloaded file was corrupted.

Then I decided to take a look at the ETL trace which was also collected with TMG Data packager. Actually the root cause behind why TMG server thought the data was invalid was clearly visible there:

…

... GZIP Dempression failed. Drop the request. (connection closed=0) 0x8007000d(ERROR_INVALID_DATA)

…

Because the file decompression fails on TMG server, TMG server finalizes the session with Error_Invalid_data (error 13)

Note: Please note that you have to contact Microsoft support for ETL trace conversion

Note: You can also collect a similar diagnostics log from TMG server’s console:

(Before reproducing the problem you have to enable logging from “Enable Diagnostic Logging” and once the problem is reproduced you have to disable logging by selecting “Disable Diagnostic Logging”)

For troubleshooting purposes, I suggested to turn off Compression on TMG server:

(We remove “External” from the “Request compressed HTTP content when sending requests to these network elements” section.)

As expectedly the corrupted file download problem was resolved. When we make the above configuration change actually we ask the TMG server not to ask for compression when sending HTTP requests out to external web servers. So the file was downloaded in uncompressed format. Please note that TMG server asks for compression for HTTP requests sent to external web sites by default and that provides some bandwidth saving by minimizing the amount of data transferred.

We decided that the problem was somehow related to the target web site or upstream Web proxy because the same TMG server was able to successfully download HTTP content in compressed format from other external web sites.

Normally it’s possible to turn off compression for a specific web site (which could be configured from “Exceptions” tab in the above screen shot). But the TMG array in question was configured to use an upstream proxy for all external web traffic. So creating an exception wouldn’t make much difference here. Our customer decided to keep HTTP compression off (and re-enable it once the file downloads from the given web site were finished)

Hope this helps

Thanks,

Murat