TIDHTTPServer not receiving POST

[pssDP 0]

Using Delphi XE7 vith Indy version 10.6.1

After the last modification for adding a new functionañity to my TiDHTTPServer web service, I have a strange issue.

From an external web service, I need to receive json POST and GET notification messages

GET notifications are received correctly, but POST notifications does not arrive to CommandGet or CommandOther.

At the beginnig of those functions I have the following code to know if those notifications really arrive:

    sTx := 'CommandGet Request from ' + ARequestInfo.RemoteIP  + ': ' + ARequestInfo.Command + ': ' + ARequestInfo.Document;

After installing TIdLogFile to monitor traffic, I can get the log for the incoming POST notifications, but nothing arrives to CommandGet o CommandOther-

This is the related log:

 

128.129.130.131:2211 Stat Connected.
128.129.130.131:2211 Recv 11/05/2021 16:59:01: POST /dpnotify HTTP/1.1<EOL>Host: agenda.sxxxxxx.com<EOL>User-Agent: xxxxxxxxxxxxxxxx curl/7.66.0 PHP/7.4.6<EOL>Content-Type: application/json<EOL>Accept: application/json<EOL>Authorization: ApiKey xxxxxxxxxxxxxxxxxxxxxxxxxxxx<EOL>>Content-Length: 1523<EOL><EOL>{"name":"address","data":.............
128.129.130.131:2211 Stat Disconnected.
0.0.0.0:0 Stat Disconnected.

 

How can I solve where is the problem.

[Remy Lebeau 1421]

Clearly the server IS receiving the POST request, you can see it in your log file.  But if the OnCommand... events are not being called, it usually means the request is incomplete, ie if TIdHTTPServer is waiting for more data that is not received.  Note the log also shows the TCP connection being disconnected at the same time the request is received.  So, the client is likely dropping the connection on its end before sending the full 1523 bytes that it claimed to be sending.

 

BTW, 10.6.1 is not the latest version of Indy, the current version is 10.6.2.

Edited May 11, 2021 by Remy Lebeau

[pssDP 0]

Thanks for your response.

I see that in the log file there are the entire 1523 bytes of the json response, but here I abbreviated it with dots.

In the connection and disconnection lines of the log there is not the date and time, so I can not check if all succeds at the same second or later.

So in my humble opinion, the disconnection is correct.

 

 

[Remy Lebeau 1421]

2 hours ago, pssDP said:

I see that in the log file there are the entire 1523 bytes of the json response

Then there is no reason why TIdHTTPServer should not be calling the events.  So, you are just going to have to debug into the server's code to find out where it is hanging.  Are the OnHeadersAvailable, OnCreatePostStream, OnParseAuthentication, and OnCreateSession events being called?

 

In the log you showed, there is an extra > before the Content-Length header.  Is that really present in the request, or is that just a typo when posting the log here?

2 hours ago, pssDP said:

In the connection and disconnection lines of the log there is not the date and time

Then I strongly suggest you add them.

[pssDP 0]

With respect to the extra ">" this was a typo reducing the log.

I added date and time to de log

So, I logged the events, and this is what I get in this same order

 

12/05/2021 17:52:01 HeadersAvailable: "Host: agenda.xxxxxxxxxxx.com","User-Agent: xxxxxxxxxxx curl/7.66.0 PHP/7.4.6","Content-Type: application/json","Accept: application/json","Authorization: ApiKey xxxxxxxxxxxxxxxxxxxxx", "xxxxxxxxxxxxxxxxxxxx","Content-Length: 1576"

 

12/05/2021 17:52:01 CreatePostStream: "Host: agenda.xxxxxx.com","User-Agent: xxxxxxx curl/7.66.0 PHP/7.4.6","Content-Type: application/json","Accept: application/json","Authorization: ApiKey xxxxxxxxxxxxxxxxxxxxxxxxx","xxxxxxxxxxxxx","Content-Length: 1576"

 

12/05/2021 17:52:01 ParseAuthentication: Type: ApiKey, Data: xxxxxxxxxxxxxxxxxxx

 

12/05/2021 17:52:29 HeadersAvailable: "Host: agenda.xxxxxxxxxxxxxx.com","User-Agent: xxxxxxx curl/7.66.0 PHP/7.4.6","xxxxxxxxxxxxxxxx"

 

In all implied events there is only a line of code to write to the log file without any other code.

In ParseAuthentication, besides logging i added the following code to try to avoid the login process by the  moment, but I think that is the reason that the OnCreateSession and subsequent CommandGet are not triggered:

 

  vUserName := 'SHERLOCK';
  VPassword := 'HOLMES';
  VHandled := True;

 

[Remy Lebeau 1421]

25 minutes ago, pssDP said:

I added date and time to de log

So, I logged the events, and this is what I get in this same order

This time, you have an extra "xxxxxxxxxxxxxxxxxxxx" between the Authorization and Content-Length headers.

 

In that log, I see a 28-second gap between OnParseAuthentication and OnHeadersAvailable events.  Those would have to be for separate requests, but are they on the same TCP connection (HTTP keep-alive)?  You should not be able to get a new OnHeadersAvailable event without a preceding OnCommand... event if they are the same TCP connection.

25 minutes ago, pssDP said:

In all implied events there is only a line of code to write to the log file without any other code.

It would still be useful to see your ACTUAL code.

25 minutes ago, pssDP said:

In ParseAuthentication, besides logging i added the following code to try to avoid the login process by the  moment, but I think that is the reason that the OnCreateSession and subsequent CommandGet are not triggered:

That would not make sense for OnCommand..., unless your code is trying to validate the credentials and terminate the TCP connection before the OnCommand... event is called.  The OnParseAuthentication event should only be used for PARSING credentials out of the request headers, not for VALIDATING the credentials.  Any validation should only be done in the OnCommand... events.

 

For the OnCreateSession event, do you have TIdHTTPServer.SessionState set to True or False?  It is set to False by default.

 

The only thing that TIdHTTPServer does in between calling the OnParseAuthentication and OnCommand..., events, but only if SessionState=True, is to extract session cookies from the request, compare them to the contents of TIdHTTPServer.SessionList calling the OnInvalidSession event for any cookies that are not in the list, and then calling the OnCreateSession event if a new session needs to be made.  So, if SessionState=False, there is no possible way that OnCommand... would not be called after OnParseAuthentication exits.  But if SessionState=True, the only way OnCommand... would not be called is if cookie/session handling is hanging/crashing.

[pssDP 0]

With respect the extra "xxxx" those are header params app related, not for the session control:

12/05/2021 17:52:01 HeadersAvailable: "Host: agenda.xxxxxx.com","User-Agent: xxxxxx curl/7.66.0 PHP/7.4.6","Content-Type: application/json","Accept: application/json","Authorization: ApiKey RGxxxxxxxpYxxxxxxxg0U04k","X-Nexxx-ID: VQIDxxxxxVGwIBxxxxxxCUw==","X-Nexxx-Transaction: PxRTWFxxxxxxVlkABgJTBQYxxxxxxxVU4aBgEJAgMxxxxxxdUBENKQQsFxxxxxxxs=","Content-Length: 1576"

 

All logs presented here are from the same tcp connection. And I do not use KeepAlive := True anywhere, so i think that in this case it is False by default.
Now I deleted the previous code in ParseAuthentication according to your comments.
With respect to the 28 seconds later HeadersAvalable log line it is because I receive a GET ping messages every 10 minutes, to check if my server is alive, and in the captured log happenned in the middle. I receive the OnCommand... events for those GETs, and I simply respond with:

AResponseInfo.ResponseNo := 200;

Referring SessionState, I have the following code in the initialization process:

     HTTPServer.AutoStartSession := True;    
     HTTPServer.SessionState := True;
     HTTPServer.Active := True;
     Started := True;

According to your comments, I added a log line for InvalidSession to check for this event too:

 

Here is the code used in all implied events:

procedure TAmWebAgeSvc.HTTPServerCreateSession(ASender: TIdContext; var VHTTPSession: TIdHTTPSession);
begin
  WriteDbgLog('CreateSession: ' + VHTTPSession.Content.CommaText);
end;

procedure TAmWebAgeSvc.HTTPServerHeadersAvailable(AContext: TIdContext; const AUri: string; AHeaders: TIdHeaderList; var VContinueProcessing: Boolean);
begin
  WriteDbgLog('HeadersAvailable: ' + AHeaders.CommaText);
end;


procedure TAmWebAgeSvc.HTTPServerCreatePostStream(AContext: TIdContext; AHeaders: TIdHeaderList; var VPostStream: TStream);
begin
  WriteDbgLog('CreatePostStream: ' + AHeaders.CommaText);
end;


procedure TAmWebAgeSvc.HTTPServerParseAuthentication(AContext: TIdContext; const AAuthType, AAuthData: string; var VUsername, VPassword: string; var VHandled: Boolean);
begin
  WriteDbgLog('ParseAuthentication: Type: ' + AAuthType + ', Data: ' + AAuthData);
end;

procedure TAmWebAgeSvc.HTTPServerInvalidSession(AContext: TIdContext; ARequestInfo: TIdHTTPRequestInfo; AResponseInfo: TIdHTTPResponseInfo; var VContinueProcessing: Boolean; const AInvalidSessionID: string);
begin
 WriteDbgLog('InvalidSession: ' + AInvalidSessionID);
end;

Procedure WriteDbgLog(sMsg: String);
var
  sTx: AnsiString;
  sFle: String;
  tsDebugLog: TFileStream;
  fs: TFormatSettings;

begin
  Try
    Try
      sFle := gCfg.sLanDir + '\DBGWEBAG.TXT';
      if FileExists(sFle) = False then
      begin
        // El fichero no existe
        tsDebugLog := TFileStream.Create(sFle, fmCreate or fmShareDenyNone);
        tsDebugLog.Seek(0, soFromEnd);
      end
      else
      begin
        // El fichero ya existe
        tsDebugLog := TFileStream.Create(sFle, fmOpenReadWrite or fmShareDenyNone);
        tsDebugLog.Seek(0, soFromEnd);
      end;

      // Grabar el texto al fichero
      fs := TFormatSettings.Create;
      sTx := AnsiString(DateTimeToStr(Now, fs) + ' ' + sMsg + #13#10);
      tsDebugLog.Write(sTx[1], Length(sTx));

    Except
      on E: Exception do
    end;

  Finally
    // Cerrar
    FreeAndNil(tsDebugLog);
  End;
end;

 

[Remy Lebeau 1421]

2 hours ago, pssDP said:

All logs presented here are from the same tcp connection.

Then, the ONLY possible way that the OnCommand... event would not be called in between the OnParseAuthentication event and a subsequent OnHeadersAvailable event, as your earlier log suggested, is if TIdHTTPServer.SessionState is true and an OnInvalidSession event handler sets its VContinueProcessing parameter to False.  Otherwise, what you describe is physically impossible given the following code from TIdCustomHTTPServer.DoExecute():

if not HeadersCanContinue then begin // <-- OnHeadersAvailable called here
  Break;
end;
...
if not PreparePostStream then begin // <-- OnCreatePostStream called here
  Break;
end;
...
ReadCookiesFromRequestHeader;
...
s := LRequestInfo.RawHeaders.Values['Authorization'];    {Do not Localize}
if Length(s) > 0 then begin
  LAuthType := Fetch(s, ' ');
  LRequestInfo.FAuthExists := DoParseAuthentication(AContext, LAuthType, s, LRequestInfo.FAuthUsername, LRequestInfo.FAuthPassword); // <-- OnParseAuthentication called here
  if not LRequestInfo.FAuthExists then begin
    raise EIdHTTPUnsupportedAuthorisationScheme.Create(
      RSHTTPUnsupportedAuthorisationScheme);
  end;
end;

// Session management
GetSessionFromCookie(AContext, LRequestInfo, LResponseInfo, LContinueProcessing); // <-- OnCreateSession and OnInvalidSession called here
if LContinueProcessing then begin
  // These essentially all "retrieve" so they are all "Get"s
  if LRequestInfo.CommandType in [hcGET, hcPOST, hcHEAD] then begin
    DoCommandGet(AContext, LRequestInfo, LResponseInfo); // <-- OnCommandGet called here
  end else begin
    DoCommandOther(AContext, LRequestInfo, LResponseInfo); // <-- OnCommandOther called here
  end;
end;

As you can see, the calls to DoCommand...() are skipped ONLY if GetSessionFromCookie() sets LContinueProcessing to False:

function TIdCustomHTTPServer.GetSessionFromCookie(AContext: TIdContext;
  AHTTPRequest: TIdHTTPRequestInfo; AHTTPResponse: TIdHTTPResponseInfo;
  var VContinueProcessing: Boolean): TIdHTTPSession;
var
  LIndex: Integer;
  LSessionID: String;
  // under ARC, convert a weak reference to a strong reference before working with it
  LSessionList: TIdHTTPCustomSessionList;
begin
  Result := nil;
  VContinueProcessing := True; // <--
  if SessionState then
  begin
    LSessionList := FSessionList;
    LIndex := AHTTPRequest.Cookies.GetCookieIndex(SessionIDCookieName);
    while LIndex >= 0 do
    begin
      LSessionID := AHTTPRequest.Cookies[LIndex].Value;
      if Assigned(LSessionList) then begin
        Result := LSessionList.GetSession(LSessionID, AHTTPRequest.RemoteIP);
        if Assigned(Result) then begin
          Break;
        end;
      end;
      DoInvalidSession(AContext, AHTTPRequest, AHTTPResponse, VContinueProcessing, LSessionID); // <-- OnInvalidSession called here
      if not VContinueProcessing then begin
        Break;
      end;
      LIndex := AHTTPRequest.Cookies.GetCookieIndex(SessionIDCookieName, LIndex+1);
    end;    { while }
    // check if a session was returned. If not and if AutoStartSession is set to
    // true, Create a new session
    if (Result = nil) and VContinueProcessing and FAutoStartSession then begin
      Result := CreateSession(AContext, AHTTPResponse, AHTTPrequest);
    end;
  end;
  AHTTPRequest.FSession := Result;
  AHTTPResponse.FSession := Result;
end;

Quote

And I do not use KeepAlive := True anywhere, so i think that in this case it is False by default.

 

There there is no possible way you can be receiving multiple HTTP requests on the same TCP connection, as TIdHTTPServer will close the current TCP connection after sending a response, Even if the client requests a keep-alive via the 'Connection' header, it will be ignored when TIdHTTPServer.KeepAlive is False.

Edited May 13, 2021 by Remy Lebeau

[pssDP 0]

To go further, I have added log lines in several places of IdCustomHTTPServer module, and changed the writing of the log with that of IdServerInterceptLogFile, as follows:

Procedure GNDebugScan(sMsg: String);
var
  FFileStream: TFileStream;

begin
  FFileStream := TIdAppendFileStream.Create('C:\TMP\DBGLOG.TXT');
  WriteStringToStream(FFileStream, sMsg);
  FreeAndNil(FFileStream);
end;

Some top most place is here:

  function HeadersCanContinue: Boolean;
  var
    LResponseNo: Integer;
    LResponseText, LContentText, S: String;
  begin
GNDebugScan('DoExecute inicio HeadersCanContinue');

    // let the user decide if the request headers are acceptable
    Result := DoHeadersAvailable(AContext, LRequestInfo.URI, LRequestInfo.RawHeaders);

And also here:

  function PreparePostStream: Boolean;
  var
    I, Size: Integer;
    S: String;
    LIOHandler: TIdIOHandler;
  begin
    Result := False;
    LIOHandler := AContext.Connection.IOHandler;

GNDebugScan('DoExecute inicio PreparePostStream:' + BoolToStr(SessionState));

    // RLebeau 1/6/2009: don't create the PostStream unless there is
    // actually something to read. This should make it easier for the
    // request handler to know when to use the PostStream and when to
    // use the (Unparsed)Params instead...

    if (LRequestInfo.TransferEncoding <> '') and
      (not TextIsSame(LRequestInfo.TransferEncoding, 'identity')) then {do not localize}
    begin
      if IndyPos('chunked', LowerCase(LRequestInfo.TransferEncoding)) = 0 then begin {do not localize}

But I do not see those logs writen, even the log file is not created.

Is there any limitation on doing it.

Also I want to point that I was telling before about that the GET messages are processed is not correct. For those messages I can only see the HeadersAvailable log line and nothing more, so OnCommandOther is not triggered for those GETs.

[Remy Lebeau 1421]

7 hours ago, pssDP said:

To go further, I have added log lines in several places of IdCustomHTTPServer module, and changed the writing of the log with that of IdServerInterceptLogFile, as follows:

On a side note: Indy has logging components, such as TIdLogFile, that you can attach to each connection's IOHandler.Intercept property, such as in the server's OnConnect event.  I would suggest doing that instead of rolling your own logging code.  If, for no other reason, than because you are opening and closing the log file on every message logged, which is highly inefficient.

7 hours ago, pssDP said:

But I do not see those logs writen, even the log file is not created.

Is there any limitation on doing it.

There is no possible way that HeadersCanContinue() and CreatePostStream() would not be called for every request.  So I have to assume that the changes you made to Indy's source code did not take effect, ie you did not recompile Indy, and then recompile your app with the updated library.  If that is not the case, then something else is going on that I can't see.

7 hours ago, pssDP said:

Also I want to point that I was telling before about that the GET messages are processed is not correct. For those messages I can only see the HeadersAvailable log line and nothing more, so OnCommandOther is not triggered for those GETs.

Obviously, OnCommandOther would not be called for a GET request, OnCommandGet would be called instead.

 

At this point, your debugging efforts are not really helping.  And I don't have a working environment that I can test with.  So, we are at a stalemate.  Can you, at least, provide a complete log or Wireshark capture of the entire HTTP conservsation that is not working for you?  Also, are you using plain HTTP or secure HTTPS?

 

You said originally that the problem did not start happening until you made a modification to your web server - what was that modification exactly?

[pssDP 0]

In my first post of this thread you can see what TIdLogFile gives me, and, if you remember I told about that there is no date and time in this log, even if I included this code:

  Intercept := TIdServerInterceptLogFile.Create(nil);
  Intercept.Filename := 'C:\TMP\DBGLOG.TXT';
  Intercept.LogTime := True;
  HTTPServer.Intercept := Intercept;

 

40 minutes ago, Remy Lebeau said:

There is no possible way that HeadersCanContinue() and CreatePostStream() would not be called for every request.  So I have to assume that the changes you made to Indy's source code did not take effect, ie you did not recompile Indy, and then recompile your app with the updated library.  If that is not the case, then something else is going on that I can't see.

HeadersAvailable, CreatePostStream and ParseAuthentication events are fired, and nothing more.

In HeadersAvailable event I have VContinueProcessing and HTTPServer.SessionState both true.

What I did was to insert temporally log lines only and nothing more, in the source code of IdCustomHTTPServer module, and compile this module only, not the entire Indy, to avoid messing my production environment, but I think that it is not possible, or at least, I do not know how to do.

46 minutes ago, Remy Lebeau said:

Obviously, OnCommandOther would not be called for a GET request, OnCommandGet would be called instead.

I mean that both OnCommandOther and OnCommandGet are not fired.

 

47 minutes ago, Remy Lebeau said:

At this point, your debugging efforts are not really helping.  And I don't have a working environment that I can test with.  So, we are at a stalemate.  Can you, at least, provide a complete log or Wireshark capture of the entire HTTP conservsation that is not working for you?  Also, are you using plain HTTP or secure HTTPS?

I am using HTTPS, I will try to get a Wireshark capture and post it here.

 

 

[pssDP 0]

Found it !!

Fist, I compiled myself IdCustomHTTPServer module source code, to not mess my installations, here is how:

1.) Copied IdCustomHTTPServer.pas, IdHTTPServer.pas, IDCompilerDefines.inc to the folder where is the source code of my project.

2.) Renamed those files in the original location C:\Program Files (x86)\Embarcadero\Studio\15.0\source\Indy10\Protocols

3.) Renamed IdCustomHTTPServer.dcu in the original location C:\Program Files (x86)\Embarcadero\Studio\15.0\lib\win32\release

4.) Added log lines to IdCustomHTTPServer.pas file added to my project, as I explained before

The affected part is in the CreateSession procedure of IdCustomHTTPServer

function TIdCustomHTTPServer.CreateSession(AContext: TIdContext; HTTPResponse: TIdHTTPResponseInfo;
  HTTPRequest: TIdHTTPRequestInfo): TIdHTTPSession;
var
  LCookie: TIdCookie;
  // under ARC, convert a weak reference to a strong reference before working with it
  LSessionList: TIdHTTPCustomSessionList;
begin
  Result := nil;
GNDebugScan('Begin CreateSession, SessState: ' + BoolToStr(SessionState) + ', SessList: ' + BoolToStr(Assigned(FSessionList)));
 if SessionState then begin
    LSessionList := FSessionList;
    if Assigned(LSessionList) then begin
      DoOnCreateSession(AContext, Result);
GNDebugScan('After DoOnCreateSession, Result: ' + BoolToStr(Result <> nil));
      if not Assigned(Result) then begin
        Result := LSessionList.CreateUniqueSession(HTTPRequest.RemoteIP);
      end else begin
        LSessionList.Add(Result);
      end;
GNDebugScan('CreateSession, after CreateUnique: ' + BoolToStr(Result <> nil));
      LCookie := HTTPResponse.Cookies.Add;
      LCookie.CookieName := GSessionIDCookie;
      LCookie.Value := Result.SessionID;
      LCookie.Path := '/';    {Do not Localize}

      // By default the cookie will be valid until the user has closed his browser window.
      // MaxAge := SessionTimeOut div 1000;
      HTTPResponse.FSession := Result;
      HTTPRequest.FSession := Result;
    end;
  end;
GNDebugScan('End CreateSession, SessState: ' + BoolToStr(SessionState) + ', Result: ' + BoolToStr(Result <> nil));
end;

With that inserted, I saw that the session was not correctly inserted in the LSessionList because of this in my CreateSession event:

procedure TAmWebAgeSvc.HTTPServerCreateSession(ASender: TIdContext; var VHTTPSession: TIdHTTPSession);
begin
  GNDebugScan('CreateSession: ' + VHTTPSession.Content.CommaText);
end;

That is, the fact that I used VHTTPSession.Content.CommaText as a debug messed up this var variable.

Once I deleted this reference, the program now runs as expected.

Now, I will restore all the original files to their original location

It goes without saying that I must deeply thank Remy for the help provided.

 

[Remy Lebeau 1421]

On 5/16/2021 at 5:01 AM, pssDP said:

With that inserted, I saw that the session was not correctly inserted in the LSessionList because of this in my CreateSession event:

procedure TAmWebAgeSvc.HTTPServerCreateSession(ASender: TIdContext; var VHTTPSession: TIdHTTPSession);
begin
  GNDebugScan('CreateSession: ' + VHTTPSession.Content.CommaText);
end;

That is, the fact that I used VHTTPSession.Content.CommaText as a debug messed up this var variable.

Once I deleted this reference, the program now runs as expected.

When the OnCreateSession event is called, the VHTTPSession parameter is initially nil.  Users of the OnCreateSession event are expected to CREATE a new TIdHTTPSession object (hence the name of the event!) and assign it to the parameter before exiting (that is why the parameter is a 'var'), if they want to, ie when using a TIdHTTPSession-derived class to track custom data.  After the event exits, if the parameter is still nil then TIdHTTPServer calls LSessionList.CreateUniqueSession() to create a default session object.

 

Since you are accessing an invalid object, you should be getting an Access Violation exception that aborts the current request, sends a 500 response to the client, and calls the OnCommandError event.

 

Sorry, I missed that when you posted your code earlier.

Edited May 17, 2021 by Remy Lebeau