Freigeben über

RPC over HTTP Logging Wildness

  • Artikel

Microsoft® Outlook® Web Access publishing is one of the most common publishing scenarios and so is the usage of RPC over HTTP for Outlook Anywhere to allow clients in the field to access their mailboxes. When troubleshooting RPC over HTTP issues, you might have noticed that in Microsoft Internet Security and Acceleration (ISA) Server live logging or in the ISA Server log files, there are many failures like error 64. This blog entry will walk through the reasons for this.

Suppose you have the following setup: I’ve used the Contoso virtual images because it is convenient. You can download those images from "TechNet Virtual Labs: ISA Server" at Microsoft TechNet.

 Topology

On the ISA Server computer, you create a publishing rule using the Exchange Web Client Access Publishing Rule Wizard, like the following.

Rule 

To understand the next lines, review how a normal HTTP conversation looks. It is usually composed of the following steps:

1. The client opens a TCP session and sends request headers.

2. If the request has a body, the client sends the whole body.

3. The server sends response headers, usually a 200 OK or a 30X-like response.

4. If the response has a body, the server sends the whole body.

5. If the request is done, the connection may keep-alive or close the connection.

For the case of RPC over HTTP, this flow is intentionally changed to make RPC work over HTTP. The sequence now looks like this:

1. The client (in this case, Outlook) opens a new TCP session and sends a request header with an HTTP method of RPC_IN_DATA and with content-length of 1 gigabyte (GB).

2. The client sends bytes whenever it wants. HTTP (and ISA Server) consider it as part of the request body, and patiently wait for the rest of the promised 1-GB body.

3. When the client doesn't need the connection anymore, it closes the connection, and at the same time, the client sends a request header with an HTTP method of RPC_OUT_DATA.

4. The server sends a 200-OK response header, with a content-length of 1 GB.

5. The server sends data whenever it wants. HTTP (and ISA Server) consider it as part of the response body, and patiently wait for the rest of the promised 1-GB body.

6. When the server doesn't need the connection anymore, it closes the connection.

Note that I omit the fact that RPC over HTTP usually runs over HTTPS. The steps outlined do not include the necessary Secure Sockets Layer (SSL) handshake, to reduce the complexity and focus on the core transactions only. The Outlook client will open multiple such sessions in parallel to the ISA Server computer. A good description of the traffic between the Outlook client and the Exchange server when using RPC over HTTP can be found in "Technical Details of Using RPC over HTTP to Access Exchange from an Outlook Client" at Microsoft TechNet.

To outline what is happening on the wire, I configured my setup to use HTTP instead of HTTPS between the ISA Server computer's internal interface and the IIS server. You can capture the network traffic with Network Monitor 3.0. When you do this, you should be able to see the following requests.

The first request from the client (ISA Server) is the RPC_IN_DATA request with the subcommand CL_ESTABLISH_IBP to the Web server:

+ Ethernet: Etype = Internet IP (IPv4)

+ Ipv4: Next Protocol = TCP, Packet ID = 54784, Total IP Length = 383

+ Tcp: Flags=...PA..., SrcPort=13227, DstPort=HTTP(80), Len=343, Seq=1605673567 - 1605673910, Ack=2126557174, Win=65535 (scale factor 0) = 0

- HTTP: Request, RPC_IN_DATA /rpc/rpcproxy.dll, CL_ESTABLISH_IBP

    Command: RPC_IN_DATA

  + URI: /rpc/rpcproxy.dll?denver.contoso.com:6002

    ProtocolVersion: HTTP/1.1

  Reverse-Via: FLORENCE

    Host: mail.contoso.com:443

    UserAgent: MSRPC

  + BasicAuthentication: Basic

    Accept: application/rpc

    Cache-Control: no-cache

    Pragma: no-cache

    Connection: Keep-Alive

    Front-End-Https: On

    ContentLength: 1073741824

    HeaderEnd: CRLF

 

In the frame details, you can see some interesting details. The first one is that the UserAgent header is MSRPC, which tells you that the request has been sent from a client that understands the Microsoft implementation of RPC over HTTP. Also note the Accept header, which is set to application/rpc, which is also a hint to the payload of the HTTP content. In addition to this, you can see that the ContentLength header has a value of 1 GB. The client will shut down the first session with an FIN_ACK message, which will cause the IIS server hosting the RPC proxy instance to respond to this with a 400 Bad Request:

+ Ethernet: Etype = Internet IP (IPv4)

+ Ipv4: Next Protocol = TCP, Packet ID = 45468, Total IP Length = 189

+ Tcp: Flags=F..PA..., SrcPort=HTTP(80), DstPort=13227, Len=149, Seq=2126557174 - 2126557323, Ack=1605674629, Win=64474 (scale factor 0) = 64474

- Http: Response, HTTP/1.1, Status Code = 400

    ProtocolVersion: HTTP/1.1

    StatusCode: 400, Bad request

    Reason: Bad Request

    ContentType: text/html

    Date: Fri, 01 May 2007 10:57:17 GMT

    Connection: close

    ContentLength: 20

    HeaderEnd: CRLF

  + payload:

 

In the ISA Server Web proxy log, you can then see an entry like the following:

0.0.0.0 MSRPC Yes FLORENCE denver.contoso.com TCP Internet - - - - - - 02.03.2007 10:57:59 0 42516 0 1251 0x8 Webproxyfilter 01.05.2007 11:57:59 Reverse proxy 10.1.1.1 10.1.1.5 80 https Failed Connection Attempt RPC over HTTPS int contoso\TestUser Internal RPC_IN_DATA http://mail.contoso.com/rpc/rpcproxy.dll?denver.contoso.com:6004 0xa03 64 Req ID: 1292293c; Compression: client=No, server=No, compress rate=0% decompress rate=0% ; FBA cookie: exists=no, valid=no, updated=yes, logged off=no, client type=unknown, user activity=yes

Note that in ISA Server logging, you will not see the 400 error code but instead the error code 64, because ISA Server translates this error code. The error code 64 means ERROR_NETNAME_DELETED, which actually makes sense in this context, because the session was closed from the IIS server, but the ISA Server computer expected more data to come.

Later, the client sends another request with a CL_ESTABLISH_IBP command (within a different TCP session). This session will then live as long as the Outlook client is sending data. Note that you need at least Network Monitor 3.0 to be able to parse the traffic so nicely; otherwise, you need to check the payload of the packets for the details:

 

  Frame:

+ Ethernet: Etype = Internet IP (IPv4)

+ Ipv4: Next Protocol = TCP, Packet ID = 54865, Total IP Length = 383

+ Tcp: Flags=...PA..., SrcPort=13229, DstPort=HTTP(80), Len=343, Seq=363886296 - 363886639, Ack=3986012674, Win=65535 (scale factor 0) = 0

- HTTP: Request, RPC_IN_DATA /rpc/rpcproxy.dll, CL_ESTABLISH_IBP

    Command: RPC_IN_DATA

  + URI: /rpc/rpcproxy.dll? denver.contoso.com:6001

    ProtocolVersion: HTTP/1.1

    Reverse-Via: FLORENCE

    Host: mail.contoso.com:443

    UserAgent: MSRPC

  + BasicAuthentication: Basic

    Accept: application/rpc

    Cache-Control: no-cache

    Pragma: no-cache

    Connection: Keep-Alive

    Front-End-Https: On

    ContentLength: 1073741824

    HeaderEnd: CRLF

 

In the frame, you can also see 1 GB again. This is used by Outlook to indicate that the connection can carry a lot of traffic. Some famous words here: No one will ever send more than 1 GB of data during the client session!

As mentioned before, the client will also initiate an RPC_OUT_DATA command with a subcommand CL_ESTABLISH_OBP to the Web server:

+ Ethernet: Etype = Internet IP (IPv4)

+ Ipv4: Next Protocol = TCP, Packet ID = 54794, Total IP Length = 376

+ Tcp: Flags=...PA..., SrcPort=13228, DstPort=HTTP(80), Len=336, Seq=143966104 - 143966440, Ack=788951920, Win=65535 (scale factor 0) = 0

- HTTP: Request, RPC_OUT_DATA /rpc/rpcproxy.dll, CL_ESTABLISH_OBP

    Command: RPC_OUT_DATA

  + URI: /rpc/rpcproxy.dll?denver.contoso.com:6002

    ProtocolVersion: HTTP/1.1

    Reverse-Via: FLORENCE

    Host: mail.contoso.com:443

    UserAgent: MSRPC

  + BasicAuthentication: Basic

    Accept: application/rpc

    Cache-Control: no-cache

    Pragma: no-cache

    Connection: Keep-Alive

    Front-End-Https: On

    ContentLength: 76

    HeaderEnd: CRLF

Here, the RPC proxy comes back with a 200 OK message:

+ Ethernet: Etype = Internet IP (IPv4)

+ Ipv4: Next Protocol = TCP, Packet ID = 45327, Total IP Length = 121

+ Tcp: Flags=...PA..., SrcPort=HTTP(80), DstPort=13228, Len=81, Seq=788951920 - 788952001, Ack=143966516, Win=65123 (scale factor 0) = 0

- HTTP: Response, HTTP/1.1, Status Code = 200, ECHO RESPONSE

    ProtocolVersion: HTTP/1.1

    StatusCode: 200, Ok

    Reason: Success

    ContentType: application/rpc

    ContentLength: 1073741824

    HeaderEnd: CRLF

To see what connections Outlook has opened to the ISA Server computer, you can hold down the CTRL key and right-click the Outlook icon in the notification area of the taskbar.

Connection Status

Now you should see a window like the following.

Connections dialog

Note the different sessions that Outlook has opened to the Exchange server. Every session is essentially a new TCP session, and you will see the previously mentioned error code in ISA Server logging. When issuing a netstat –an command, you can see the correlation between the TCP sessions and the open session that appears in the Outlook connection status window.

netstat

If the Outlook client is closed, you will also notice several 10054 error messages in ISA Server live logging or in the ISA Server Web proxy log. The reason for this is that the client is sending first a FIN_ACK frame to the Web server for the TCP connection that opened the RPC_IN_DATA request, which will cause the RPC proxy on the IIS server to respond with the usual 400 Bad Request message (as seen previously). This triggers a 64 error to be logged again in the ISA Server logs. After that, the client also sends a RESET over this TCP port message:

+ Ethernet: Etype = Internet IP (IPv4)

+ Ipv4: Next Protocol = TCP, Packet ID = 57122, Total IP Length = 40

+ Tcp: Flags=..R.A..., SrcPort=13230, DstPort=HTTP(80), Len=0, Seq=655234511, Ack=2116779508, Win=0 (scale factor 0) = 0

This causes the 10054 error message to be logged. The error code is a Winsock error code and is translated to WSAECONNRESET. For more details, see "Windows Sockets Error Codes" at the MSDN Web site.

You may also see error message 503 logged in ISA Server. In the network trace, it represents itself as the following:

+ Ethernet: Etype = Internet IP (IPv4)

+ Ipv4: Next Protocol = TCP, Packet ID = 45471, Total IP Length = 76

+ Tcp: Flags=...PA..., SrcPort=HTTP(80), DstPort=13228, Len=36, Seq=788952427 - 788952463, Ack=143966516, Win=65123 (scale factor 0) = 0

- HTTP: Response, HTTP/1.0, Status Code = 503

    ProtocolVersion: HTTP/1.0

    StatusCode: 503, Service unavailable

    Reason: RPC Error: c0021012

    HeaderEnd: CRLF

The error code c0021012 in the payload of the frame is an RPC error code and means RPC_P_CONNECTION_SHUTDOWN, which indicates an RPC connection shutdown, and is expected. Typically, you see this being sent from the IIS server to the ISA Server computer.

Summary

As you have seen in this blog entry, the error codes 64 and 10054 are normal for RPC over HTTP traffic when ISA Server is publishing Outlook Anywhere, and do not indicate an actual error condition. In addition, the 400 Bad Request log entries on the IIS server hosting the RPC proxy instance are also expected. When you troubleshoot RPC over HTTP issues, this knowledge can help you focus on other errors that might occur, which are the real problems.

For another excellent resource for troubleshooting RPC over HTTP issues, see "Troubleshooting RPC over HTTP Communications" at Microsoft TechNet.

Thomas Detzner

Escalation Engineer

Comments

  • Anonymous
    January 01, 2003
    News BizTalk Server NEW ESB Guidance Community The Microsoft ESB Guidance provides architectural guidance,

  • Anonymous
    January 01, 2003
    News BizTalk Server NEW ESB Guidance Community The Microsoft ESB Guidance provides architectural guidance,

  • Anonymous
    January 01, 2003
    Recommended Reading Before you delve into the following discussion, you will likely find the following

  • Anonymous
    January 01, 2003
    Thanks for the great information.  This site has many useful links and great server information.

  • Anonymous
    June 27, 2007
    Booo!! You used NETSTAT but could have used the way cooler FWENGMON!! FWENGMON gets no respect I tell ya... Great article Thomas - great technical depth. Very interesting that the 64 and 10054 messages can be expected in this scenario.

  • Anonymous
    July 02, 2007
    Thanks for the comment Clint! I used netstat on the client, the OS maybe a bit confusing since Outlook was running on a W2k3 Server in my example. I agree that fwengmon is a cool Tool on the ISA Server. Maybe time for a blog on this Tool :)