Page tree
Skip to end of metadata
Go to start of metadata

Title:

How to use a sniffer(WireShark) trace  to troubleshoot  Relay Server issues.

Purpose:

Provide the reader an understanding of how to use a sniffer trace to troubleshoot Relay Server issues.
This document will show how to troubleshoot a http 400 Bad Request error.
The concepts from this document can be used for other Relay Server problems, that require using a sniffer trace.

Overview:

Note: this Wiki assumes that the reader has some experience with reading and using network traces and tools.


This example uses the below URL from a browser to test the Relay Server and RSOE connection:

http://Web Server/ias_relay_server/client/rs_client.dll/SMP.QA/tm.  This test returned a 400 Bad Request.
The RS, IIS and RSOE configuration look 
OK and the RSOE connects to the RS just fine.  
The RSOE Log shows:

E. OEE1036: A network connection was closed by the Relay Server or an intermediary while the Outbound Enabler was reading from it
and the RS LOG shows:
E. <3496.732.F0B0Dn> <SMP.QA> RSE3004: Communication error [SYS10054: An existing connection was forcibly closed by the remote host...] occurred while reading from down channel of backend server 'RSOE BOX' in backend farm 'SMP.QA'

The next step is to use a network sniffer tool to see if there is a firewall or network issues causing this error.
See: How to use a browser to test RS-RSOE installation for SUP-SMP for more information on how to test the RS using a browser.

Solution:

To troubleshoot this issue further a network sniffer(Wireshark) trace was generated on the RS Box and the SMP/RSOE box.
As you can see from the client TCP/IP stream below the error was captured on the browser connection to the Relay Server:


943 2015-02-06 14:50:03.401651 xx.RSOE xx  xxx.RS.xxx.xx HTTP 363 GET /ias_relay_server/client/rs_client.dll/SMP.QA/tm HTTP/1.1 
957 2015-02-06 14:50:03.531130 xxx.RS.xxx.xx  xx.RSOE xxHTTP 58 HTTP/1.1 400 Bad request with no response from backend server (text/html)
Note: all of the IP addresses have been overwritten. 

However the above information is not completely helpful.  We need to look at the RSOE Up and Down channels in the sniffer trace to understand the 400 Bad Request.
See Explanation of Relay Server and Relay Server Outbound Enabler (RSOE) Up and Down Channels for more information on the RSOE channels.

Lets start by examining the Up channel to see if the /tm request made it to the RSOE/SMP backend.
If you look at the URL test you can see that after the rs_client.DLL you see a /RSOEFarmName/tm.
This is an IIS Web server.  The /RSOEFarmName is a parameter to the dll, and the dll knows
that anything after the farm name, in this case ("/tm"), is to be passed to the backend.
For this  example we need to  search the Wireshark trace for "/tm", which is  hex "2f746d" in the packet content, so we need to search in hex.

We do find that Packet 944, has the "Get /tm" :


0050 00 01 47 45 54 20 2f 74 6d 20 48 54 54 50 2f 31 ..GET /tm HTTP/1
0060 2e 31 0d 0a 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 .1..Connection:

If you continue to follow this stream (below),  you will see that the TM was sent to the Messaging port 5001 on the SMP server.
This is confirmed by the TCP/IP socket being closed normally.  Therefore we know that TM made it to SMP's port 5001( Messaging).

945 2015-02-06 14:50:03.428719 xxx.RS.xxx.xx xx.RSOE xx HTTP 1438 Continuation or non-HTTP traffic
946 2015-02-06 14:50:03.428719 xxx.RS.xxx.xx   xx.RSOE xx HTTP 145 Continuation or non-HTTP traffic
947 2015-02-06 14:50:03.429177  xx.RSOE xx xxx.RS.xxx.xx TCP 58 49285 > http [ACK] Seq=446 Ack=2096 Win=131072 Len=0
952 2015-02-06 14:50:03.517917 xxx.RS.xxx.xx  xx.RSOE xx TCP 58 http > 49285 [FIN, ACK] Seq=2096 Ack=446 Win=66048 Len=0
953 2015-02-06 14:50:03.518314 xx.RSOE xx xxx.RS.xxx.xx TCP 58 49285 > http [ACK] Seq=446 Ack=2097 Win=131072 Len=0
954 2015-02-06 14:50:03.518482  xx.RSOE xx xxx.RS.xxx.xx TCP 58 49285 > http [FIN, ACK] Seq=446 Ack=2097 Win=131072 Len=0
960 2015-02-06 14:50:03.541506 xxx.RS.xxx.xx  xx.RSOE xx TCP 58 http > 49285 [ACK] Seq=2097 Ack=447 Win=66048 Len=0

Next,  to confirm that this TCP/IP stream is  the up channel you will see an http Post and  the content will show  IAS_OE_UpChannel.
In this specific case we know that a /tm was passed.  We then searched for that in the content but you 
also can confirm that this TCP/IP stream is the Up Channel  by searching for  IAS_OE_UpChannel in the content:

  
866 2015-02-06 14:49:53.903075 xx.RSOE xx xxx.RS.xxx.xx  HTTP 503 POST /ias_relay_server/server/rs_server.dll HTTP/1.1 (application/octet-stream)POST /ias_relay_server/server/rs_server.dll HTTP/1.1
Host: xxxxxxxxx.xxxxxxx.com:80 
Connection: close 
User-Agent:
IAS_OE_UpChannel
Content-Type: application/octet-stream
Content-Length: 244

Since the data (/tm) made it to the back-end SMP server, we now need to see if the response is returned back up to the Relay Server.
Next we examine the RSOE Down Channel.  We know that this test will require a "tm://" response.

Again we can search for the "tm://" or  "IAS_OE_DnChannel" in the content.  As you see below we searched for the "tm".
Packet 948 shows that the "tm://" is being returned up to the RS, but if you follow the stream you can see that
packet 955 is showing that the RS side is resetting the connection. 

948 2015-02-06 14:50:03.492131 10.5.36.193 198.177.159.12 TCP 1438 [TCP segment of a reassembled PDU]
CONTENT:
0000 e0 2f 6d bb 6b 76 54 7f ee ed 7a 41 81 00 00 60 ./m.kvT...zA...`
0010 08 00 45 00 05 8c 0f 17 40 00 7f 06 52 d1 0a 05 ..E.....@...R...
0020 24 c1 c6 b1 9f 0c c0 86 00 50 31 c9 c0 e7 20 f2 $........P1... .
0030 0e 53 50 10 02 00 40 b9 00 00 33 01 03 e0 00 00 .SP...@...3.....
0040 00 00 00 00 00 00 00 00 21 00 e2 01 0d 18 00 3b ........!......;
0050 00 00 00 1a 01 48 54 54 50 2f 31 2e 31 20 32 30 .....HTTP/1.1 20
0060 30 20 53 75 63 63 65 73 73 0d 0a 45 78 70 69 72 0 Success..Expir
0070 65 73 3a 20 54 68 75 2c 20 30 31 20 4a 61 6e 20 es: Thu, 01 Jan
0080 31 39 37 30 20 30 30 3a 30 30 3a 30 30 20 47 4d 1970 00:00:00 GM
0090 54 0d 0a 53 65 74 2d 43 6f 6f 6b 69 65 3a 20 58 T..Set-Cookie: X
00a0 2d 53 55 50 2d 53 45 53 53 49 44 3d 31 66 75 68 -SUP-SESSID=1fuh
00b0 35 62 63 68 33 61 30 30 65 3b 50 61 74 68 3d 2f 5bch3a00e;Path=/
00c0 0d 0a 53 65 74 2d 43 6f 6f 6b 69 65 3a 20 58 2d ..Set-Cookie: X-
00d0 53 55 50 2d 44 4f 4d 41 49 4e 3d 64 65 66 61 75 SUP-DOMAIN=defau
00e0 6c 74 0d 0a 73 6f 75 72 63 65 75 72 69 3a 20 74 lt..sourceuri: t
00f0 6d 3a 2f 2f 0d 0a 53 65 74 2d 43 6f 6f 6b 69 65 m://..Set-Cookie
0100 3a 20 41 70 70 4e 6f 64 65 49 6e 66 6f 3d 6c 6f : AppNodeInfo=lo
0110 63 61 6c 68 6f 73 74 26 32 34 38 30 26 32 34 38 calhost&2480&248
0120 31 26 35 30 31 31 3b 50 61 74 68 3d 2f 0d 0a 54 1&5011;Path=/..T
0130 72 61 6e 73 66 65 72 2d 45 6e 63 6f 64 69 6e 67 ransfer-Encoding
0140 3a 20 63 68 75 6e 6b 65 64 0d 0a 0d 0a 31 43 0d : chunked....1C.
0150 0a 03 1b 11 00 00 15 00 01 00 01 00 00 00 06 74 ...............t
0160 6d 3a 2f 2f 00 06 74 6d 3a 2f 2f 00 00 0d 0a b2 m://..tm://.....

955 2015-02-06 14:50:03.529376 xxx.RS.xxx.xx xx.RSOE xx TCP 58 http > 49286 [RST, ACK] Seq=1 Ack=49361 Win=65792 Len=0

The Relay Server side is closing the connection.  The next step is to look at the sniffer trace running on the Relay Server Box.
There is no need to look at the UP channel since we saw that the  "GET /tm" was passed to the RSOE side.
We need to look at the Down channel using the  same string as before 'IAS_OE_DnChannel'.   Then when you find the packet, follow the stream.
In this specific case  when you follow the stream  you will see that the last packet 1234 shows a RST  that is coming from the RSOE:


1234 2015-02-10 10:39:47.696663 xx.RSOE xx  xxx.RS.xxx.xx TCP 60 49474 > http [RST, ACK] Seq=49365 Ack=1 Win=131072 Len=0

Both traces are showing us that the other side has reset the connections.  This means that something in the middle is closing the connections.

In this specific case the network had a load balancer and firewalls between the RS and RSOE. 
The issue  was in the CISCO network. CISCO signature 7212 packet inspection was delaying and timing out the packet.
Signature 7212 detects Set-Cookie: in HTTP Requests. This can potentially be an attack or test to see if the web application is vulnerable to "HTTP Response Splitting".

 

 

  • No labels