Recent

Author Topic: Thread-safe logger  (Read 1907 times)

SymbolicFrank

  • Hero Member
  • *****
  • Posts: 1313
Thread-safe logger
« on: August 24, 2022, 01:44:53 pm »
I tried LazLogger, but it seems to be a bit buggy:
- You cannot use the command-line parameter to specify a file, you have to assign the name to DebugLogger.LogName
- It only writes the log when the program ends, and only partially at that (it just stops at some random location).

This is on Windows 10 64-bit, with trunk.
« Last Edit: August 24, 2022, 01:47:41 pm by SymbolicFrank »

Martin_fr

  • Administrator
  • Hero Member
  • *
  • Posts: 9794
  • Debugger - SynEdit - and more
    • wiki
Re: Thread-safe logger
« Reply #1 on: August 24, 2022, 01:53:54 pm »
There is an option you can set the command line param's name for the logfile. (Though that had some bugs, and was fixed recently in the main branch)

Also there are different thread handling implementation. The default uses TThread.queue, which requires the main thread to run synchronize. And if that fails, the log is cut.


Try TLazLoggerFileHandleThreadSave
You need to check the code where/how to set it...

You can also try "CloseLogFileBetweenWrites" to make sure the file is flushed.

-------
Feel free to add any findings to the docs: https://wiki.lazarus.freepascal.org/LazLogger

SymbolicFrank

  • Hero Member
  • *****
  • Posts: 1313
Re: Thread-safe logger
« Reply #2 on: August 24, 2022, 05:58:03 pm »
Thanks. In my app, the threads start their own threads, so I decided to roll my own. But it has the same problems. Conclusion: the FileStreams are not the right tool for the job and the RTLEvents run through the message handler of the main thread.

I'll make a version that uses low-level file access and uses better signalling.

KodeZwerg

  • Hero Member
  • *****
  • Posts: 2010
  • Fifty shades of code.
    • Delphi & FreePascal
Re: Thread-safe logger
« Reply #3 on: August 27, 2022, 12:03:49 am »
Thanks. In my app, the threads start their own threads, so I decided to roll my own. But it has the same problems. Conclusion: the FileStreams are not the right tool for the job and the RTLEvents run through the message handler of the main thread.

I'll make a version that uses low-level file access and uses better signalling.
Code: Pascal  [Select][+][-]
  1. unit Unit1;
  2.  
  3. {$mode objfpc}{$H+}
  4.  
  5. interface
  6.  
  7. uses
  8.   Windows,
  9.   Classes, SysUtils, Forms, Controls, Graphics, Dialogs;
  10.  
  11. type
  12.  
  13.   { TForm1 }
  14.  
  15.   TForm1 = class(TForm)
  16.     procedure FormCreate(Sender: TObject);
  17.   private
  18.   public
  19.   end;
  20.  
  21. var
  22.   Form1: TForm1;
  23.  
  24. implementation
  25.  
  26. {$R *.lfm}
  27.  
  28. procedure TForm1.FormCreate(Sender: TObject);
  29. var
  30.   FN: string;
  31.   SL: TStringList;
  32.   FS: THandleStream;
  33.   FH: THandle;
  34. begin
  35.   FN := ChangeFileExt(Application.ExeName, '.txt');
  36.   SL := TStringList.Create;
  37.   try
  38.     ForceDirectories(ExtractFileDir(FN));
  39.     FH := CreateFile(PChar(FN), GENERIC_READ or GENERIC_WRITE, FILE_SHARE_READ, nil,
  40.       OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL or FILE_FLAG_SEQUENTIAL_SCAN, 0);
  41.     if FH = INVALID_HANDLE_VALUE then
  42.       RaiseLastOSError;
  43.     try
  44.       FS := THandleStream.Create(FH);
  45.       try
  46.         SL.LoadFromStream(FS); // get old data
  47.  
  48.         //... add new data
  49.  
  50.         FS.Position := 0;
  51.         FS.Size := 0; // after save to kind rewrite things... dunno
  52.         SL.SaveToStream(FS);
  53.       finally
  54.         FS.Free;
  55.       end;
  56.     finally
  57.       CloseHandle(FH);
  58.     end;
  59.   finally
  60.     SL.Free;
  61.   end;
  62. end;
  63.  
  64. end.
  65.  
Just as a prototype typed quick, if you would declare within class and keep handle open, that could be an solution that you might like to use on windows?...
« Last Edit: Tomorrow at 31:76:97 xm by KodeZwerg »

Martin_fr

  • Administrator
  • Hero Member
  • *
  • Posts: 9794
  • Debugger - SynEdit - and more
    • wiki
Re: Thread-safe logger
« Reply #4 on: August 27, 2022, 12:28:34 am »
I believe at least on windows they should work, if you put them in critical sections.

That is what TLazLoggerFileHandleThreadSave does.

The other part is that the filehandle must be owned (opened) by the main thread (or a thread that is not terminated before all logging is done).

Not sure about other OS.

SymbolicFrank

  • Hero Member
  • *****
  • Posts: 1313
Re: Thread-safe logger
« Reply #5 on: August 29, 2022, 11:56:07 am »
This seems to work, and should be multi-platform:

Code: Pascal  [Select][+][-]
  1. unit MPLogger;
  2.  
  3. {$mode Delphi}{$H+}{$I-}
  4.  
  5. interface
  6.  
  7. uses
  8.   Classes, SysUtils, FileUtil, PasMP, syncobjs;
  9.  
  10. type
  11.  
  12.   TLogQueue = class(TPasMPUnboundedQueue<string>);
  13.  
  14.   { TMPLogger }
  15.  
  16.   TMPLogger = class(TThread)
  17.   private
  18.     procedure SetFileName(ThisFileName: string);
  19.   protected
  20.     MyQueue: TLogQueue;
  21.     MyFileName: string;
  22.     MyWait: TEvent;
  23.     MyCriticalSection: TCriticalSection;
  24.     procedure Execute; override;
  25.     procedure Log;
  26.   public
  27.     property Queue: TLogQueue read MyQueue;
  28.     property WaitEvent: TEvent read MyWait;
  29.     property FileName: string read MyFileName write SetFileName;
  30.  
  31.     constructor Create(ThisFile: string);
  32.     destructor Destroy; override;
  33.   end;
  34.  
  35. procedure LogLn(s: string = ''; ThisFileName: string = '');
  36.  
  37. var
  38.   GlobalMPLog: TMPLogger;
  39.  
  40. implementation
  41.  
  42. procedure LogLn(s: string = ''; ThisFileName: string = '');
  43. begin
  44.   if not Assigned(GlobalMPLog) then
  45.   begin
  46.     GlobalMPLog := TMPLogger.Create(ThisFileName);
  47.   end;
  48.  
  49.   GlobalMPLog.Queue.Enqueue(s);
  50.   GlobalMPLog.WaitEvent.SetEvent;
  51. end;
  52.  
  53. { TMPLogger }
  54.  
  55. procedure TMPLogger.Log;
  56. var
  57.   MyFile: TextFile;
  58.   s: string;
  59. begin
  60.   if not MyQueue.IsEmpty then
  61.   begin
  62.     AssignFile(MyFile, MyFileName);
  63.     if IOResult <> 0 then Exit;
  64.     if FileExists(MyFileName) then Append(MyFile)
  65.     else Rewrite(MyFile);
  66.     if IOResult <> 0 then Exit;
  67.     try
  68.       while MyQueue.Dequeue(s) do WriteLn(MyFile, s);
  69.       CloseFile(MyFile);
  70.     except
  71.       Terminate;
  72.       Exit;
  73.     end;
  74.   end;
  75. end;
  76.  
  77. procedure TMPLogger.SetFileName(ThisFileName: string);
  78. begin
  79.   MyCriticalSection.Enter;
  80.   if Length(Trim(ThisFileName)) > 0 then MyFileName := ThisFileName
  81.   else MyFileName := ChangeFileExt(ExtractFileName(ParamStr(0)), '.log');
  82.   MyCriticalSection.Leave;
  83. end;
  84.  
  85. procedure TMPLogger.Execute;
  86. begin
  87.   while not Terminated do
  88.   begin
  89.     MyWait.WaitFor; // Suspend until there is a line waiting
  90.  
  91.     MyWait.SetEvent; // Get the syncobject
  92.     if Terminated then Break;
  93.     Log;
  94.  
  95.     MyWait.ResetEvent; // Release the syncobject
  96.   end;
  97. end;
  98.  
  99. constructor TMPLogger.Create(ThisFile: string);
  100. begin
  101.   inherited Create(True);
  102.  
  103.   MyCriticalSection := TCriticalSection.Create;
  104.   FileName := ThisFile;
  105.   MyQueue := TLogQueue.Create;
  106.   MyWait := TEvent.Create;
  107.   Start;
  108. end;
  109.  
  110. destructor TMPLogger.Destroy;
  111. begin
  112.   RTLEventDestroy(MyWait);
  113.   MyQueue.Free;
  114.   MyCriticalSection.Free;
  115.  
  116.   inherited Destroy;
  117. end;
  118.  
  119. end.
  120.  

Uses this.

Include and call LogLn when you want to write a string to the log.

Edit: I added the critical section for the filename.
« Last Edit: August 29, 2022, 12:19:09 pm by SymbolicFrank »

Martin_fr

  • Administrator
  • Hero Member
  • *
  • Posts: 9794
  • Debugger - SynEdit - and more
    • wiki
Re: Thread-safe logger
« Reply #6 on: August 29, 2022, 01:26:07 pm »
Btw, you might be able to use TLazThreadedQueue from lazcollections instead of TLogQueue.


Otherwise, you now have a separate thread just for logging.
That means, it does still carry the risk of something not being logged, albeit much smaller chance.
Unless I read something wrong:
- you add the text to the queue
- you signal the logger thread that something is there.
- you continue (i.e., the calling thread does not wait, until the logger thread has logged)

My understanding is, that if (in the small time, until the logger thread does its work) there is a fatal error and the app is terminated (shut down by OS, no waiting for threads), then the logger thread may be terminated before it logs.
Its a small chance, but it is there.

Also, you open and close the logfile each time.
So you could just but the TMPLogger.Log into a critical section and execute it within each thread.
Sure then the threads have to wait... But if you need 100% "no log lost" then the thread need to wait for the logger thread too. Otherwise the logger thread can always be force terminated while it has unlogged data.

And sorry for seemingly tearing your solution apart... But only trying to help.
There is another issue.
If I understand correctly, then "LogLn"  is called by the threads?
So it could be called by multiple threads, and you can have a race condition on "if not Assigned(GlobalMPLog) then", leading to more than one logger running.
You could instead of "GlobalMPLog := TMPLogger.Create(ThisFileName);"
do something like
Code: Pascal  [Select][+][-]
  1. if GlobalMPLog <> nil then begin // test for most cases / deal with race condition below
  2.   tmp := TMPLogger.Create(ThisFileName); // starts a new logger, even if not needed
  3.   old := InterlockCompareExchange(GlobalMPLog, tmp,nil);  // only sets the new value, if GlobalMPLog is nil / thread save
  4.   if old <> nil then   // if GlobalMPLog was not nil => clean up
  5.     tmp.free; // and shut down the thread...
  6. end;
After that use GlobalMPLog which either has the correct logger.

Your SetFilename has a critical section => so do you change the filename while the logger is running.
(and therefore only one thread at a time is allowed to set it?)
You don't use a critical section in  TMPLogger.Log when you read the filename.
AnsiStrings are in many cases threadsafe, but not always. This particular instance may not be...
Because MyFileName has a refcount of 1. (At least it could end up with that).
Then while you change it, it may be dec-refed and freed.
But in a race condition that "free" could happen while the logger-thread tries to get a inc-ref on it. The logger thread would incref a dangling pointer, and then use freed mem as the string.
IMHO its as likely as the one person winning the lottery jackpot twice in a row, but it is possible.
=> If you assign the global var (the field in the global logger counts as global) to a local var, while in a critical section, then the local var is thread save afterwards. Even if the global var is changed (and even if the global var points to the same data). This is because the local var has a ref to the string that is owned only by one thread....



Btw, the "log in critical section" exists in LazLogger, though needs some setup.
Using TLazLoggerFileHandleThreadSave gives the critical section
Using CloseLogFileBetweenWrites will ensure the file is opened and closed each time.

Martin_fr

  • Administrator
  • Hero Member
  • *
  • Posts: 9794
  • Debugger - SynEdit - and more
    • wiki
Re: Thread-safe logger
« Reply #7 on: August 29, 2022, 01:27:45 pm »
Just as a prototype typed quick, if you would declare within class and keep handle open, that could be an solution that you might like to use on windows?...
You still need critical sections when you write to that handle.
Otherwise afaik yes, but I would have to check if its documented by MS.

SymbolicFrank

  • Hero Member
  • *****
  • Posts: 1313
Re: Thread-safe logger
« Reply #8 on: August 29, 2022, 01:43:02 pm »
@Martin_fr: thanks for the feedback, I appreciate that. You're right, the initial design was to have just a single instance, with a single filename. But it's the only settable property, and only there to create a name if you don't supply one, so 'just to make sure', a critical section was called for. And then it seems to have become something you can reuse for multiple logfiles at the same time, but it lacks the mechanisms for that.

I'll change it to use the TLazThreadedQueue (I didn't know it existed). And make the filename protected. But opening the file when needed is a desirable feature to me: that way, you can have it open in a text editor (preferably one that reloads it when changed). And I wasn't planning on using multiple instances or files at the same time.

So, to make it into a full-fledged logger you can use for everything takes more work. For starters: listing the requirements. This was just something I needed and where I couldn't get the default option to work. And it's as simple as possible, but not simpler.

If I do turn it into one that takes care of everything, I'll post it here.

Edit: the TLazThreadedQueue is bound, you have to specify a length up front.
« Last Edit: August 29, 2022, 01:53:18 pm by SymbolicFrank »

Martin_fr

  • Administrator
  • Hero Member
  • *
  • Posts: 9794
  • Debugger - SynEdit - and more
    • wiki
Re: Thread-safe logger
« Reply #9 on: August 29, 2022, 02:06:45 pm »
Edit: the TLazThreadedQueue is bound, you have to specify a length up front.

But you can "Grow()" it (including negative growth), if needed.

You just subclass "PushItem". (of the FifoQueue)

Have a look al fpdebug / FpDebugUtils: TFpThreadWorkerQueue

SymbolicFrank

  • Hero Member
  • *****
  • Posts: 1313
Re: Thread-safe logger
« Reply #10 on: August 29, 2022, 02:47:36 pm »
A general question about threads: in the original POSIX model, you could create threads / processes as children or fully stand-alone, with or without shared memory. But because most OSes implemented that only partially, we are now left with the common demeanor: windows threads (children, shared memory). Although *NIXes also support 'fork', which tends to result in child processes as well.

Is it possible in Free Pascal to start a fully-independent thread? Or only processes, through the CreateProcess (or equivalent) syscalls?


But, anyway, this is taking too long, it's just a tiny part of my project. The show must go on!

PascalDragon

  • Hero Member
  • *****
  • Posts: 5448
  • Compiler Developer
Re: Thread-safe logger
« Reply #11 on: August 30, 2022, 09:11:43 am »
A general question about threads: in the original POSIX model, you could create threads / processes as children or fully stand-alone, with or without shared memory. But because most OSes implemented that only partially, we are now left with the common demeanor: windows threads (children, shared memory). Although *NIXes also support 'fork', which tends to result in child processes as well.

Is it possible in Free Pascal to start a fully-independent thread? Or only processes, through the CreateProcess (or equivalent) syscalls?

On *nix systems you can call the corresponding POSIX functions without problems. E.g. fork is available as fpFork from unit BaseUnix and on Linux you might also use clone which allows for more fine grained control and which is - at least in theory - provided in the Linux unit (however the defines are not quite correct, so you should import it directly from the C library yourself).
As soon as you don't share the address space however you have essentially two different processes and thus for synchronization you need to use IPC instead of simply e.g. TCriticalSection.

On Windows there is no real equivalent of fork as CreateProcess will always start the binary image anew (just like the combination of fork and execve that is the normal sequence to start a new process on *nix).
Note: one can achieve something similar to fork by using the base function of CreateProcess, namely NtCreateProcess, but right now I don't see a real use of it considering that this will result in a new process and processes are more heavy weight than threads (which is true for *nix as well).

marcov

  • Administrator
  • Hero Member
  • *
  • Posts: 11384
  • FPC developer.
Re: Thread-safe logger
« Reply #12 on: August 31, 2022, 10:19:50 pm »
A general question about threads: in the original POSIX model, you could create threads / processes as children or fully stand-alone, with or without shared memory. But because most OSes implemented that only partially, we are now left with the common demeanor: windows threads (children, shared memory). Although *NIXes also support 'fork', which tends to result in child processes as well.

Is it possible in Free Pascal to start a fully-independent thread? Or only processes, through the CreateProcess (or equivalent) syscalls?

On *nix systems you can call the corresponding POSIX functions without problems. E.g. fork is available as fpFork from unit BaseUnix and on Linux you might also use clone which allows for more fine grained control and which is - at least in theory - provided in the Linux unit (however the defines are not quite correct, so you should import it directly from the C library yourself).

IIRC the *BSD equivalent of clone is rfork, but both are of the "here be dragons"  category.
 
Quote
Note: one can achieve something similar to fork by using the base function of CreateProcess, namely NtCreateProcess, but right now I don't see a real use of it considering that this will result in a new process and processes are more heavy weight than threads (which is true for *nix as well).

After resp Linux 2.2/2.4 and FreeBSD 4/5. (afaik the later version implemented threads as schedulable entities, iow full M:N)

As far as replacing processes in memory, this was common in dos and specially in Basics with the chain() command? I know QB had one, maybe VB too ?

 

TinyPortal © 2005-2018