luebbe 26 Posted June 20, 2022 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? Share this post Link to post
PeterBelow 238 Posted June 20, 2022 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? Share this post Link to post
Stefan Glienke 2002 Posted June 20, 2022 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 Share this post Link to post
luebbe 26 Posted June 21, 2022 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; Share this post Link to post
luebbe 26 Posted June 21, 2022 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. Share this post Link to post
Stefan Glienke 2002 Posted June 21, 2022 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. Share this post Link to post
luebbe 26 Posted June 21, 2022 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. Share this post Link to post
Stefan Glienke 2002 Posted June 21, 2022 (edited) 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 1 Share this post Link to post