EMonitorLockException help needed

[luebbe 26]

Hi Folks,

 

in one ouf our projects I'm using @Daniele Teti 's loggerpro library (https://github.com/danieleteti/loggerpro) instead of a homebrew logging solution. A few weeks after switching to loggerpro, a first Eurekalog bug report came in with the message:
"EMonitorLockException in ThreadSafeQueueU.pas: {ThreadSafeQueueU}TThreadSafeQueue<LoggerPro.TLogItem>.Enqueue, Zeile 157 (0)". This exception is clearly raised inside loggerpro.

I have already asked at GitHub (https://github.com/danieleteti/loggerpro/issues/53), but have received no reply yet.

Every month or so, another of these bug reports comes in. The problem is:

- I cannot reproduce/trigger it on my development PC, even though I think I can locate exactly, where and under which circumstances it happens

- I don't see any obvious error in the loggerpro code

- I don't see any obvious error in my code

which is why I'm asking for help here. Maybe I have missed something obvious in my code...

We have the following scenario: The main thread starts a background task (IFuture), which builds up an index of files for later use. Both, main and background task log their status with LoggerPro.

 

The index updater:

procedure TUpdater.Update;
var
  LXxxFiles, LYyyFiles: TFileList;
begin
  if FStatus = stNotLoaded then
    begin
      Log.Debug('Renewing Index', 'INDEX');

      LXxxFiles := TFileList.Create;
      LYyyFiles := TFileList.Create;
      try
        FStatus := stLoading;

        ... Prepare XXX and YYY lists ...
        
        Log.Info('Check %d Xxx Files', [LYyyFiles.Count], 'INDEX');
        Log.Info('Check %d Yyy Files', [LXxxFiles.Count], 'INDEX');

        // Check existing files and index their content
        if FStatus <> stCanceled then
          if Process(LXxxFiles) and Process(LYyyFiles) then
            FStatus := stLoaded;

        if FAutoSave then
          FIndex.Save;

        FIndex.LogStats;
        Log.Debug('Status - ' + TRttiEnumerationType.GetName<TLoadStatus>(FStatus), 'INDEX');

      finally
        LXxxFiles.Free;
        LYyyFiles.Free;
      end;
    end;
end;

If the main task needs the index, it calls the following routine:

function TUpdater.WaitForCompletion: boolean;
begin
  Log.Enter('Updater.WaitForCompletion', 'INDEX');
  // Waits until the IFuture task is finished and returns its status
  // The calling thread is blocked while waiting
  Result := (FTask.Value = stLoaded);
  Log.Exit('Updater.WaitForCompletion', 'INDEX');
end;

Log.Enter and Log.Exit are just two wrapper functions around Log.Debug that I have added to LoggerPro. The Exception occurs on the `Log.Exit` call

 

Here are the relevant lines of the Eurekalog report:

EMonitorLockException Object lock not owned.

|005B7380|Application.exe|ThreadSafeQueueU.pas         |{ThreadSafeQueueU}TThreadSafeQueue<LoggerPro |TLogItem>.Enqueue                |157[0]   |
|005B61B5|Application.exe|LoggerPro.pas                |TLogWriter                                   |Log                              |557[5]   |
|0110346B|Application.exe|System.Generics.Defaults.pas |                                             |                                 |39[0]    |
|010FF5A2|Application.exe|Update.Index.pas             |TUpdater                                     |WaitForCompletion                |845[4]   |
|010FF560|Application.exe|Update.Index.pas             |TUpdater                                     |WaitForCompletion                |841[0]   |

Normally the update task takes some time, so the typical log output is:

2022-04-21 15:22:13:937  [TID    16780][INFO   ] [INDEX ] Updater.Update in: C:\Users\Public\Documents\#####
2022-04-21 15:22:13:937  [TID    16780][DEBUG  ] [INDEX ] --> Updater.StopUpdate
2022-04-21 15:22:13:937  [TID    16780][DEBUG  ] [INDEX ] <-- Updater.StopUpdate
2022-04-21 15:22:13:987  [TID    16780][INFO   ] [INDEX ] Contains 240 Files
2022-04-21 15:22:13:987  [TID    16780][INFO   ] [INDEX ] Contains 4931 Entries
2022-04-21 15:22:13:987  [TID     3280][DEBUG  ] [INDEX ] Renewing Index
2022-04-21 15:22:13:987  [TID    16780][DEBUG  ] [INDEX ] --> Updater.WaitForCompletion
2022-04-21 15:22:14:080  [TID     3280][INFO   ] [INDEX ] Remove 0 Files
2022-04-21 15:22:14:080  [TID     3280][INFO   ] [INDEX ] Check 238 xxx Files
2022-04-21 15:22:14:080  [TID     3280][INFO   ] [INDEX ] Check 2 yyy Files
2022-04-21 15:22:14:242  [TID     3280][INFO   ] [INDEX ] Contains 240 Files
2022-04-21 15:22:14:242  [TID     3280][INFO   ] [INDEX ] Contains 4931 Entries
2022-04-21 15:22:14:242  [TID     3280][DEBUG  ] [INDEX ] Updater.Status - stLoaded
2022-04-21 15:22:14:242  [TID    16780][DEBUG  ] [INDEX ] <-- Updater.WaitForCompletion
... Normal work continues here

 

In some cases (no search paths defined or search paths empty), there's "nothing" to do, which results in the following log output:

2022-04-21 14:18:14:972  [TID    22208][INFO   ] [INDEX ] Updater.Update in: C:\Users\Public\Documents\#####
2022-04-21 14:18:14:972  [TID    22208][DEBUG  ] [INDEX ] --> Updater.StopUpdate
2022-04-21 14:18:14:972  [TID    22208][DEBUG  ] [INDEX ] <-- Updater.StopUpdate
2022-04-21 14:18:14:973  [TID    22208][INFO   ] [INDEX ] Contains 0 Files
2022-04-21 14:18:14:973  [TID    22208][INFO   ] [INDEX ] Contains 0 Entries
2022-04-21 14:18:14:974  [TID    14984][DEBUG  ] [INDEX ] Renewing Index
2022-04-21 14:18:14:974  [TID    14984][INFO   ] [INDEX ] Remove 0 Files
2022-04-21 14:18:14:974  [TID    14984][INFO   ] [INDEX ] Check 0 xxx Files
2022-04-21 14:18:14:974  [TID    14984][INFO   ] [INDEX ] Check 0 yyy Files
2022-04-21 14:18:14:977  [TID    14984][INFO   ] [INDEX ] Contains 0 Files
2022-04-21 14:18:14:977  [TID    14984][INFO   ] [INDEX ] Contains 0 Entries
2022-04-21 14:18:14:977  [TID    14984][DEBUG  ] [INDEX ] Updater.Status - stLoaded
2022-04-21 14:18:14:979  [TID    22208][DEBUG  ] [INDEX ] --> Updater.WaitForCompletion
2022-04-21 14:18:14:979  [TID    22208][DEBUG  ] [INDEX ] <-- Updater.WaitForCompletion
... Normal work continues here

Note that in this case the updater was finished (stLoaded) before WaitForCompletion was called. The Log.Enter "--> Updater.WaitforCompletion" line may occur anywhere between the lines of the background thread (TID 14984 in this case).

This is the LoggerPro output matching the bug report. The `EMonitorLockException` occured on the `Log.Exit` call in `TUpdater.WaitForCompletion` and this line is missing from the log:

2022-04-21 14:42:03:003  [TID    20620][INFO   ] [INDEX ] Updater.Update in: C:\Users\Public\Documents\#####
2022-04-21 14:42:03:003  [TID    20620][DEBUG  ] [INDEX ] --> Updater.StopUpdate
2022-04-21 14:42:03:003  [TID    20620][DEBUG  ] [INDEX ] <-- Updater.StopUpdate
2022-04-21 14:42:03:004  [TID    20620][INFO   ] [INDEX ] Contains 0 Files
2022-04-21 14:42:03:004  [TID    20620][INFO   ] [INDEX ] Contains 0 Entries
2022-04-21 14:42:03:004  [TID     3312][DEBUG  ] [INDEX ] Renewing Index
2022-04-21 14:42:03:004  [TID     3312][INFO   ] [INDEX ] Remove 0 Files
2022-04-21 14:42:03:004  [TID     3312][INFO   ] [INDEX ] Check 0 xxx Files
2022-04-21 14:42:03:004  [TID     3312][INFO   ] [INDEX ] Check 0 yyy Files
2022-04-21 14:42:03:008  [TID    20620][DEBUG  ] [INDEX ] --> Updater.WaitForCompletion
2022-04-21 14:42:03:008  [TID     3312][INFO   ] [INDEX ] Contains 0 Files
2022-04-21 14:42:03:008  [TID     3312][INFO   ] [INDEX ] Contains 0 Entries
2022-04-21 14:42:03:008  [TID     3312][DEBUG  ] [INDEX ] Updater.Status - stLoaded
... Normal work continues here

Note that the updater was still working (on nothing ;-)) when WaitForCompletion was called. It looks like Log.Exit('WaitForCompletion') and Log.Debug('Updater.Status - stLoaded') happen in the same millisecond, so I assume that thread 3312 still held the lock, when exception thread 20620 called `Log.Exit`.

But I see this all the time (finish/exit happens in the sme millisecond) when I run the code on my PC and never get an EMonitorLock exception.

 

Is there something we are doing wrong or have we come across a race condition in LoggerPro or the Delphi locking implementation?

 

 

 

[PeterBelow 238]

5 hours ago, luebbe said:

TUpdater.WaitForCompletion

As far as I can see this function does not wait at all, it just checks the task value and returns. Or does the getter for FTask.Value wait?

[Stefan Glienke 1998]

The Eurekalog call stack makes zero sense compared to the code on github. Either you are using some outdated code or modified something yourself. There is nothing monitor in TThreadSafeQueue.Enqueue. It is using a critical section

[luebbe 26]

15 hours ago, PeterBelow said:

As far as I can see this function does not wait at all, it just checks the task value and returns. Or does the getter for FTask.Value wait?

FTask is an IFuture, so yes, it should wait. I just mentioned this fact but didn't show any code. Here it is:

 

procedure TUpdater.UpdateIndex(const ASearchPathList: string; AForceUpdate: boolean);
begin

  ... cancel running tasks etc ...
  
  FTask := TTask.Future<TLoadStatus>(
    function: TLoadStatus
    begin
      Update;
      Result := FStatus;
    end);
end;

 

[luebbe 26]

7 hours ago, Stefan Glienke said:

The Eurekalog call stack makes zero sense compared to the code on github. Either you are using some outdated code or modified something yourself. There is nothing monitor in TThreadSafeQueue.Enqueue. It is using a critical section

You're right, the call stack doesn't make sense. I'm using my own fork of loggerpro (https://github.com/luebbe/loggerpro.git) and made two PRs with additional functionality in the original, but I didn't modify any of the queuing code.

We're using a very old version (6.x) of Eurekalog. Perhaps this is reason for the wrong stack trace, but still I wouldn't expect any exception to happen here.

[Stefan Glienke 1998]

My point is that posting a red herring won't get you much help. First task should be to get a proper call stack because that will directly point you to the source location that causes it without the need to poke in the dark hoping to find it.

The exception is clear and this happens when a monitor lock is being exited or waited on from a different thread than the one that entered it.

[luebbe 26]

Got the point, thanks 🙂 I was missing the obvious part that the call stack doesn't make sense. Been digging through the RTL to find out when a EMonitorlock Exception would be raised.

[Stefan Glienke 1998]

10 minutes ago, luebbe said:

Been digging through the RTL to find out when a EMonitorlock Exception would be raised.

Only from TMonitor.CheckOwningThread (indirectly via the lookup mechanism from ErrorProc in ErrorAt) which gets called from two places: TMonitor.Exit and TMonitor.Wait.

Edited June 21, 2022 by Stefan Glienke