Exception attempting to use Http Tunneling

RCF support and general discussion.
gentzel
Posts: 9
Joined: Thu May 25, 2017 8:58 pm

Exception attempting to use Http Tunneling

Post by gentzel »

I'm attempting to modify an existing application of ours which has used RCF for years to add HTTP tunneling support. I'm presently getting the following exception:

Code: Select all

[159: HTTP tunnel error. HTTP session index mismatch on request. Expected index: 10 . Actual index: 12 .][0: No sub system.][0: ][What: ][Context: c:\jenkins\dailybuild\workspace\amcc\download.unpacked\rcf\src\rcf\HttpFrameFilter.cpp:468]
There have been minimal changes from the original, non-tunneling code, mainly substituting HttpEndpoint for TcpEndpoint.

This is using the latest RCF release (2.2.0.0). Can you give me any advice on where to start looking?

Thanks.

jarl
Posts: 238
Joined: Mon Oct 03, 2011 4:53 am
Contact:

Re: Exception attempting to use Http Tunneling

Post by jarl »

Hi,

Are there any forward or reverse HTTP proxies between the client and the server? If so you should try connecting a client directly to a server and see if that makes any difference.

Are you able to run up Fiddler and inspect the HTTP traffic between the client and server? In each HTTP request there will he a header "X-RCFSessionIndex" which should contain a number that increases by 1 for each round trip. Somehow in your situation this number has gotten out of sync.

To get the HTTP traffic to go through Fiddler you'll need to configure the client to use Fiddler as a proxy e.g.

Code: Select all

client.getClientStub().setHttpProxy("127.0.0.1");
client.getClientStub().setHttpProxyPort(8888);
Kind Regards

Jarl Lindrud
Delta V Software
http://www.deltavsoft.com

gentzel
Posts: 9
Joined: Thu May 25, 2017 8:58 pm

Re: Exception attempting to use Http Tunneling

Post by gentzel »

Thanks for the reply, Jarl.

Ultimately there will be an optional, configurable proxy between client & server (as well as choosing HTTP vs. HTTPS), but for this initial testing I'm limiting things to no proxy and HTTP only to get the simplest case working before adding complexity.

I'll let you know what I see in the HTTP request headers.

gentzel
Posts: 9
Joined: Thu May 25, 2017 8:58 pm

Re: Exception attempting to use Http Tunneling

Post by gentzel »

I'm still investigating, but the first suspicious thing I see is simultaneous outstanding requests with an out-of-order response. It's after this that I get the exception.
  • Request(1)
  • Response(1)
  • Request(2)
  • Response(2)
  • Request(3)
  • Response(3)
  • Request(4)
  • Response(4)
  • Request(5)
  • Response(5)
  • Request(6)
  • Response(6)
  • Request(7)
  • Response(7)
  • Request(8)
  • Response(8)
  • Request(9)
  • Request(10)
  • Request(11)
  • Response(11)
  • Request(12)
At this point I get "HTTP tunnel error. HTTP session index mismatch on request. Expected index: 10 . Actual index: 12 ."

gentzel
Posts: 9
Joined: Thu May 25, 2017 8:58 pm

Re: Exception attempting to use Http Tunneling

Post by gentzel »

More data.

It appears that a single remote call is getting split into three distinct writes, each of which gets an index. The final index is what is included in the response. The next remote call then fails with an index mismatch:

Code: Select all

19:31:53.607 - RCF/include/RCF/Future.hpp(245): [Thread: 13468][Time: 2948] RcfClient - begin remote call. I_CDEngine::reserveEngine(). Fnid: 1. Type: R7
19:31:53.607 - rcf/src/rcf/Future.cpp(105): [Thread: 13468][Time: 2948] RcfClient - sending synchronous request. [Args: mpClientStub=167BA288, mpClientStub->mRequest=(r.mToken = ( id = 0 ))(r.mSubInterface = I_CDEngine)(r.mFnId = 1)(r.mSerializationProtocol = 1)(r.mMarshalingProtocol = 1)(r.mOneway = 0)(r.mClose = 0)(r.mService = I_CDEngine)(r.mRuntimeVersion = 12)(r.mPingBackIntervalMs = 0)(r.mArchiveVersion = 0), ]
19:31:53.607 - rcf/src/rcf/ConnectedClientTransport.cpp(362): [Thread: 13468][Time: 2948] ConnectionOrientedClientTransport - initiating timed send operation. [Args: lengthByteBuffers(data)=620, totalTimeoutMs=10000, ]
19:31:53.607 - rcf/src/rcf/ConnectedClientTransport.cpp(619): [Thread: 13468][Time: 2948] ConnectionOrientedClientTransport - initiating write. [Args: lengthByteBuffers(byteBuffers)=620, ]
19:31:53.607 - rcf/src/rcf/HttpFrameFilter.cpp(786): [Thread: 13468][Time: 2948] Sending HTTP message. [Args: this=167BB3A0, frameLen=482, "\n" + httpMessageHeader=
POST / HTTP/1.1
Host: 192.168.119.35:9999
Accept: */*
Connection: Keep-Alive
X-RCFSessionId: cf554273-4d19-4fa6-941c-9a11099a05dc
X-RCFSessionIndex: 9
Content-Length: 302

, ]
19:31:53.607 - rcf/src/rcf/BsdClientTransport.cpp(320): [Thread: 13468][Time: 2948] BsdClientTransport - initiating send on socket. [Args: lengthByteBuffers(byteBuffers)=482, ]
19:31:53.607 - rcf/src/rcf/ConnectedClientTransport.cpp(619): [Thread: 13468][Time: 2948] ConnectionOrientedClientTransport - initiating write. [Args: lengthByteBuffers(byteBuffers)=347, ]
19:31:53.607 - rcf/src/rcf/HttpFrameFilter.cpp(786): [Thread: 13468][Time: 2948] Sending HTTP message. [Args: this=167BB3A0, frameLen=467, "\n" + httpMessageHeader=
POST / HTTP/1.1
Host: 192.168.119.35:9999
Accept: */*
Connection: Keep-Alive
X-RCFSessionId: cf554273-4d19-4fa6-941c-9a11099a05dc
X-RCFSessionIndex: 10
Content-Length: 286

, ]
19:31:53.607 - rcf/src/rcf/BsdClientTransport.cpp(320): [Thread: 13468][Time: 2948] BsdClientTransport - initiating send on socket. [Args: lengthByteBuffers(byteBuffers)=467, ]
19:31:53.607 - rcf/src/rcf/ConnectedClientTransport.cpp(619): [Thread: 13468][Time: 2948] ConnectionOrientedClientTransport - initiating write. [Args: lengthByteBuffers(byteBuffers)=90, ]
19:31:53.607 - rcf/src/rcf/HttpFrameFilter.cpp(786): [Thread: 13468][Time: 2948] Sending HTTP message. [Args: this=167BB3A0, frameLen=300, "\n" + httpMessageHeader=
POST / HTTP/1.1
Host: 192.168.119.35:9999
Accept: */*
Connection: Keep-Alive
X-RCFSessionId: cf554273-4d19-4fa6-941c-9a11099a05dc
X-RCFSessionIndex: 11
Content-Length: 119

, ]
19:31:53.607 - rcf/src/rcf/BsdClientTransport.cpp(320): [Thread: 13468][Time: 2948] BsdClientTransport - initiating send on socket. [Args: lengthByteBuffers(byteBuffers)=300, ]
19:31:53.607 - rcf/src/rcf/ConnectedClientTransport.cpp(610): [Thread: 13468][Time: 2948] ConnectionOrientedClientTransport - initiating read. [Args: bytesToRead=4, ]
19:31:53.607 - rcf/src/rcf/BsdClientTransport.cpp(208): [Thread: 13468][Time: 2948] BsdClientTransport - initiating read from socket. [Args: byteBuffer.getLength()=1024, bytesToRead=1024, ]
19:31:53.744 - rcf/src/rcf/HttpFrameFilter.cpp(424): [Thread: 13468][Time: 3089] Received HTTP message [Args: this=167BB3A0, mHttpMessage.mFrameLen=0, "\n" + mHttpMessage.mHttpMessageHeader=
HTTP/1.1 200 OK
X-RCFSessionId: cf554273-4d19-4fa6-941c-9a11099a05dc
X-RCFSessionIndex: 11
Content-Length: 108
Connection: Keep-Alive

, ]
19:31:53.744 - rcf/src/rcf/ConnectedClientTransport.cpp(610): [Thread: 13468][Time: 3089] ConnectionOrientedClientTransport - initiating read. [Args: bytesToRead=75, ]
19:31:53.744 - rcf/src/rcf/Marshal.cpp(593): [Thread: 13468][Time: 3089] RcfClient - received response. [Args: this=167BA288, response=(r.mException = 0)(r.mError = 0), ]
19:31:53.744 - RCF/include/RCF/Future.hpp(252): [Thread: 13468][Time: 3089] RcfClient - end remote call. I_CDEngine::reserveEngine(). Fnid: 1. Type: R7
19:31:53.744 - RCF/include/RCF/Future.hpp(245): [Thread: 13468][Time: 3089] RcfClient - begin remote call. I_CDEngine::addRAL(). Fnid: 19. Type: V4
19:31:53.745 - rcf/src/rcf/Future.cpp(105): [Thread: 13468][Time: 3089] RcfClient - sending synchronous request. [Args: mpClientStub=167BA288, mpClientStub->mRequest=(r.mToken = ( id = 0 ))(r.mSubInterface = I_CDEngine)(r.mFnId = 19)(r.mSerializationProtocol = 1)(r.mMarshalingProtocol = 1)(r.mOneway = 0)(r.mClose = 0)(r.mService = I_CDEngine)(r.mRuntimeVersion = 12)(r.mPingBackIntervalMs = 0)(r.mArchiveVersion = 0), ]
19:31:53.745 - rcf/src/rcf/ConnectedClientTransport.cpp(362): [Thread: 13468][Time: 3089] ConnectionOrientedClientTransport - initiating timed send operation. [Args: lengthByteBuffers(data)=212, totalTimeoutMs=10000, ]
19:31:53.745 - rcf/src/rcf/ConnectedClientTransport.cpp(619): [Thread: 13468][Time: 3089] ConnectionOrientedClientTransport - initiating write. [Args: lengthByteBuffers(byteBuffers)=212, ]
19:31:53.745 - rcf/src/rcf/HttpFrameFilter.cpp(786): [Thread: 13468][Time: 3089] Sending HTTP message. [Args: this=167BB3A0, frameLen=422, "\n" + httpMessageHeader=
POST / HTTP/1.1
Host: 192.168.119.35:9999
Accept: */*
Connection: Keep-Alive
X-RCFSessionId: cf554273-4d19-4fa6-941c-9a11099a05dc
X-RCFSessionIndex: 12
Content-Length: 241

, ]
19:31:53.745 - rcf/src/rcf/BsdClientTransport.cpp(320): [Thread: 13468][Time: 3089] BsdClientTransport - initiating send on socket. [Args: lengthByteBuffers(byteBuffers)=422, ]
19:31:53.745 - rcf/src/rcf/ConnectedClientTransport.cpp(610): [Thread: 13468][Time: 3089] ConnectionOrientedClientTransport - initiating read. [Args: bytesToRead=4, ]
19:31:53.745 - rcf/src/rcf/BsdClientTransport.cpp(208): [Thread: 13468][Time: 3089] BsdClientTransport - initiating read from socket. [Args: byteBuffer.getLength()=1024, bytesToRead=1024, ]
19:31:53.745 - rcf/src/rcf/HttpFrameFilter.cpp(424): [Thread: 13468][Time: 3089] Received HTTP message [Args: this=167BB3A0, mHttpMessage.mFrameLen=0, "\n" + mHttpMessage.mHttpMessageHeader=
HTTP/1.1 400 Bad Request
X-RCFError: HTTP session index mismatch on request. Expected index: 10 . Actual index: 12 .
Content-Length: 0

, ]
19:31:53.745 - rcf/src/rcf/HttpFrameFilter.cpp(468): [Thread: 13468][Time: 3089] RCF exception thrown. Error message: HTTP tunnel error. HTTP session index mismatch on request. Expected index: 10 . Actual index: 12 .
19:31:53.745 - rcf/src/rcf/ClientStub.cpp(447): [Thread: 13468][Time: 3089] RcfClient - disconnecting from server. [Args: this=167BA288, endpoint=http://192.168.119.35:9999, ]
19:31:53.745 - rcf/src/rcf/ClientStub.cpp(447): [Thread: 13468][Time: 3089] RcfClient - disconnecting from server. [Args: this=167BA288, endpoint=http://192.168.119.35:9999, ]
19:31:53.746 - RCF/include/RCF/Future.hpp(252): [Thread: 13468][Time: 3089] RcfClient - end remote call. I_CDEngine::addRAL(). Fnid: 19. Type: V4

jarl
Posts: 238
Joined: Mon Oct 03, 2011 4:53 am
Contact:

Re: Exception attempting to use Http Tunneling

Post by jarl »

Do you have any compression or encryption configured on the client connection? That could possibly be triggering the extra writes.

It would be very useful to see a call stack, at the point where the extra write is happening. Are you able to put a breakpoint in HttpFrameFilter::write() , in src\RCF\HttpFrameFilter.cpp , then debug the client and break on the first extra write, i.e. when the request ID is 10. That will give me some more info on what is causing the issue, and we should be able to resolve it from there.

Alternatively, if you can reproduce this bug in a simple program and send it to me, that would be even better.
Kind Regards

Jarl Lindrud
Delta V Software
http://www.deltavsoft.com

gentzel
Posts: 9
Joined: Thu May 25, 2017 8:58 pm

Re: Exception attempting to use Http Tunneling

Post by gentzel »

We are indeed using an OpenSSL encryption filter on the client connection.

I'll work on getting a standalone test app to send you.

gentzel
Posts: 9
Joined: Thu May 25, 2017 8:58 pm

Re: Exception attempting to use Http Tunneling

Post by gentzel »

I have confirmed that disabling the encryption filter avoids the problem. Not a viable option for production, but a very useful observation for debugging.

jarl
Posts: 238
Joined: Mon Oct 03, 2011 4:53 am
Contact:

Re: Exception attempting to use Http Tunneling

Post by jarl »

OK, that's good to know.

You can also try using RCF::HttpsEndpoint instead of RCF::HttpEndpoint, and see if that makes any difference.
Kind Regards

Jarl Lindrud
Delta V Software
http://www.deltavsoft.com

gentzel
Posts: 9
Joined: Thu May 25, 2017 8:58 pm

Re: Exception attempting to use Http Tunneling

Post by gentzel »

Unfortunately I get the same error with HttpsEndpoint.

Thus far I've been unable to reproduce this in a test application. Still working on that...

Post Reply