Update DistributedLockService.cs by imranazad · Pull Request #8398 · OrchardCMS/Orchard

imranazad · 2020-06-30T21:38:56Z

jtkech · 2020-07-01T01:54:08Z

As said i would need to focus more on it and try it, but i trust you and you will be able to try it ;)

First, in the context of the related issue where it is called by the audit trail bg task we have maxValidFor = 1 hour, timeout = TimeSpan.Zero, and as it is done trhough TryAcquireLock(), we have throwOnTimeout = false.

I don't think that doing Monitor.Exit() in the context of the RepeatUntilTimeout() (here executed once as timeout = TimeSpan.Zero) is the right place, i think it needs to be fixed after in the if (!success) { block. If throwOnTimeout is true we throw an exception so we go to the enclosing catch that does a Monitor.Exit() so that's okay, but if throwOnTimeout is false, as in your case and i think this is the path that we missed, we still need to do explicitly a Monitor.Exit().

Could you try it?

Note: Maybe an little issue with the record ValidUntilUtc (here 1 hour), as i can see it may expire while it is still in use ...

jtkech · 2020-07-01T02:29:26Z

So maybe we only need to add the 2 lines below

if (!success) {
    Logger.Debug("Record for lock '{0}' could not be created for current machine within the specified timeout ({1}).", internalName, timeout);

    if (throwOnTimeout)
        throw new TimeoutException(String.Format("Failed to acquire lock '{0}' within the specified timeout ({1}).", internalName, timeout));
    else // here the 2 added lines
        Monitor.Exit(monitorObj);

    return null;
}

imranazad · 2020-07-01T12:07:48Z

Haha @jtkech thank you for having faith in me! :-) I wasn't happy with my proposed fix as I knew something was off about it. Your suggestion works a treat! And I can confirm the lock is now released! :-)

I tested it albeit manually:

I ran the task and hit a break point here:

Orchard/src/Orchard/Tasks/Locking/Services/DistributedLockService.cs

Line 144 in 5b5eda6

var records = repository.Table.Where(x => x.Name == internalName).ToList();
I then inserted the following record:

  INSERT INTO  [Orchard_Framework_DistributedLockRecord] (
      [Name]
      ,[MachineName]
      ,[CreatedUtc]
      ,[ValidUntilUtc]
	  ) VALUES ('DistributedLock:Default:Orchard.AuditTrail.Services.AuditTrailTrimmingBackgroundTask', 'IMT-000', '2001-03-20 18:45:12.000', '2020-07-01 21:55:12.000')

I then continued execution from the break point which led to this line which returns false

Orchard/src/Orchard/Tasks/Locking/Services/DistributedLockService.cs

Line 177 in 5b5eda6

return hasLockRecord;
I then further continued execution until it hit the new else statement to exit the lock: https://github.com/OrchardCMS/Orchard/pull/8398/files#diff-f5d641271fe12d6f2c0f9373dc2c7786R123
I then waited for the task to run again and then hit a break point on this line to ensure and verify the lock enters successfully and that the previous lock was indeed exited:

Orchard/src/Orchard/Tasks/Locking/Services/DistributedLockService.cs

Line 77 in 5b5eda6

if (!Monitor.TryEnter(monitorObj, monitorTimeout)) {

One additional change I have made is to change the log level from warning to debug for this line otherwise despite the fix this error will keep being logged as the lock will still return null where another machine has acquired a lock on the same task: https://github.com/OrchardCMS/Orchard/pull/8398/files#diff-f5d641271fe12d6f2c0f9373dc2c7786L49

Please do let me know your thoughts. If you're happy with the changes can you please do the honours of a code review and approve them and then I'll ask @sebastienros if he is happy to merge in as we are keen to get this change released for our live systems as we're being inundated with these log messages.

Many thanks

jtkech · 2020-07-02T01:31:19Z

@imranazad okay cool

So, as a reminder, the issue was that if we can't acquire a lock in a given timeout, if throwOnTimeout is true the lock is freed by a Monitor.Exit() called by the enclosing catch, but if throwOnTimeout is false the lock was not freed. So subsequent Monitor.TryEnter() were always returning false.

So with this fix, normally you will have a lot less logged warnings, but when used in the context of TryAcquireLock() and, as with the audit trail bg task, with a timeout = TimeSpan.Zero you will still have some warnings messages, in fact each time the lock is doing its job.

So i agree, in the context of TryAcquireLock() we can use Logger.Debug() in place of Logger.Warning().

imranazad · 2020-07-02T07:56:27Z

@imranazad okay cool

So, as a reminder, the issue was that if we can't acquire a lock in a given timeout, if throwOnTimeout is true the lock is freed by a Monitor.Exit() called by the enclosing catch, but if throwOnTimeout is false the lock was not freed. So subsequent Monitor.TryEnter() were always returning false.

So with this fix, normally you will have a lot less logged warnings, but when used in the context of TryAcquireLock() and, as with the audit trail bg task, with a timeout = TimeSpan.Zero you will still have some warnings messages, in fact each time the lock is doing its job.

So i agree, in the context of TryAcquireLock() we can use Logger.Debug() in place of Logger.Warning().

@jtkech yep that is spot on and thanks for the prompt response.

Regarding

Maybe an little issue with the record ValidUntilUtc (here 1 hour), as i can see it may expire while it is still in use

That's a good point, I didn't get a chance to test this - I've acknowledged it here maybe someone else reading this can volunteer to take a look at it as a separate issue.

@sebastienros could you please take a look at merging this in?

sebastienros · 2020-07-02T17:06:46Z

                            throw new TimeoutException(String.Format("Failed to acquire lock '{0}' within the specified timeout ({1}).", internalName, timeout));
-
+                        else
+                            Monitor.Exit(monitorObj);


Shouldn't it be released even if throwOnTimeout is true?

@sebastienros the enclosing catch releases it further below see here:

Orchard/src/Orchard/Tasks/Locking/Services/DistributedLockService.cs

Line 133 in af0f715

Monitor.Exit(monitorObj);

@sebastienros yes, when an exception is thrown, explicitly or not, this is the enclosing catch that does a Monitor.Exit(), so we should not do it before if throwOnTimeout is true as we throw explicitly an exception, but we should do it if throwOnTimeout is false, i think we missed this path when the throwOnTimeout option has been added

@sebastienros

* Added tokenizable default value to ContentPickerFields (#8351) * Fixes errors during Indexing (#8349) * Added admin search permissions (#8346) * Reuse Settings_ShellDescriptorRecord during an http request (#8355) * Added a new index to CommonPartRecord (#8362) * Attempted AutoroutePart improvement (#8360) This should ease Database issues, because it short circuits some code paths through aliases. * Save MemberBindingRecords in memory (#8371) Prevent fetching the same table from the database 5+ times per request by loading it and saving it in a private property for a request. * Cache list of configured layers (#8373) On every page load on frontend we were querying for all existing layers to test for the ones that are currently active. Since that information is not bound to change often, we added a cache layer to prevent querying every time. The cache is evicted whenever a Layer gets updated. * Memorize query results in blog service (#8374) The query for all published blogs is being called twice while building the admin menu, so we are memorizing its results. * Updated UI for projections (#8380) Some textboxes were too small for the actual text users would generally write in them. Those meant to hold HTML have been converted to textareas. * Process ignored paths while being aware of RequestUrlPrefix (#8384) * Process ignored paths while being aware of RequestUrlPrefix * Fix: I had moved a Trim to the wrong place * Fixed issue with empty/uninitialized null set of ignored urls * tokens sort criteria (#8382) * Tokenized state for sort criteria * Tokenized state also in the other place where sort criteria are used * Remove lock from the dictionary when the task has completed. (#8395) Fixes #8391 * Update DistributedLockService.cs (#8398) * fix for CPF when other scripts are also adding to sessionStorage (#8404) * Fixes Boolean Conversion error (#8393) * Fix/8392 remeber me model state exception (#8410) @sebastienros this fixes the possible NRE that would happen for absent models from merged #8393 (see your comment there #8393 (comment)) * Removed changes to model bindings (#8412) This is the same as reverting 1.10.x to commit 868ce12 * New version of Boolean Binder Provider (#8413) * New version of Boolean Binder Provider * Use Convert.ToBoolean(string) rather than ValueProviderResult.ConvertTo(bool) * Upgrade host resolution (#8387) * Reverted changes to RunningShellTable and then changed the way shells are sorted, so we can correctly give "priority" to tenants based on their prefix. Added test adapter reference to Orchard.Framework.Tests so tests can be run in the latest VS 2017. Fixed a test that was failing to account for the order the shells were being processed. * Removed some stuff from csproj that vs had added * Handle the case where a form sends more than one attempted value for a boolean (#8416) * fix record mapping nhibernate (#8415) * Allow downstream methods to set default value (#8419) Moreover, this won't try to set a default value to the bool when it's not sent. This will allow calls with missing required parameters to fail as they should. * Fixed Media Library Picker Style (#8433) * Removed check preventing reassignment of loader delegates (#8436) * Added an event activity for workflows that activates on the first Upd… (#8438) * target framework 4.8 to all projects (#8444) * Feature/8445 libraries update (#8446) * Fixed conflict with style for layouts (#8456) the .overlay is used for different things in MediaLibraryPickerField and Layouts, and as it was the styles would conflict. This should fix it. * Feature/upgradable libraries (#8457) * Updated Migration for CommonPartRecord and IdentityPartRecord (#8459) This orders the operations differently than what is in dev for retrocompatibility in both environments. * Prevents throwing exception when Href is null (#8461) * added culture in widgets page (#8466) * added culture in widgets page Co-authored-by: elena.lampugnani <[email protected]> Co-authored-by: Hermes Sbicego <[email protected]> * Show disable action for deprecated features even if they are categorized as "Core" (#8468) * Upgrades YamlDotNet from 9.1.3 to 11.1.1 because 9.1.3 is not more available as nuget package (#8472) * Bypass cache for XSRF Tokens (#8470) Fixes #8469 * flag exclude children for taxonomies (#8481) * Remove cache by tag on Unpublished (#8483) As it was, cached lists/projections would not be evicted when a ContentItem they contained was unpublished. * Cloning doesn't overwrite identity (#8487) Fixes #8486 * Update nhibernate (#8488) * Update nHibernate to version 4.1.2.4000 # Conflicts: # src/Orchard.Web/Modules/Orchard.ContentPicker/packages.config # src/Orchard.Web/Modules/Orchard.ImportExport/packages.config # src/Orchard.Web/Modules/Orchard.MessageBus/packages.config # src/Orchard.Web/Modules/Orchard.MultiTenancy/packages.config # src/Orchard.Web/Modules/Orchard.Projections/packages.config # src/Orchard.Web/Modules/Orchard.Tags/packages.config # src/Orchard.Web/Modules/Upgrade/packages.config # src/Orchard.Web/Web.config * Update AssemblyBindings for NHibernate * Fixes disposed LifetimeScope issue (#8490) * fixed scope in in recomputing the context to figure out whether an antiforgery token needs replacing * Revert "Cloning doesn't overwrite identity (#8487)" (#8495) This reverts commit af42947. * Remove whitespace when importing list of permissions (#8499) Similarly to what's already being done when we import features. this allows to go to a new line in the xml that we import, and even tabulate for readability and maintenance. * Force enumeration of list of permissions. Without this, imported permissions (#8492) would always replace existing ones: i.e. if an existing permission is not in the list being imported it would be removed for the role. * Projection default settings (#8497) * added settings in projection part * read settings into driver * commit files setting * add logic of filter query * added logic of filter query setting * managed import/export * fixed migration * added message information Co-authored-by: elena.lampugnani <[email protected]> * HtmlDecode token (#8501) Added HtmlDecode token management. Needed for #8500 * Sets SSL redirection as permanent for SEO reasons (#8503) Fixes #8502 * Added null checks (#8511) The added null checks manage properly importing definitions that do not contain the properties. * Fix/editmenulink (#8515) * Removed useless spaces * Corrections on ProjectionPart query link (it didn't update the link when changing the selected query). Added edit link for menu in MenuWidget. * Added menuId parameter to menu edit link * Fixed various typos: (#8512) * Added descriptor to audit trail context (#8517) Co-authored-by: Hermes Sbicego <[email protected]> Co-authored-by: Imran Azad <[email protected]> Co-authored-by: LorenzoFrediani-Laser <[email protected]> Co-authored-by: ElenaRepository <[email protected]> Co-authored-by: Andrea Piovanelli <[email protected]>

Update DistributedLockService.cs

96625b9

imranazad mentioned this pull request Jun 30, 2020

Continuous lock in multi-server setup causes "Failed to acquire lock" error #8399

Closed

Update DistributedLockService.cs

ec2c890

Update DistributedLockService.cs

af0f715

jtkech approved these changes Jul 2, 2020

View reviewed changes

sebastienros reviewed Jul 2, 2020

View reviewed changes

sebastienros merged commit c622031 into OrchardCMS:1.10.x Jul 9, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Update DistributedLockService.cs#8398

Update DistributedLockService.cs#8398
sebastienros merged 3 commits into
OrchardCMS:1.10.xfrom
imranazad:patch-1

imranazad commented Jun 30, 2020 •

edited

Loading

Uh oh!

jtkech commented Jul 1, 2020

Uh oh!

jtkech commented Jul 1, 2020

Uh oh!

imranazad commented Jul 1, 2020 •

edited

Loading

Uh oh!

jtkech commented Jul 2, 2020

Uh oh!

imranazad commented Jul 2, 2020 •

edited

Loading

Uh oh!

sebastienros Jul 2, 2020

Uh oh!

imranazad Jul 2, 2020

Uh oh!

jtkech Jul 2, 2020

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Uh oh!

Conversation

imranazad commented Jun 30, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jtkech commented Jul 1, 2020

Uh oh!

jtkech commented Jul 1, 2020

Uh oh!

imranazad commented Jul 1, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jtkech commented Jul 2, 2020

Uh oh!

imranazad commented Jul 2, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

sebastienros Jul 2, 2020

Choose a reason for hiding this comment

Uh oh!

imranazad Jul 2, 2020

Choose a reason for hiding this comment

Uh oh!

jtkech Jul 2, 2020

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

imranazad commented Jun 30, 2020 •

edited

Loading

imranazad commented Jul 1, 2020 •

edited

Loading

imranazad commented Jul 2, 2020 •

edited

Loading