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 TIdTCPServer
s 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...
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).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 associatedTIdYarn
, which will remove itself from the list.TIdTCPServer
vs aTIdHTTPServer
. 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 theActive
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 theTerminateAllYarns()
loop keeps running.