0

Under Linux, TIdHTTPServer hangs on shutdown (IdHTTPServer1.Active := false) due to an un-ending loop in TIdScheduler.TerminateAllYarns(). The problem is permanent (on my development PC) and only if there has been at least one connection to the HTTP server.

However, the weird bit is that while the problem shows up in the shared code of the base Indy system, it only occurs in the shutting down of the HTTP server, and does NOT occur in the shutting down of two TIdTCPServers just before, and which also have open connections. They work normally.

I added lots of Syslog entries through the code, and the syslog looks like this:

Aug 31 09:32:32 debian11 sartrackserver[31893]: DebugLogShutdown: HTTP Server stop
Aug 31 09:32:32 debian11 sartrackserver[31893]: IdCustomHTTPServer.Shutdown: SetSessionList(nil)
Aug 31 09:32:32 debian11 sartrackserver[31893]: IdCustomHTTPServer.SetSessionList: LSessionList <> AValue
Aug 31 09:32:32 debian11 sartrackserver[31893]: IdCustomHTTPServer.SetSessionList: FImplicitSessionList
Aug 31 09:32:32 debian11 sartrackserver[31893]: IdCustomHTTPServer.SetSessionList: IdDisposeAndNil
Aug 31 09:32:32 debian11 sartrackserver[31893]: IdCustomHTTPServer.SetSessionList: DONE
Aug 31 09:32:32 debian11 sartrackserver[31893]: IdCustomHTTPServer.Shutdown: inherited Shutdown
Aug 31 09:32:32 debian11 sartrackserver[31893]: IdCustomTCPServer.Shutdown
Aug 31 09:32:32 debian11 sartrackserver[31893]: IdCustomTCPServer.StopListening
Aug 31 09:32:32 debian11 sartrackserver[31893]: IdSocketHandle.CloseSocket: HandleAllocated
Aug 31 09:32:32 debian11 sartrackserver[31893]: IdSocketHandle.CloseSocket calls Disconnect
Aug 31 09:32:32 debian11 sartrackserver[31893]: IdSocketHandle.Disconnect calls GStack.Disconnect(Handle)
Aug 31 09:32:32 debian11 sartrackserver[31893]: IdSocketHandle.CloseSocket: NOT HandleAllocated
Aug 31 09:32:32 debian11 sartrackserver[31893]: IdSocketHandle.Disconnect: GStack.Disconnect DONE
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdSocketHandle.CloseSocket: NOT HandleAllocated
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdCustomTCPServer.StopListening Done
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdCustomTCPServer.Shutdown TerminateAllThreads
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdCustomTCPServer.TerminateAllThreads: LockList
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdCustomTCPServer.TerminateAllThreads: List.Count=1
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdCustomTCPServer.TerminateAllThreads: Assert 1 okay
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdCustomTCPServer.TerminateAllThreads: AssertClassname 1 okay
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdCustomTCPServer.TerminateAllThreads: Calling DoTerminateContext
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdCustomTCPServer.DoTerminateContext calls CloseSocket
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdSocketHandle.CloseSocket: HandleAllocated
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdSocketHandle.CloseSocket calls Disconnect
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdSocketHandle.Disconnect calls GStack.Disconnect(Handle)
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdSocketHandle.Disconnect: GStack.Disconnect DONE
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdCustomTCPServer.TerminateAllThreads: UnLockList
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdCustomTCPServer.TerminateAllThreads calls TerminateAllYarns
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdScheduler.TerminateAllYarns loop: Count=1
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdScheduler.TerminateAllYarns DONE
Aug 31 09:32:33 debian11 sartrackserver[31893]: IdScheduler.TerminateAllYarns loop: Count=1
Aug 31 09:32:34 debian11 sartrackserver[31893]: IdScheduler.TerminateAllYarns DONE
Aug 31 09:32:34 debian11 sartrackserver[31893]: IdScheduler.TerminateAllYarns loop: Count=1
Aug 31 09:32:34 debian11 sartrackserver[31893]: IdScheduler.TerminateAllYarns DONE
Aug 31 09:32:34 debian11 sartrackserver[31893]: IdScheduler.TerminateAllYarns loop: Count=1
Aug 31 09:32:35 debian11 sartrackserver[31893]: IdScheduler.TerminateAllYarns DONE

etc.

The actual code in TerminateYarns() is this:

procedure TIdScheduler.TerminateAllYarns;
var
  i: Integer;
  LList: TIdYarnList;
begin
  Assert(FActiveYarns<>nil);

  while True do begin
    // Must unlock each time to allow yarns that are terminating to remove themselves from the list
    // Bart
    LList := FActiveYarns.LockList;
    try
      syslog(LOG_NOTICE, 'IdScheduler.TerminateAllYarns loop: Count='+LList.Count.ToString);
      if LList.Count = 0 then begin
        Break;
      end;
      for i := LList.Count - 1 downto 0 do begin
        TerminateYarn(
          {$IFDEF HAS_GENERICS_TList}LList.Items[i]{$ELSE}TIdYarn(LList.Items[i]){$ENDIF} <<< Never deletes anything from the list
        );
      end;
    finally
      FActiveYarns.UnlockList;
    end;
                                            
    IndySleep(500); // Wait a bit before looping to prevent thrashing
    syslog(LOG_NOTICE, 'IdScheduler.TerminateAllYarns DONE');
  end;
end;

Any idea what I can try to fix this?

UPDATE: here is my code:

class procedure TDebugLogEventHandlers.IdHTTPServer1CommandGet(AContext: TIdContext; ARequestInfo: TIdHTTPRequestInfo; AResponseInfo: TIdHTTPResponseInfo);
var
  TmpList: TStringList;
  ST: TSystemTime;
begin
  // if StatsListInProgress then
  if true then
  begin 
    TmpList := TStringList.Create;
    try
      TmpList.Add('<!DOCTYPE html PUBLIC "-//W3C//DTD HTML 4.01//EN" "http://www.w3.org/TR/html4/strict.dtd"><html><head>');
      TmpList.Add('<meta content="text/html; charset=ISO-8859-1" http-equiv="content-type"><title>SARTrack Server Stats</title>');
      TmpList.Add('<meta http-equiv="refresh" content="5">');
      TmpList.Add('</head><body>');
      TmpList.Add('Data Temporarily Unavailable');
      TmpList.Add(MyDateToStrEx(ST)+' '+MyTimeToStr(ST)+' UTC');
      TmpList.Add('</body></html>'); 
      try
        AResponseInfo.ContentText := TmpList.Text;
      except
        on E:Exception do
          LocalLog('TDebugLogEventHandlers: '+E.Message,d_error);
      end;
      LocalLog('TDebugLogEventHandlers: StatsList is in use during request',d_error); 
    finally
      TmpList.Free;
    end;
  end else
  begin
    {try
      AResponseInfo.ContentText := StatsList.Text;
    except
      on E:Exception do
        LocalLog('TDebugLogEventHandlers: '+E.Message,d_error);
    end;} 
  end;
end;

procedure DebugLogInit;
begin
  try
    Log('DebugLogInit');
    IdHTTPServer1 := TIdHTTPServer.Create(nil);
    IdHTTPServer1.OnCommandGet := TDebugLogEventHandlers.IdHTTPServer1CommandGet;
    IdHTTPServer1.OnException := TDebugLogEventHandlers.IdHTTPServer1Exception;
    IdHTTPServer1.DefaultPort := 8053;
    IdHTTPServer1.KeepAlive := true;
    IdHTTPServer1.MaxConnections := 10;
  except
    on E:Exception do
      Log('DebugLogInit: '+E.Message,d_error);
  end;
end;

procedure DebugLogShutdown;
begin
  Log('Shutting down DebugLog system...');
  try
    {TimerQueue.Release(WebRefreshTimer);
    TimerQueue.Release(Port2ClearTimer);
    Log('DebugLogShutdown: TCP Server stop...');
    IdTCPServerDebug.Active := false;
    Log('DebugLogShutdown: Freeing TCP Server...');
    IdTCPServerDebug.Free;}
    Log('DebugLogShutdown: HTTP Server stop');
    IdHTTPServer1.Active := false;
    Log('DebugLogShutdown: HTTP Server free');
    IdHTTPServer1.Free;
    {StatsList.Free;
    IOFormShutDown;
    CloseAllIniFiles;
    Port2StationList.Free;}
  except
    on E:Exception do
      Log('DebugLogForm.Shutdown: '+E.Message,d_error);
  end;
end;

UPDATE2

I went deeper in the code, and this is where it goes wrong:

 IdCustomTCPServer.TerminateAllThreads calls TerminateAllYarns
Sep  1 07:37:47 debian11 sartrackserver[33098]: IdScheduler.TerminateAllYarns loop: Count=1
Sep  1 07:37:47 debian11 sartrackserver[33098]: IdSchedulerOfThread.TerminateYarn
Sep  1 07:37:47 debian11 sartrackserver[33098]: IdSchedulerOfThread.TerminateYarn calls LThread.Stop
Sep  1 07:37:48 debian11 sartrackserver[33098]: IdScheduler.TerminateAllYarns DONE
Sep  1 07:37:48 debian11 sartrackserver[33098]: IdScheduler.TerminateAllYarns loop: Count=1
Sep  1 07:37:48 debian11 sartrackserver[33098]: IdSchedulerOfThread.TerminateYarn
Sep  1 07:37:48 debian11 sartrackserver[33098]: IdSchedulerOfThread.TerminateYarn calls LThread.Stop
Sep  1 07:37:48 debian11 sartrackserver[33098]: IdScheduler.TerminateAllYarns DONE
Sep  1 07:37:48 debian11 sartrackserver[33098]: IdScheduler.TerminateAllYarns loop: Count=1

And the code looks like this:

procedure TIdSchedulerOfThread.TerminateYarn(AYarn: TIdYarn);
var
  LYarn: TIdYarnOfThread;
  LThread: TIdThreadWithTask;
begin
  // Bart
  syslog(LOG_NOTICE, 'IdSchedulerOfThread.TerminateYarn');
  Assert(AYarn<>nil);
  LYarn := TIdYarnOfThread(AYarn);
  LThread := LYarn.Thread;
  if (LThread <> nil) and (not LThread.Suspended) then begin
    // Is still running and will free itself
    syslog(LOG_NOTICE, 'IdSchedulerOfThread.TerminateYarn calls LThread.Stop');
    LThread.Stop;
    // Dont free the yarn. The thread frees it (IdThread.pas)
  end else
  begin
    // If suspended, was created but never started
    // ie waiting on connection accept

    // RLebeau: free the yarn here as well. This allows TIdSchedulerOfThreadPool
    // to put the suspended thread, if present, back in the pool.
    syslog(LOG_NOTICE, 'IdSchedulerOfThread.TerminateYarn calls IdDisposeAndNil(LYarn)');
    IdDisposeAndNil(LYarn);
  end;
end;

UPDATE 3

procedure TIdThread.Stop;
begin
  syslog(LOG_NOTICE, 'IdThread.Stop: Try enter lock');
  FLock.Enter;
  syslog(LOG_NOTICE, 'IdThread.Stop: locked');
  try
    if not Stopped then
    begin
      case FStopMode of
        smTerminate: begin syslog(LOG_NOTICE, 'IdThread.Stop calls Terminate'); Terminate; end
        // smSuspend: ;{DO not suspend here. Suspend is immediate. See Execute for implementation};
        else syslog(LOG_NOTICE, 'IdThread.Stop does NOT call Terminate');
      end;
      Include(FOptions, itoStopped);
    end else syslog(LOG_NOTICE, 'IdThread.Stop: is Stopped. Not doing anything');
  finally FLock.Leave; end;
end;

and Terminate:

procedure TIdThread.Terminate;
begin
  //this assert can only raise if terminate is called on an already-destroyed thread
  Assert(FLock<>nil);

  FLock.Enter;
  try
    syslog(LOG_NOTICE, 'IdThread.Terminate calls Include');
    Include(FOptions, itoStopped);
    syslog(LOG_NOTICE, 'IdThread.Terminate calls inherited Terminate');
    inherited Terminate;
  finally FLock.Leave; end;
end;

The Stop and Terminate do NOT FREE the Yarn. So it never gets freed. Correct me if I am wrong...

12
  • Assign the first item of the list to a local variable, then unlock the list, then call TerminateYarn( firstItem ); - this makes sure the locked list is not part of the problem (as in: can't be removed from list because the list is locked).
    – AmigoJack
    Aug 30, 2021 at 22:38
  • @AmigoJack TerminateYarn() simply signals the thread to terminate itself, and then the list gets unlocked. The thread will destroy itself when it stops running, which will destroy the associated TIdYarn, which will remove itself from the list. Aug 30, 2021 at 23:32
  • @BartKindt There is no difference between shutting down a TIdTCPServer vs a TIdHTTPServer. The most common reason for a hang during shutdown is a deadlock in your server event handlers, preventing one or more threads from terminating properly. For example, by synchronizing with the same thread that is trying to shutdown the server, since the Active setter is a blocking operation. Without a minimal reproducible example, it is difficult to diagnose your problem, but it is clear from the logging that there is a thread not terminating properly, which is why the TerminateAllYarns() loop keeps running. Aug 30, 2021 at 23:34
  • I so dislike this forum. Now i can no longer add any code.
    – Bart Kindt
    Aug 31, 2021 at 3:14
  • Also note that this only occurs under Linux. Under Windows it works fine, and has been for the last 5 years, two Internet based servers running 24/7. I just tested again recompiled as a Windows Service, and it works normally. This is the same code. In Linux it fails every time, as reported.
    – Bart Kindt
    Aug 31, 2021 at 4:13

1 Answer 1

0

This is a known issue, but this moment no solution in common. However, the hangs appear if using SSL IOhandler only. So, I do not recommend to use SSL IOHandler as it does not support TLSv1.3 and advanced cipher algorithms. Instead, turn on a nginx reverse proxy server with HTTPS frontend and HTTP backend connected to your application.

1
  • As it’s currently written, your answer is unclear. Please edit to add additional details that will help others understand how this addresses the question asked. You can find more information on how to write good answers in the help center.
    – Community Bot
    Sep 28, 2021 at 15:48

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.