TIdHTTPProxyServer hangs when used with RemObjects

[Keesver 23]

Hello,

 

I'm using a TIdHTTPProxyServer component to create a proxy server for our application. Unfortunately the proxy server frequently blocks communication. As a test, I put a TIdHTTPProxyServer on a form and use this proxy i.c.m. with a call to a RemObjects server. I added an interceptor to log the output of the proxy component (see attachment). From this file I can see that the proxy server hangs on this call (see also attachment):

127.0.0.1:12719 Stat Connected.
127.0.0.1:12719 Recv 12/08/2022 15:59:26: POST http://service.a-dato.net:80/handler.ashx/binmessage HTTP/1.1
Host: service.a-dato.net
Keep-Alive: 300
Proxy-Connection: keep-alive
User-Agent: Remoting SDK
Content-Type: text/html
Content-Length: 17
Accept-Encoding: identity
Connection: keep-alive

}Ðm�BÐ�@�Fx8‘¯®V� (data is binary)

Comments:

• The first call to the server succeeds
• The problem comes on subsequent calls to the server (pressing 'Call service (8081)' multiple times)
• This problem only occurs when I use 'http' (using 'https' it works)
• It works when I use no proxy
• It works when I use another proxy (the second button will use Fiddler as a proxy server)
• When you run the test application, a logfile is written to 'c:\Temp\Log'

 

I have attached a test application to replicate the problem.

 

Thanks for your support and comments.

Kees

SimpleProxy.log

 

ProxyTestMain.zip

Edited August 12, 2022 by Keesver

[Remy Lebeau 1421]

Quote

I added an interceptor to log the output of the proxy component (see attachment). From this file I can see that the proxy server hangs on this call (see also attachment):

I don't understand what this log is supposed to be showing me.  Looks like every request received is responded to, and each connection is closed.  What am I missing?

Quote

Comments:

• The first call to the server succeeds
• The problem comes on subsequent calls to the server (pressing 'Call service (8081)' multiple times)

What is the actual problem, exactly?

Quote

• This problem only occurs when I use 'http' (using 'https' it works)

Using HTTPS through an HTTP proxy requires use of the CONNECT verb, which is just a straight passthough tunnel of raw data from the client to the target server and back. TIdHTTPProxyServer does not attempt to interpret the raw data in any way, all it is doing is managing the 2 TCP connections involved.

 

Whereas, using HTTP through an HTTP proxy requires sending HTTP requests to the proxy itself, and then the proxy makes its own HTTP requests to the target server.  So TIdHTTPProxyServer by default is fully reading and interpreting your client's requests and then replicating them to the target server.  So sure, there could certainly be some glitches in that process.  TIdHTTPProxyServer is not a full HTTP server or HTTP client, it is quite bare-bones, so it is not outside the realm of possibility that RemObjects is sending its HTTP requests in a way that TIdHTTPProxyServer can't handle correctly.  Or, because TIdHTTPProxyServer uses HTTP 1.0 when communicating with the target server, there could be differences between its use of HTTP 1.0 and the client's use of HTTP 1.1 that is causing interference.  Hard to say for sure.  I'm speculating, because I have no way to actually test/debug this at the moment.

 

Something else to consider - by default, TIdHTTPProxyServer.DefaultTransferMode is set to tmFullDocument, which means for GET/POST/HEAD requests, TIdHTTPProxyServer will read the client's entire request into memory before then passing it along to the target server, and then read the server's entire response into memory before then passing it along to the client.  This allows the user's application code to modify the request/response data if desired before passing it along.  Do you have the same problem if you set TIdHTTPProxyServer.DefaultTransferMode to tmStreaming instead?  That will cause TIdHTTPProxyServer to not buffer the request/response data in memory, it will be passed along as it is being received (at the cost that application code can't modify it anymore).

Edited August 12, 2022 by Remy Lebeau

[Keesver 23]

Hello Remy,

 

Thanks for taking to time to reply. The log shows that that every request receives a response, except the one highlighted. The log also shows that the first call to the server worked (that is calling LoginService.DomainCheck), trying to call the server a second time (re-using the same RemObjects channel) fails. I will do some more debugging to find out where it fails. Your clarifications are a good start starting points.

 

Greetings

[Keesver 23]

Hello again,

I have done some more testing and added extra logging to the proxy server:

    TIdTCPClient(LContext.FOutboundClient).Connect;
    try
      if Intercept <> nil then
        (Intercept as TIdServerInterceptLogBase).LogWriteString('Start call: ' + callno.ToString + #13#10);
      TransferData(LContext, LContext.Connection, LContext.FOutboundClient);

      Sleep(200);
      if Intercept <> nil then
        (Intercept as TIdServerInterceptLogBase).LogWriteString('Sent call: ' + callno.ToString + #13#10);

      LContext.Headers.Clear;
      LContext.FOutboundClient.IOHandler.Capture(LContext.Headers, '', False);
      LContext.FTransferMode := FDefTransferMode;
      LContext.FTransferSource := tsServer;
      DoHTTPResponse(LContext);

      if Intercept <> nil then
        (Intercept as TIdServerInterceptLogBase).LogWriteString('Reading call: ' + callno.ToString + #13#10);
      TransferData(LContext, LContext.FOutboundClient, LContext.Connection);
      if Intercept <> nil then
        (Intercept as TIdServerInterceptLogBase).LogWriteString('Done call: ' + callno.ToString + #13#10);
    finally
      LContext.FOutboundClient.Disconnect;
    end;

I have attached a logfile. In total 10 calls are made by the client. When the call succeeds, there is a message in the logfile saying 'Done: ' + call number. Calls 8 and 9 do not return a result, however call 10 does. Before a call is started there is a message indicating the connection is started (like 127.0.0.1:50376 Stat Connected.), however there are only 9 'Stat Connected' messages for 10 calls. Are connections re-used or does this indicate a problem with TIdHTTPProxyServer?

 

I also tried synchronizing the calls to the server by adding System.TMonitor.Enter(Self)/System.TMonitor.Exit(Self) at the start and end of method CommandPassThrough. This always causes a deadlock. I think this should work.

 

Questions:

• Is it logical that only 9 connections are started for 10 calls?
• How can I synchronize all calls to the server?

ProxyLog.txt

ProxyTest.zip

Edited August 16, 2022 by Keesver

[Keesver 23]

I enabled all exceptions in Delphi and learned that a 'Connection closed gracefully' is raised during the communication, once this exception is raised, the communication hangs. Could it be that TIdHTTPProxyServer is re-using a closed socket? I have attached another log file that seems to prove it does. This logs ends with:

Reading call: 10
0.0.0.0:0 Stat Disconnected.

To investigate, I logged the address of the IdContext used in each call (inside the logfile shown as 'Start call: 8 Port: 49877 Addr: 3928120'). This shows that the connection used in call 10 was previously used in call 8. Call 8 succeeded, while 10 fails.

 

I tried setting TIdHTTPProxyServe.ReuseSocket to 'rsFalse' but this does not make a difference.

 

Hope this helps someone to understand the issue...

ProxyLog.txt

[Remy Lebeau 1421]

8 hours ago, Keesver said:

I have attached a logfile. In total 10 calls are made by the client. When the call succeeds, there is a message in the logfile saying 'Done: ' + call number. Calls 8 and 9 do not return a result, however call 10 does. Before a call is started there is a message indicating the connection is started (like 127.0.0.1:50376 Stat Connected.), however there are only 9 'Stat Connected' messages for 10 calls.

It would be nice if the "Call started" and "Call completed" messages logged WHAT operation(s) were being started/completed.  And also, if every Call start/sent/reading message included the PeerPort that is processing the Call, to better differentiate between Calls that overlap in parallel.  The Call numbers alone are making it confusing which client is performing which action when Calls overlap.  Logging the PeerPort instead on everything should remove that ambiguity.

 

Is it possible/expected that any given "Call" in your client code produces multiple HTTP requests at a time?  Or, is it expected to be only 1 HTTP request per "Call"?

8 hours ago, Keesver said:

Are connections re-used or does this indicate a problem with TIdHTTPProxyServer?

Connections to the target server are not re-used.  There is 1 new connection per request forwarded.

 

The connection with a client stays open as log as the client wants.  There can be multiple requests per connection to the proxy.  And your client is requesting keep-alives with the proxy, though most connections are sending only 1 request per connection.  But Call 6 appears to share a TCP connection with an unknown Call number, and that 2nd call is difficult to determine what is actually happening on it.  It might have hung, or not, I can't tell yet.

8 hours ago, Keesver said:

I also tried synchronizing the calls to the server by adding System.TMonitor.Enter(Self)/System.TMonitor.Exit(Self) at the start and end of method CommandPassThrough. This always causes a deadlock. I think this should work.

I can't comment on that, since I don't see that in your code.

8 hours ago, Keesver said:

• Is it logical that only 9 connections are started for 10 calls?

Possibly, if the client uses HTTP keep-alives to reuse a connection for multiple HTTP requests.  As it does appear really happened for at least 2 Calls.  It is certainly possible that TIdHTTPProxyServer may not be handling that situation correctly, since it is not a fully functional HTTP server.  I might have to force "Connection: close" on every response until that can be verified/addressed.

8 hours ago, Keesver said:

• How can I synchronize all calls to the server?

Synchronize what, exactly?

3 hours ago, Keesver said:

I enabled all exceptions in Delphi and learned that a 'Connection closed gracefully' is raised during the communication, once this exception is raised, the communication hangs.

It should not be.  Provided you are not blocking the exception then all Indy servers should be handling it to close the socket and stop the thread.

3 hours ago, Keesver said:

Could it be that TIdHTTPProxyServer is re-using a closed socket?

No.

3 hours ago, Keesver said:

I have attached another log file that seems to prove it does.

To investigate, I logged the address of the IdContext used in each call (inside the logfile shown as 'Start call: 8 Port: 49877 Addr: 3928120'). This shows that the connection used in call 10 was previously used in call 8. Call 8 succeeded, while 10 fails.

I have not looked at the 2nd log yet, I will do so shortly.  The 1st log was not easy to follow.  But this does go back to my comment above that there possibly could be an issue with TIdHTTPProxyServer not correctly handling multiple requests on the same TCP connection through HTTP keep-alives.

3 hours ago, Keesver said:

I tried setting TIdHTTPProxyServe.ReuseSocket to 'rsFalse' but this does not make a difference.

That only applies to the listening Binding sockets, to reuse ports that were previously closed and then reopened in a short amount of time.

[Fr0sT.Brutal 900]

Isn't there an option to just force CONNECT method for all destinations? HTTP proxy is lazy for clients but awful for servers

[Keesver 23]

I do not know how that should work. Http requires that the remote server closes the connection to signal the call has completed. Forcing a CONNECT keeps the connection alive and breaks the flow between client and server. The client keeps waiting for the disconnect to happen, before completing a call to GET/POST.

[Keesver 23]

Remy, thanks for your comments again. I got it working now.

 

After adding extra logging I saw some strange behavior myself. RemObjects is sending 'keep-alive' messages and at some point the connection gets closed immediately after reading the POST request:

127.0.0.1:50782 Recv 8/17/2022 1:38:48 AM: POST http://service.a-dato.net:80/handler.ashx/binmessage HTTP/1.1
Host: service.a-dato.net
Keep-Alive: 300
Proxy-Connection: keep-alive
User-Agent: Remoting SDK
Content-Type: application/octet-stream
Content-Length: 17
Accept-Encoding: identity
Connection: keep-alive

R�R
ìF+F„�ò${n¼��
127.0.0.1:50782 Stat Disconnected.
Start call: 6 Port: 50782 Addr: 4437F28
Sent call: 6 Port: 50782 Addr: 4437F28

(See log file, line #190)
The log shows that port 50782 gets closed right after retrieving the POST request from the client, still CommandPassThrough is getting called which will then raise the 'Connection closed gracefully' exception. Doing some more testing, I found that the port gets closed here:

IdCommandHandlers.pas, line #507

	if LCommand.Disconnect then begin
        AContext.Connection.Disconnect;
      end;

I therefore updated TIdHTTPProxyServer.InitializeCommandHandlers and set Disconnect to False:

  LCommandHandler := CommandHandlers.Add;
  LCommandHandler.Command := 'POST';            {do not localize}
  LCommandHandler.OnCommand := CommandPassThrough;
  LCommandHandler.ParseParams := True;
  LCommandHandler.Disconnect := False; // <= Set to False

And....it works!!

 

Question:

• Should the command handler Disconnect?
• Are there any side effects to this change?

Full log file added again.

 

 

ProxyLog.txt

[Fr0sT.Brutal 900]

5 hours ago, Keesver said:

I do not know how that should work. Http requires that the remote server closes the connection to signal the call has completed. Forcing a CONNECT keeps the connection alive and breaks the flow between client and server. The client keeps waiting for the disconnect to happen, before completing a call to GET/POST.

Seems you misunderstood a bit, CONNECT is just a method of establishing connection via proxy. It also frequently referred to as HTTP tunnel. With this method proxy doesn't have to analyse HTTP headers, it just serves as pipe. Less actions => less bugs

[Remy Lebeau 1421]

9 hours ago, Fr0sT.Brutal said:

Isn't there an option to just force CONNECT method for all destinations? HTTP proxy is lazy for clients but awful for servers

No, there is not.  Handling CONNECT is very different than handling other HTTP verbs.  A CONNECT request just contains the target host/port to connect to, and then all data between client and target server is tunneled back and forth as-is.  But any other HTTP verb is a full HTTP request sent to the proxy itself, containing the full target URL, so the proxy will have to parse and forward the request as needed.  And HTTP proxies are allowed to modify a request and/or response as it wants (unless the client asks the proxy not to do that, but TIdHTTPProxyServer does not implement that feature at this time).

 

If you want a straight passthrough, look at TIdMappedPortTCP instead.  But to make that work as an HTTP proxy, you will have to parse the HTTP protocol manually in its OnConnect, OnExecute, and OnOutboundData events.

8 hours ago, Keesver said:

Http requires that the remote server closes the connection to signal the call has completed.

That is the default behavior for HTTP 0.9 and HTTP 1.0, but in HTTP 1.1 onward the default behavior is to keep the connection open instead, and the client has to explicitly ask the remote server to close the connection after sending a response.

 

Looking at TIdHTTPProxyServer again, I see it uses HTTP 1.0 when communicating with the remote server, so it closes the remote connection after each response, and it will also close the connection with the requesting client after each response too.  I'll have to update TIdHTTPProxyServer to support keep-alives.

8 hours ago, Keesver said:

Forcing a CONNECT keeps the connection alive and breaks the flow between client and server.

A CONNECT is a straight passthrough of raw data back and forth, the proxy does not process the data in any way.  That is not the case when handling other HTTP verbs.

8 hours ago, Keesver said:

The client keeps waiting for the disconnect to happen, before completing a call to GET/POST.

That is incorrect.  If the response has a 'Connection: keep-alive' (HTTP 0.9/1.0) header, or does not have a 'Connection: close' (HTTP 1.1+) header, the HTTP client is required by the HTTP specs to parse the response to discover when it actually ends, specifically because a disconnect WON'T occur at the end in that situation.

7 hours ago, Keesver said:

After adding extra logging I saw some strange behavior myself. RemObjects is sending 'keep-alive' messages and at some point the connection gets closed immediately after reading the POST request:

 

Makes sense, as TIdHTTPProxyServer does not support keep-alives at this time.  I'll have to update it to handle the 'Connection' and 'Proxy-Connection' headers better.

7 hours ago, Keesver said:

The log shows that port 50782 gets closed right after retrieving the POST request from the client, still CommandPassThrough is getting called which will then raise the 'Connection closed gracefully' exception.

It shouldn't even be getting that far, since the disconnect should happen before TIdHTTPProxyServer attempts to read the next request from the client.

7 hours ago, Keesver said:

Doing some more testing, I found that the port gets closed here:

Yes, because TIdCommandHandler.Disconnect is set to True in TIdHTTPProxyServer.InitializeCommandHandlers() for all proxy requests.

7 hours ago, Keesver said:

I therefore updated TIdHTTPProxyServer.InitializeCommandHandlers and set Disconnect to False:

 

And....it works!!

Good to know, thanks.

7 hours ago, Keesver said:

• Should the command handler Disconnect?

Currently, it does, because TIdHTTPProxyServer does not implement proper handling of HTTP keep-alives at this time.  Though, it doesn't really seem to be handling non-keepalives properly, either.  It should be passing around 'Connection: close' and 'Proxy-Connection: close' headers, at least until keep-alives can be implemented.

7 hours ago, Keesver said:

• Are there any side effects to this change?

Not that I can think of.  The proxy uses HTTP 1.0 to communicate with the remote server, so it already disconnects from the server after each response.  As long as the client wants to stay connected to the proxy, it could send subsequent requests to the proxy, and each one will be forwarded individually.

 

Though, I would not suggest setting Disconnect=False in TIdHTTPProxyServer.InitializeCommandHandlers().  I would leave it as True as a fallback, and then set TIdCommand.Disconnect=False inside of TIdHTTPProxyServer.CommandPassThrough() after reading the client's request headers, so that the keep-alive can be handled on a per-request basis.  I'll update TIdHTTPProxyServer to handle that.

2 hours ago, Fr0sT.Brutal said:

Seems you misunderstood a bit, CONNECT is just a method of establishing connection via proxy. It also frequently referred to as HTTP tunnel. With this method proxy doesn't have to analyse HTTP headers, it just serves as pipe. Less actions => less bugs

I know what CONNECT is.  And what you describe is how TIdHTTPProxyServer handles CONNECT right now.  But an HTTP client won't use CONNECT for HTTP verbs like HEAD/GET/POST unless they are used over HTTPS, since CONNECT is required to let the client negotiate SSL/TLS security directly with the remote server through an HTTP proxy.  Otherwise, the client would be negotiating SSL/TLS with the proxy instead, which would then subject the requests to MITM attacks.

[Remy Lebeau 1421]

I have checked in a new branch with some changes for TIdHTTPProxyServer:

 

https://github.com/IndySockets/Indy/tree/http-proxy-keepalive

 

Let me know if it works OK, and then I'll merge it in to the main code.

 

I also opened a ticket in Indy's repo:

 

https://github.com/IndySockets/Indy/issues/425

Edited August 17, 2022 by Remy Lebeau

[Keesver 23]

Yes, it works OK now.

 

Thanks for taking the time explaining the workings of Http and Indy. I have learned a lot over the past few days. I now have my reverse proxy working.

 

Greetings,

Kees

[Fr0sT.Brutal 900]

13 hours ago, Remy Lebeau said:

I know what CONNECT is

Sure you do! I was addressing Keesver.

[Remy Lebeau 1421]

9 hours ago, Fr0sT.Brutal said:

Sure you do! I was addressing Keesver.

You are right, my bad.  Didn't realize there was another person on this thread.

[Remy Lebeau 1421]

On 8/17/2022 at 11:38 AM, Remy Lebeau said:

I have checked in a new branch with some changes for TIdHTTPProxyServer:

 

https://github.com/IndySockets/Indy/tree/http-proxy-keepalive

 

Let me know if it works OK, and then I'll merge it in to the main code.

I have merged it now.