Horse.Logger está travando o recycle do pool no IIS (Aplicação ISAPI x64)

[soul-a]

Possuo algumas aplicações no ambiente ISAPI e funcionam normalmente, porém ao tentar dar recycle do pool da aplicação, o pool só é reciclado quando o timeout de "Desligamento" é atingido, durante testes internos notei que o problema estava no Horse.Logger.

Aparentemente a aplicação não está limpando as threads, fiz diversas tentativas diretamente no Horse.Provider.ISAPI, porém não obtive sucesso, deixarei abaixo uma das tentativas que tentei usar para limpar as threads

procedure DoOnTerminate;
begin
  // Terminate threads...
  try
    Log('Log Manager Thread is starting terminate proccess...');

    if THorseLoggerManager.DefaultManager <> nil then
    begin
      THorseLoggerManager.DefaultManager.Terminate;
      THorseLoggerManager.DefaultManager.GetEvent.SetEvent;
      THorseLoggerManager.DefaultManager.WaitFor;
      THorseLoggerManager.DefaultManager.Free;
    end;

    if THorseLoggerManager.DefaultManager <> nil then
      TerminateThread(THorseLoggerManager.DefaultManager.Handle, 0);

    Log('Log Manager Thread is terminated');
  except on E: Exception do
    Log('Log Manager Thread dispath an error: ' + E.StackTrace + #13#10 + E.Message);
  end;
end;

// ...

class procedure THorseProvider<T>.InternalListen;
begin
  CoInitFlags := COINIT_MULTITHREADED;
  Application.Initialize;
  Application.WebModuleClass := WebModuleClass;
  (Application as TISAPIApplication).OnTerminate := DoOnTerminate;
  DoOnListen;
  Application.Run;
end;

O log interno acima, acusa que ele está limpando a thread manager, porém a aplicação não termina o recycle mesmo assim.

Fiz algumas pesquisas relacionadas a ThreadPool no IIS e vi que é uma boa prática finalizar as therads no método TISAPIApplication.OnTerminate ou no método de export TerminateExtension.

Dependências usadas (apenas as relacionadas a issue)

"github.com/hashload/horse": "^3.0.1",
"github.com/hashload/horse-logger": "^2.0.6",

O provider para o logger é interno, foi criado baseado no provider horse-logger-provider-logfile e horse-logger-provider-console

Links relacionados

• https://pastebin.com/s04VDPjG
• https://mathiaspannier.wordpress.com/2016/07/17/how-to-properly-cleanupshutdown-a-delphi-isapi-which-uses-threads/
• https://en.delphipraxis.net/topic/1632-isapi-dll-concurrent-requests/
• https://stackoverflow.com/questions/65455467/delphi-isapi-multi-threading-log-object-not-disposed-correctly

[viniciussanchez]

Bom dia... poderia nos mostrar como está o seu provider de log? Acredito que o problema esteja nele

[soul-a]

Bom dia, segue abaixo o provider usado, dentro do DispatchLogCache do log eu chamo um service que registra os dados no banco, estou usando o Firebird v4.0.

unit Providers.Logger.Database;

interface

uses
  System.Classes,
  Horse.Logger;

type
  TLoggerDatabaseConfig  = class
  { private declarations }
  private
    FLogFormat: string;
  { public declarations }
  public
    constructor Create;
    function SetLogFormat(ALogFormat: string): TLoggerDatabaseConfig;
    function GetLogFormat(out ALogFormat: string): TLoggerDatabaseConfig;
    class function New: TLoggerDatabaseConfig;
  end;

  TLoggerProviderDatabaseManager = class(THorseLoggerThread)
  { private declarations }
  private
    FConfig: TLoggerDatabaseConfig;
  { protected declarations }
  protected
    procedure DispatchLogCache; override;
  { public declarations }
  public
    destructor Destroy; override;
    function SetConfig(AConfig: TLoggerDatabaseConfig): TLoggerProviderDatabaseManager;
  end;

  TLoggerProviderDatabase = class(TInterfacedObject, IHorseLoggerProvider)
  private
    { private declarations }
    FLoggerProviderDatabaseManager: TLoggerProviderDatabaseManager;
  protected
    { protected declarations }
  public
    { public declarations }
    constructor Create(const AConfig: TLoggerDatabaseConfig = nil);
    destructor Destroy; override;
    procedure DoReceiveLogCache(ALogCache: THorseLoggerCache);
    class function New(const AConfig: TLoggerDatabaseConfig = nil): IHorseLoggerProvider;
  end;

implementation

uses System.SysUtils, System.JSON, System.SyncObjs, Services.Logger.Database;

{ THorseLoggerProviderDatabase }

const
  DEFAULT_LOG_FORMAT =
    '${time}, ${time_short}, ${execution_time}, ${request_clientip}, ${request_method}, ' +
    '${request_version}, ${request_url}, ${request_query}, ${request_path_info}, ' +
    '${request_path_translated}, ${request_cookie}, ${request_accept}, ${request_from}, ' +
    '${request_host}, ${request_referer}, ${request_user_agent}, ${request_connection}, ' +
    '${request_remote_addr}, ${request_remote_host}, ${request_script_name}, ${request_server_port}, ' +
    '${request_authorization}, ${request_content_encoding}, ${request_content_type}, ' +
    '${request_content_length}, ${request_content_version}, ${request_content}, ' +
    '${response_server}, ${response_allow}, ${response_location}, ${response_content_encoding}, ' +
    '${response_content_type}, ${response_content_length}, ${response_content}, ${response_status}';

constructor TLoggerProviderDatabase.Create(const AConfig: TLoggerDatabaseConfig);
begin
  FLoggerProviderDatabaseManager := TLoggerProviderDatabaseManager.Create(True);
  FLoggerProviderDatabaseManager.SetConfig(AConfig);
  FLoggerProviderDatabaseManager.FreeOnTerminate := False;
  FLoggerProviderDatabaseManager.Start;
end;

destructor TLoggerProviderDatabase.Destroy;
begin
  FLoggerProviderDatabaseManager.Terminate;
  FLoggerProviderDatabaseManager.GetEvent.SetEvent;
  FLoggerProviderDatabaseManager.WaitFor;
  FLoggerProviderDatabaseManager.Free;
  inherited;
end;

procedure TLoggerProviderDatabase.DoReceiveLogCache(ALogCache: THorseLoggerCache);
var
  I: Integer;
begin
  for I := 0 to Pred(ALogCache.Count) do
    FLoggerProviderDatabaseManager.NewLog(THorseLoggerLog(ALogCache.Items[0].Clone));
end;

class function TLoggerProviderDatabase.New(const AConfig: TLoggerDatabaseConfig): IHorseLoggerProvider;
begin
  Result := TLoggerProviderDatabase.Create(AConfig);
end;

{ TLoggerProviderDatabaseManager }

destructor TLoggerProviderDatabaseManager.Destroy;
begin
  FreeAndNil(FConfig);
  inherited;
end;

procedure TLoggerProviderDatabaseManager.DispatchLogCache;
var
  I, Z: Integer;
  LLogCache: THorseLoggerCache;
  LLog: THorseLoggerLog;
  LParams: TArray<string>;
  LValue: string;
  LLogStr: string;
  Service: TServiceLoggerDatabase;
begin
  if FConfig = nil then
    FConfig := TLoggerDatabaseConfig.New;

  Service := TServiceLoggerDatabase.Create;

  FConfig.GetLogFormat(LLogStr);
  LLogCache := ExtractLogCache;
  try
    if LLogCache.Count = 0 then
      Exit;

    { Percorre o LOG com base no formato predefindo }
    for I := 0 to Pred(LLogCache.Count) do
    begin
      var LLogJSON: TJSONObject;

      LLog     := LLogCache.Items[I] as THorseLoggerLog;
      LParams  := THorseLoggerUtils.GetFormatParams(LLogStr);
      LLogJSON := TJSONObject.Create;

      for Z := Low(LParams) to High(LParams) do
      begin
        if LLog.TryGetValue<string>(LParams[Z], LValue) then
          LLogJSON.AddPair(LParams[Z], LValue);
      end;

      { Service para LOG }
      Service.ProduceLog(LLogJSON);

      { Free JSON }
      LLogJSON.Free;
    end;
  finally
    LLogCache.Free;
    FreeAndNil(Service);
  end;
end;

function TLoggerProviderDatabaseManager.SetConfig(AConfig: TLoggerDatabaseConfig): TLoggerProviderDatabaseManager;
begin
  Result  := Self;
  FConfig := AConfig;
end;

{ TLoggerDatabaseConfig }

constructor TLoggerDatabaseConfig.Create;
begin
  FLogFormat := DEFAULT_LOG_FORMAT;
end;

function TLoggerDatabaseConfig.GetLogFormat(out ALogFormat: string): TLoggerDatabaseConfig;
begin
  Result := Self;
  ALogFormat := FLogFormat;
end;

class function TLoggerDatabaseConfig.New: TLoggerDatabaseConfig;
begin
  Result := TLoggerDatabaseConfig.Create;
end;

function TLoggerDatabaseConfig.SetLogFormat(ALogFormat: string): TLoggerDatabaseConfig;
begin
  Result := Self;
  FLogFormat := ALogFormat;
end;

end.

Fico a disposição para mais detalhes, agradeço.

Obs: Já realizei testes isolados usando o outros provider's, inclusive os oficiais fornecidos pelo middleware de logger e o problema é o mesmo, em pesquisar a outros lib's que utilizam middlewares para log, o mesmo possuem finalizações especificas de seus log's quando feito o deploy para IS_API DLL.

Edit 1 (05/02/2024 10:26):

• Dar continuidade nesta issue @leonardo-gomes03, @LeandroMartins99

[viniciussanchez]

Boa tarde... acharam alguma solução para o problema em questão? Aqui nos também utilizamos o logger inclusive com o provider oficial de salvar em arquivo texto, compilando para o IIS em modo 64 bits e não temos esse tipo de comportamento. Precisava analisar algo mais próximo do cenário de vocês. Até porque até então, ninguém mais reclamou do problema.