diff --git a/src/Umbraco.Cms.Persistence.Sqlite/Services/SqliteDistributedLockingMechanism.cs b/src/Umbraco.Cms.Persistence.Sqlite/Services/SqliteDistributedLockingMechanism.cs index 646bc3107c..4a47d41846 100644 --- a/src/Umbraco.Cms.Persistence.Sqlite/Services/SqliteDistributedLockingMechanism.cs +++ b/src/Umbraco.Cms.Persistence.Sqlite/Services/SqliteDistributedLockingMechanism.cs @@ -4,6 +4,7 @@ using Microsoft.Data.SqlClient; using Microsoft.Data.Sqlite; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Options; +using Umbraco.Cms.Core; using Umbraco.Cms.Core.Configuration.Models; using Umbraco.Cms.Core.DistributedLocking; using Umbraco.Cms.Core.DistributedLocking.Exceptions; @@ -147,7 +148,9 @@ public class SqliteDistributedLockingMechanism : IDistributedLockingMechanism DbCommand command = db.CreateCommand(db.Connection, CommandType.Text, query); // imagine there is an existing writer, whilst elapsed time is < command timeout sqlite will busy loop - command.CommandTimeout = _timeout.Seconds; + // Important to note that if this value == 0 then Command.DefaultTimeout (30s) is used. + // Math.Ceiling such that (0 < totalseconds < 1) is rounded up to 1. + command.CommandTimeout = (int)Math.Ceiling(_timeout.TotalSeconds); try { diff --git a/tests/Umbraco.Tests.Integration/TestServerTest/UmbracoTestServerTestBase.cs b/tests/Umbraco.Tests.Integration/TestServerTest/UmbracoTestServerTestBase.cs index 3c0e0aeb81..e25438b03b 100644 --- a/tests/Umbraco.Tests.Integration/TestServerTest/UmbracoTestServerTestBase.cs +++ b/tests/Umbraco.Tests.Integration/TestServerTest/UmbracoTestServerTestBase.cs @@ -153,6 +153,7 @@ namespace Umbraco.Cms.Tests.Integration.TestServerTest ConfigureServices(services); ConfigureTestServices(services); + services.AddUnique(CreateLoggerFactory()); if (!TestOptions.Boot) { @@ -184,7 +185,6 @@ namespace Umbraco.Cms.Tests.Integration.TestServerTest protected void ConfigureServices(IServiceCollection services) { - services.AddUnique(CreateLoggerFactory()); services.AddTransient(); Core.Hosting.IHostingEnvironment hostingEnvironment = TestHelper.GetHostingEnvironment(); diff --git a/tests/Umbraco.Tests.Integration/Testing/UmbracoIntegrationTest.cs b/tests/Umbraco.Tests.Integration/Testing/UmbracoIntegrationTest.cs index 2fd07b131d..b11b7ea074 100644 --- a/tests/Umbraco.Tests.Integration/Testing/UmbracoIntegrationTest.cs +++ b/tests/Umbraco.Tests.Integration/Testing/UmbracoIntegrationTest.cs @@ -84,6 +84,7 @@ namespace Umbraco.Cms.Tests.Integration.Testing { ConfigureServices(services); ConfigureTestServices(services); + services.AddUnique(CreateLoggerFactory()); if (!TestOptions.Boot) { @@ -98,7 +99,6 @@ namespace Umbraco.Cms.Tests.Integration.Testing protected void ConfigureServices(IServiceCollection services) { - services.AddUnique(CreateLoggerFactory()); services.AddTransient(); IWebHostEnvironment webHostEnvironment = TestHelper.GetWebHostEnvironment(); services.AddRequiredNetCoreServices(TestHelper, webHostEnvironment); diff --git a/tests/Umbraco.Tests.Integration/Testing/UmbracoIntegrationTestBase.cs b/tests/Umbraco.Tests.Integration/Testing/UmbracoIntegrationTestBase.cs index 237bf87daa..0b4082e425 100644 --- a/tests/Umbraco.Tests.Integration/Testing/UmbracoIntegrationTestBase.cs +++ b/tests/Umbraco.Tests.Integration/Testing/UmbracoIntegrationTestBase.cs @@ -8,6 +8,7 @@ using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Logging.Console; using Microsoft.Extensions.Options; using NUnit.Framework; using Serilog; @@ -93,12 +94,17 @@ public abstract class UmbracoIntegrationTestBase Log.Logger = new LoggerConfiguration() .WriteTo.File(path, rollingInterval: RollingInterval.Day) .MinimumLevel.Debug() + .ReadFrom.Configuration(Configuration) .CreateLogger(); builder.AddSerilog(Log.Logger); }); case UmbracoTestOptions.Logger.Console: - return LoggerFactory.Create(builder => builder.AddConsole().SetMinimumLevel(LogLevel.Debug)); + return LoggerFactory.Create(builder => + { + builder.AddConfiguration(Configuration.GetSection("Logging")) + .AddConsole(); + }); } } catch diff --git a/tests/Umbraco.Tests.Integration/Umbraco.Infrastructure/Persistence/LocksTests.cs b/tests/Umbraco.Tests.Integration/Umbraco.Infrastructure/Persistence/LocksTests.cs index 1214098915..d146729e48 100644 --- a/tests/Umbraco.Tests.Integration/Umbraco.Infrastructure/Persistence/LocksTests.cs +++ b/tests/Umbraco.Tests.Integration/Umbraco.Infrastructure/Persistence/LocksTests.cs @@ -5,10 +5,13 @@ using System.Text; using System.Threading; using System.Threading.Tasks; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; using NPoco; using NUnit.Framework; +using Serilog; using Umbraco.Cms.Core; using Umbraco.Cms.Core.DistributedLocking.Exceptions; +using Umbraco.Cms.Core.Scoping; using Umbraco.Cms.Infrastructure.Persistence.Dtos; using Umbraco.Cms.Persistence.Sqlite.Interceptors; using Umbraco.Cms.Tests.Common.Testing; @@ -425,40 +428,66 @@ namespace Umbraco.Cms.Tests.Integration.Umbraco.Infrastructure.Persistence [Test] public void Throws_When_Lock_Timeout_Is_Exceeded_Write() { + var counter = 0; + var gate = new ManualResetEventSlim(false); + var logger = GetRequiredService>(); + using (ExecutionContext.SuppressFlow()) { var t1 = Task.Run(() => { - using (var scope = ScopeProvider.CreateScope()) + using var scope = ScopeProvider.CreateScope(); + + _ = (scope as Scope)?.Database; // Begin transaction + Interlocked.Increment(ref counter); + gate.Wait(); + + logger.LogInformation("t1 - Attempting to acquire write lock"); + Assert.DoesNotThrow(() => { - - Console.WriteLine("Write lock A"); + // ReSharper disable once AccessToDisposedClosure // This will acquire right away - scope.EagerWriteLock(TimeSpan.FromMilliseconds(2000), Constants.Locks.ContentTree); - Thread.Sleep(6000); // Wait longer than the Read Lock B timeout - scope.Complete(); - Console.WriteLine("Finished Write lock A"); - } - }); + scope.EagerWriteLock(TimeSpan.FromMilliseconds(1000), Constants.Locks.ContentTree); + }); - Thread.Sleep(500); // 100% sure task 1 starts first + logger.LogInformation("t1 - Acquired write lock, sleeping"); + Thread.Sleep(1500); // Wait longer than the Read Lock B timeout + + scope.Complete(); + logger.LogInformation("t1 - Complete transaction"); + }); var t2 = Task.Run(() => { - using (var scope = ScopeProvider.CreateScope()) + using var scope = ScopeProvider.CreateScope(); + + _ = (scope as Scope)?.Database; // Begin transaction + Interlocked.Increment(ref counter); + gate.Wait(); + Thread.Sleep(100); // Let other transaction obtain write lock first. + + logger.LogInformation("t2 - Attempting to acquire write lock"); + var ex = Assert.Throws(() => { - Console.WriteLine("Write lock B"); + // ReSharper disable once AccessToDisposedClosure + scope.EagerWriteLock(TimeSpan.FromMilliseconds(1000), Constants.Locks.ContentTree); + logger.LogInformation("t2 - Acquired write lock, something has gone wrong."); + }); - // This will wait for the write lock to release but it isn't going to wait long - // enough so an exception will be thrown. - Assert.Throws(() => - scope.EagerWriteLock(TimeSpan.FromMilliseconds(3000), Constants.Locks.ContentTree)); - - scope.Complete(); - Console.WriteLine("Finished Write lock B"); + if (ex != null) + { + logger.LogInformation("t2 - Failed to acquire write lock in time, all is well."); } + + scope.Complete(); }); + while (counter < 2) + { + Thread.Sleep(10); + } + + gate.Set(); Task.WaitAll(t1, t2); } } diff --git a/tests/Umbraco.Tests.Integration/appsettings.Tests.json b/tests/Umbraco.Tests.Integration/appsettings.Tests.json index 8580268550..101b1a1aef 100644 --- a/tests/Umbraco.Tests.Integration/appsettings.Tests.json +++ b/tests/Umbraco.Tests.Integration/appsettings.Tests.json @@ -1,4 +1,13 @@ { + "Logging": { + "LogLevel": { + "Default": "Warning", + "Umbraco.Cms.Tests": "Information" + }, + "Console": { + "DisableColors": true + } + }, "Tests": { "Database": { "DatabaseType": "SQLite",