RPC over HTTP Logging Wildness
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.
On the ISA Server computer, you create a publishing rule using the Exchange Web Client Access Publishing Rule Wizard, like the following.
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.
 |
Now you should see a window like the following.
|
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.
|
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