v6.11.3: Add a bunch of logging to config writing and semaphore usage

build/Version.props

@@ -3,7 +3,7 @@
   <!-- Integration tests will ensure they match across the board -->
   <Import Project="WebpanelVersion.props" />
   <PropertyGroup>
-    <TgsCoreVersion>6.11.2</TgsCoreVersion>
+    <TgsCoreVersion>6.11.3</TgsCoreVersion>
     <TgsConfigVersion>5.3.0</TgsConfigVersion>
     <TgsRestVersion>10.10.0</TgsRestVersion>
     <TgsGraphQLVersion>0.2.0</TgsGraphQLVersion>

src/Tgstation.Server.Host/Components/StaticFiles/Configuration.cs

@@ -185,7 +185,7 @@ public Configuration(
 			this.generalConfiguration = generalConfiguration ?? throw new ArgumentNullException(nameof(generalConfiguration));
 			this.sessionConfiguration = sessionConfiguration ?? throw new ArgumentNullException(nameof(sessionConfiguration));
 
-			semaphore = new SemaphoreSlim(1);
+			semaphore = new SemaphoreSlim(1, 1);
 			disposeCts = new CancellationTokenSource();
 			uploadTasks = Task.CompletedTask;
 		}
@@ -201,7 +201,7 @@ public void Dispose()
 		/// <inheritdoc />
 		public async ValueTask<ServerSideModifications?> CopyDMFilesTo(string dmeFile, string destination, CancellationToken cancellationToken)
 		{
-			using (await SemaphoreSlimContext.Lock(semaphore, cancellationToken))
+			using (await SemaphoreSlimContext.Lock(semaphore, cancellationToken, logger))
 			{
 				var ensureDirectoriesTask = EnsureDirectories(cancellationToken);
 
@@ -270,7 +270,7 @@ void ListImpl()
 				}));
 			}
 
-			using (SemaphoreSlimContext.TryLock(semaphore, out var locked))
+			using (SemaphoreSlimContext.TryLock(semaphore, logger, out var locked))
 			{
 				if (!locked)
 				{
@@ -376,7 +376,7 @@ void GetFileStream()
 				}
 			}
 
-			using (SemaphoreSlimContext.TryLock(semaphore, out var locked))
+			using (SemaphoreSlimContext.TryLock(semaphore, logger, out var locked))
 			{
 				if (!locked)
 				{
@@ -434,7 +434,7 @@ await ValueTaskExtensions.WhenAll(entries.Select<string, ValueTask>(async file =
 				}));
 			}
 
-			using (await SemaphoreSlimContext.Lock(semaphore, cancellationToken))
+			using (await SemaphoreSlimContext.Lock(semaphore, cancellationToken, logger))
 			{
 				await EnsureDirectories(cancellationToken);
 				var ignoreFileBytes = await ioManager.ReadAllBytes(StaticIgnorePath(), cancellationToken);
@@ -501,14 +501,15 @@ void WriteCallback()
 								return;
 							}
 
-							using (SemaphoreSlimContext.TryLock(semaphore, out var locked))
+							using (SemaphoreSlimContext.TryLock(semaphore, logger, out var locked))
 							{
 								if (!locked)
 								{
 									fileTicket.SetError(ErrorCode.ConfigurationContendedAccess, null);
 									return;
 								}
 
+								logger.LogTrace("Kicking off write callback");
 								if (systemIdentity == null)
 									await Task.Factory.StartNew(WriteCallback, cancellationToken, DefaultIOManager.BlockingTaskCreationOptions, TaskScheduler.Current);
 								else
@@ -519,6 +520,8 @@ void WriteCallback()
 								fileTicket.SetError(ErrorCode.ConfigurationFileUpdated, fileHash);
 							else if (uploadStream.Length > 0)
 								postWriteHandler.HandleWrite(path);
+							else
+								logger.LogTrace("Write complete");
 						}
 					}
 
@@ -559,7 +562,7 @@ void WriteCallback()
 				}
 			}
 
-			using (SemaphoreSlimContext.TryLock(semaphore, out var locked))
+			using (SemaphoreSlimContext.TryLock(semaphore, logger, out var locked))
 			{
 				if (!locked)
 				{
@@ -585,7 +588,7 @@ void WriteCallback()
 			bool? result = null;
 			void DoCreate() => result = synchronousIOManager.CreateDirectory(path, cancellationToken);
 
-			using (SemaphoreSlimContext.TryLock(semaphore, out var locked))
+			using (SemaphoreSlimContext.TryLock(semaphore, logger, out var locked))
 			{
 				if (!locked)
 				{
@@ -651,7 +654,7 @@ public ValueTask HandleEvent(EventType eventType, IEnumerable<string?> parameter
 			var path = ValidateConfigRelativePath(configurationRelativePath);
 
 			var result = false;
-			using (SemaphoreSlimContext.TryLock(semaphore, out var locked))
+			using (SemaphoreSlimContext.TryLock(semaphore, logger, out var locked))
 			{
 				if (!locked)
 				{
@@ -750,7 +753,7 @@ async ValueTask ExecuteEventScripts(IEnumerable<string?> parameters, bool deploy
 			await EnsureDirectories(cancellationToken);
 
 			// always execute in serial
-			using (await SemaphoreSlimContext.Lock(semaphore, cancellationToken))
+			using (await SemaphoreSlimContext.Lock(semaphore, cancellationToken, logger))
 			{
 				var files = await ioManager.GetFilesWithExtension(EventScriptsSubdirectory, platformIdentifier.ScriptFileExtension, false, cancellationToken);
 				var resolvedScriptsDir = ioManager.ResolvePath(EventScriptsSubdirectory);

src/Tgstation.Server.Host/Utils/SemaphoreSlimContext.cs

@@ -2,6 +2,8 @@
 using System.Threading;
 using System.Threading.Tasks;
 
+using Microsoft.Extensions.Logging;
+
 namespace Tgstation.Server.Host.Utils
 {
 	/// <summary>
@@ -14,29 +16,39 @@ sealed class SemaphoreSlimContext : IDisposable
 		/// </summary>
 		/// <param name="semaphore">The <see cref="SemaphoreSlim"/> to lock.</param>
 		/// <param name="cancellationToken">The <see cref="CancellationToken"/> for the operation.</param>
+		/// <param name="logger">An optional <see cref="ILogger"/> to write to.</param>
 		/// <returns>A <see cref="Task{TResult}"/> resulting in the <see cref="SemaphoreSlimContext"/> for the lock.</returns>
-		public static async ValueTask<SemaphoreSlimContext> Lock(SemaphoreSlim semaphore, CancellationToken cancellationToken)
+		public static async ValueTask<SemaphoreSlimContext> Lock(SemaphoreSlim semaphore, CancellationToken cancellationToken, ILogger? logger = null)
 		{
 			ArgumentNullException.ThrowIfNull(semaphore);
+			logger?.LogTrace("Acquiring semaphore...");
 			await semaphore.WaitAsync(cancellationToken);
-			return new SemaphoreSlimContext(semaphore);
+			return new SemaphoreSlimContext(semaphore, logger);
 		}
 
 		/// <summary>
 		/// Asyncronously attempts to lock a <paramref name="semaphore"/>.
 		/// </summary>
 		/// <param name="semaphore">The <see cref="SemaphoreSlim"/> to lock.</param>
+		/// <param name="logger">An optional <see cref="ILogger"/> to write to.</param>
 		/// <param name="locked">The <see cref="bool"/> result of the lock attempt.</param>
 		/// <returns>A <see cref="SemaphoreSlimContext"/> for the lock on success, or <see langword="null"/> if it was not acquired.</returns>
-		public static SemaphoreSlimContext? TryLock(SemaphoreSlim semaphore, out bool locked)
+		public static SemaphoreSlimContext? TryLock(SemaphoreSlim semaphore, ILogger? logger, out bool locked)
 		{
 			ArgumentNullException.ThrowIfNull(semaphore);
+			logger?.LogTrace("Trying to acquire semaphore...");
 			locked = semaphore.Wait(TimeSpan.Zero);
+			logger?.LogTrace("Acquired semaphore {un}successfully", locked ? String.Empty : "un");
 			return locked
-				? new SemaphoreSlimContext(semaphore)
+				? new SemaphoreSlimContext(semaphore, logger)
 				: null;
 		}
 
+		/// <summary>
+		/// An optional <see cref="ILogger"/> to write to.
+		/// </summary>
+		readonly ILogger? logger;
+
 		/// <summary>
 		/// The locked <see cref="SemaphoreSlim"/>.
 		/// </summary>
@@ -46,14 +58,20 @@ public static async ValueTask<SemaphoreSlimContext> Lock(SemaphoreSlim semaphore
 		/// Initializes a new instance of the <see cref="SemaphoreSlimContext"/> class.
 		/// </summary>
 		/// <param name="lockedSemaphore">The value of <see cref="lockedSemaphore"/>.</param>
-		SemaphoreSlimContext(SemaphoreSlim lockedSemaphore)
+		/// <param name="logger">The value of <see cref="logger"/>.</param>
+		SemaphoreSlimContext(SemaphoreSlim lockedSemaphore, ILogger? logger)
 		{
 			this.lockedSemaphore = lockedSemaphore;
+			this.logger = logger;
 		}
 
 		/// <summary>
 		/// Release the lock on <see cref="lockedSemaphore"/>.
 		/// </summary>
-		public void Dispose() => lockedSemaphore.Release();
+		public void Dispose()
+		{
+			logger?.LogTrace("Releasing semaphore...");
+			lockedSemaphore.Release();
+		}
 	}
 }