Skip to content

Commit 9006767

Browse files
brdeyobrdeyo
committed
Fix bug causing process logging to overwrite log files during high-concurrency, multi-threaded operations.
1 parent 1459206 commit 9006767

6 files changed

Lines changed: 307 additions & 43 deletions

File tree

‎src/VirtualClient/VirtualClient.Contracts.UnitTests/FileUploadDescriptorFactoryTests.cs‎

Lines changed: 11 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -93,7 +93,7 @@ public void FileUploadDescriptorFactoryCreatesTheExpectedDescriptor_When_Timesta
9393
string expectedContentType = HttpContentType.PlainText;
9494
string expectedContentEncoding = Encoding.UTF8.WebName;
9595
string expectedFilePath = this.mockFile.Object.FullName;
96-
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-fffffZ")}-{this.mockFile.Object.Name}";
96+
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-ffffffZ")}-{this.mockFile.Object.Name}";
9797
string expectedBlobPath = string.Join('/', (new string[] { expectedAgentId, expectedToolName, expectedRole, expectedScenario })
9898
.Where(i => i != null))
9999
.ToLowerInvariant();
@@ -139,7 +139,7 @@ public void FileUploadDescriptorFactoryCreatesTheExpectedDescriptorWithDefaultCo
139139
string expectedContentType = HttpContentType.PlainText;
140140
string expectedContentEncoding = Encoding.UTF8.WebName;
141141
string expectedFilePath = this.mockFile.Object.FullName;
142-
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-fffffZ")}-{this.mockFile.Object.Name}";
142+
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-ffffffZ")}-{this.mockFile.Object.Name}";
143143
string expectedBlobPath = string.Join('/', (new string[]
144144
{
145145
expectedAgentId,
@@ -186,7 +186,7 @@ public void FileUploadDescriptorFactoryCreatesTheExpectedDescriptorWithDefaultCo
186186
string expectedContentType = HttpContentType.PlainText;
187187
string expectedContentEncoding = Encoding.UTF8.WebName;
188188
string expectedFilePath = this.mockFile.Object.FullName;
189-
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-fffffZ")}-{this.mockFile.Object.Name}";
189+
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-ffffffZ")}-{this.mockFile.Object.Name}";
190190
string expectedBlobPath = string.Join('/', (new string[]
191191
{
192192
expectedAgentId,
@@ -272,7 +272,7 @@ public void FileUploadDescriptorFactoryCreatesTheExpectedDescriptorWithCustomCon
272272
string expectedContentType = HttpContentType.PlainText;
273273
string expectedContentEncoding = Encoding.UTF8.WebName;
274274
string expectedFilePath = this.mockFile.Object.FullName;
275-
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-fffffZ")}-{this.mockFile.Object.Name}";
275+
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-ffffffZ")}-{this.mockFile.Object.Name}";
276276

277277
// The blob path itself is lower-cased. However, the file name casing is NOT modified.
278278
expectedBlobPath = $"{expectedBlobPath.ToLowerInvariant().TrimEnd('/')}/{expectedFileName}";
@@ -339,7 +339,7 @@ public void FileUploadDescriptorFactoryCreatesTheExpectedDescriptorWithCustomCon
339339
string expectedContentType = HttpContentType.PlainText;
340340
string expectedContentEncoding = Encoding.UTF8.WebName;
341341
string expectedFilePath = this.mockFile.Object.FullName;
342-
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-fffffZ")}-{this.mockFile.Object.Name}";
342+
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-ffffffZ")}-{this.mockFile.Object.Name}";
343343

344344
// The blob path itself is lower-cased. However, the file name casing is NOT modified.
345345
expectedBlobPath = $"{expectedBlobPath.ToLowerInvariant().TrimEnd('/')}/{expectedFileName}";
@@ -394,7 +394,7 @@ public void FileUploadDescriptorFactoryIsNotCaseSensitiveOnContentPathTemplatesD
394394
string expectedContentType = HttpContentType.PlainText;
395395
string expectedContentEncoding = Encoding.UTF8.WebName;
396396
string expectedFilePath = this.mockFile.Object.FullName;
397-
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-fffffZ")}-{this.mockFile.Object.Name}";
397+
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-ffffffZ")}-{this.mockFile.Object.Name}";
398398

399399
// The blob path itself is lower-cased. However, the file name casing is NOT modified.
400400
string expectedContainer = "customcontainer";
@@ -463,7 +463,7 @@ public void FileUploadDescriptorFactoryCreatesTheExpectedDescriptorWithCustomCon
463463
string expectedContentType = HttpContentType.PlainText;
464464
string expectedContentEncoding = Encoding.UTF8.WebName;
465465
string expectedFilePath = this.mockFile.Object.FullName;
466-
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-fffffZ")}-{this.mockFile.Object.Name}";
466+
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-ffffffZ")}-{this.mockFile.Object.Name}";
467467

468468
// The blob path itself is lower-cased. However, the file name casing is NOT modified.
469469
expectedBlobPath = $"{expectedBlobPath.ToLowerInvariant().TrimEnd('/')}/{expectedFileName}";
@@ -517,7 +517,7 @@ public void FileUploadDescriptorFactoryCreatesBlobPathsWithTheExpectedCasing(str
517517
string expectedContentType = HttpContentType.PlainText;
518518
string expectedContentEncoding = Encoding.UTF8.WebName;
519519
string expectedFilePath = this.mockFile.Object.FullName;
520-
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-fffffZ")}-{this.mockFile.Object.Name}";
520+
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-ffffffZ")}-{this.mockFile.Object.Name}";
521521

522522
// The blob path itself is lower-cased. However, the file name casing is NOT modified.
523523
expectedBlobPath = $"{expectedBlobPath.ToLowerInvariant().TrimEnd('/')}/{expectedFileName}";
@@ -582,7 +582,7 @@ public void FileUploadDescriptorFactorySupportsEitherOrPathTemplateDefinitions_1
582582
string expectedContentType = HttpContentType.PlainText;
583583
string expectedContentEncoding = Encoding.UTF8.WebName;
584584
string expectedFilePath = this.mockFile.Object.FullName;
585-
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-fffffZ")}-{this.mockFile.Object.Name}";
585+
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-ffffffZ")}-{this.mockFile.Object.Name}";
586586

587587
string contentPathTemplate = "customcontainer/{experimentDefinitionId}/{experimentName}/{experimentId},{revision}/{toolkitCommand|scenario}";
588588

@@ -637,7 +637,7 @@ public void FileUploadDescriptorFactorySupportsEitherOrPathTemplateDefinitions_2
637637
string expectedContentType = HttpContentType.PlainText;
638638
string expectedContentEncoding = Encoding.UTF8.WebName;
639639
string expectedFilePath = this.mockFile.Object.FullName;
640-
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-fffffZ")}-{this.mockFile.Object.Name}";
640+
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-ffffffZ")}-{this.mockFile.Object.Name}";
641641

642642
// A parameter "toolkitCommand" does not exist. The template should use the "scenario" parameter instead.
643643
string contentPathTemplate = "customcontainer/{experimentDefinitionId}/{experimentName}/{experimentId},{revision}/{toolkitCommand|scenario}";
@@ -691,7 +691,7 @@ public void FileUploadDescriptorFactoryHandlesCasesWhereTheTemplateReferencesAPa
691691
string expectedContentType = HttpContentType.PlainText;
692692
string expectedContentEncoding = Encoding.UTF8.WebName;
693693
string expectedFilePath = this.mockFile.Object.FullName;
694-
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-fffffZ")}-{this.mockFile.Object.Name}";
694+
string expectedFileName = $"{this.mockFile.Object.CreationTimeUtc.ToString("yyyy-MM-ddTHH-mm-ss-ffffffZ")}-{this.mockFile.Object.Name}";
695695

696696
// A parameter "toolkitCommand" does not exist. The factory should just remove the parameter in the
697697
// final blob path.

‎src/VirtualClient/VirtualClient.Contracts/FileContext.cs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -16,7 +16,7 @@ namespace VirtualClient.Contracts
1616
/// </summary>
1717
public class FileContext
1818
{
19-
private const string FileTimestampFormat = "yyyy-MM-ddTHH-mm-ss-fffffK";
19+
private const string FileTimestampFormat = "yyyy-MM-ddTHH-mm-ss-ffffffK";
2020
private static readonly Regex PathReservedCharacterExpression = new Regex(@"[""<>:|?*\\/]+", RegexOptions.Compiled);
2121
private static readonly Regex TemplatePlaceholderExpression = new Regex(@"\{(.*?)\}", RegexOptions.Compiled | RegexOptions.IgnoreCase);
2222

‎src/VirtualClient/VirtualClient.Contracts/PlatformSpecifics.cs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -95,7 +95,7 @@ public PlatformSpecifics(PlatformID platform, Architecture architecture, string
9595
/// <summary>
9696
/// The directory for file/content upload notifications (e.g. /logs/contentuploads).
9797
/// </summary>
98-
public string ContentUploadsDirectory { get; }
98+
public string ContentUploadsDirectory { get; set; }
9999

100100
/// <summary>
101101
/// The CPU architecture (e.g. x64, arm64).

‎src/VirtualClient/VirtualClient.Core.UnitTests/VirtualClientLoggingExtensionsTests.cs‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -121,7 +121,7 @@ public async Task LogProcessDetailsExtensionLogsToTheExpectedLogFile_Timestamped
121121
// e.g.
122122
// /home/user/virtualclient/logs/testexecutor/2025-07-20-193948162-anyscenario.log
123123
string expectedLogDirectory = this.GetLogsPath(component.TypeName.ToLowerInvariant());
124-
string expectedLogFile = $@"[\\/][0-9]{{4}}-[0-9]{{2}}-[0-9]{{2}}-[0-9]{{9}}-{component.Scenario}.log".ToLowerInvariant();
124+
string expectedLogFile = $@"[\\/][0-9]{{4}}-[0-9]{{2}}-[0-9]{{2}}-[0-9]{{12}}-{component.Scenario}.log".ToLowerInvariant();
125125

126126
this.FileSystem
127127
.Setup(fs => fs.Directory.CreateDirectory(expectedLogDirectory))
@@ -162,7 +162,7 @@ public async Task LogProcessDetailsExtensionLogsToTheExpectedLogFile_Timestamped
162162
// e.g.
163163
// /home/user/virtualclient/logs/bash/2025-07-20-193948162-anyscenario.log
164164
string expectedLogDirectory = this.GetLogsPath("bash");
165-
string expectedLogFile = $@"[\\/][0-9]{{4}}-[0-9]{{2}}-[0-9]{{2}}-[0-9]{{9}}-{component.Scenario}.log".ToLowerInvariant();
165+
string expectedLogFile = $@"[\\/][0-9]{{4}}-[0-9]{{2}}-[0-9]{{2}}-[0-9]{{12}}-{component.Scenario}.log".ToLowerInvariant();
166166

167167
this.FileSystem
168168
.Setup(fs => fs.Directory.CreateDirectory(expectedLogDirectory))
@@ -412,7 +412,7 @@ public async Task LogProcessDetailsExtensionLogsToTheExpectedLogFile_Component_L
412412
// e.g.
413413
// /home/user/virtualclient/logs/workloads/bash.log
414414
string expectedLogDirectory = this.GetLogsPath("workloads");
415-
string expectedLogFile = $@"[\\/][0-9]{{4}}-[0-9]{{2}}-[0-9]{{2}}-[0-9]{{9}}-{component.Scenario.ToLowerInvariant()}.log";
415+
string expectedLogFile = $@"[\\/][0-9]{{4}}-[0-9]{{2}}-[0-9]{{2}}-[0-9]{{12}}-{component.Scenario.ToLowerInvariant()}.log";
416416

417417
this.FileSystem
418418
.Setup(fs => fs.Directory.CreateDirectory(expectedLogDirectory))

‎src/VirtualClient/VirtualClient.Core/VirtualClientLoggingExtensions.cs‎

Lines changed: 43 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@ namespace VirtualClient
1111
using System.Runtime.InteropServices;
1212
using System.Text;
1313
using System.Text.RegularExpressions;
14+
using System.Threading;
1415
using System.Threading.Tasks;
1516
using Microsoft.Extensions.Logging;
1617
using Polly;
@@ -29,6 +30,8 @@ public static class VirtualClientLoggingExtensions
2930
private static readonly IAsyncPolicy FileSystemAccessRetryPolicy = Policy.Handle<IOException>()
3031
.WaitAndRetryAsync(10, (retries) => TimeSpan.FromSeconds(retries));
3132

33+
private static readonly Semaphore FileAccessLock = new Semaphore(1, 1);
34+
3235
/// <summary>
3336
/// Captures the details of the process including standard output, standard error and exit codes to
3437
/// telemetry and log files on the system.
@@ -87,38 +90,48 @@ public static async Task LogProcessDetailsAsync(this VirtualClientComponent comp
8790
processDetails.ThrowIfNull(nameof(processDetails));
8891
telemetryContext.ThrowIfNull(nameof(telemetryContext));
8992

90-
if (logToTelemetry)
93+
if (VirtualClientLoggingExtensions.FileAccessLock.WaitOne())
9194
{
9295
try
9396
{
94-
component.Logger?.LogProcessDetails(processDetails, component.TypeName, telemetryContext, logToTelemetryMaxChars);
95-
}
96-
catch (Exception exc)
97-
{
98-
// Best effort but we should never crash VC if the logging fails. Metric capture
99-
// is more important to the operations of VC. We do want to log the failure.
100-
component.Logger?.LogErrorMessage(exc, telemetryContext, LogLevel.Warning);
101-
}
102-
}
97+
if (logToTelemetry)
98+
{
99+
try
100+
{
101+
component.Logger?.LogProcessDetails(processDetails, component.TypeName, telemetryContext, logToTelemetryMaxChars);
102+
}
103+
catch (Exception exc)
104+
{
105+
// Best effort but we should never crash VC if the logging fails. Metric capture
106+
// is more important to the operations of VC. We do want to log the failure.
107+
component.Logger?.LogErrorMessage(exc, telemetryContext, LogLevel.Warning);
108+
}
109+
}
103110

104-
// The VirtualClientComponent itself has a global setting (defined on the command line)
105-
// for logging to file. The secondary extension method level boolean parameter here enables
106-
// individual usages of this method to override if needed at the use case level.
107-
//
108-
// e.g.
109-
// The user may request logging to file on the command line. However, a specific component
110-
// implementation may want to avoid logging its contents to file because it is not useful information etc...
111-
if (component.LogToFile && logToFile)
112-
{
113-
try
114-
{
115-
await component.LogProcessDetailsToFileAsync(processDetails, telemetryContext, logFileName, timestamped, upload);
111+
// The VirtualClientComponent itself has a global setting (defined on the command line)
112+
// for logging to file. The secondary extension method level boolean parameter here enables
113+
// individual usages of this method to override if needed at the use case level.
114+
//
115+
// e.g.
116+
// The user may request logging to file on the command line. However, a specific component
117+
// implementation may want to avoid logging its contents to file because it is not useful information etc...
118+
if (component.LogToFile && logToFile)
119+
{
120+
try
121+
{
122+
await component.LogProcessDetailsToFileAsync(processDetails, telemetryContext, logFileName, timestamped, upload);
123+
}
124+
catch (Exception exc)
125+
{
126+
// Best effort but we should never crash VC if the logging fails. Metric capture
127+
// is more important to the operations of VC. We do want to log the failure.
128+
component.Logger?.LogErrorMessage(exc, telemetryContext, LogLevel.Warning);
129+
}
130+
}
116131
}
117-
catch (Exception exc)
132+
finally
118133
{
119-
// Best effort but we should never crash VC if the logging fails. Metric capture
120-
// is more important to the operations of VC. We do want to log the failure.
121-
component.Logger?.LogErrorMessage(exc, telemetryContext, LogLevel.Warning);
134+
VirtualClientLoggingExtensions.FileAccessLock.Release();
122135
}
123136
}
124137
}
@@ -382,7 +395,10 @@ private static string GetSafeFileName(string fileName, bool timestamped = true)
382395

383396
if (timestamped)
384397
{
385-
effectiveLogFileName = $"{DateTime.UtcNow.ToString("yyyy-MM-dd-HHmmssfff")}-{effectiveLogFileName}";
398+
// Note:
399+
// In order to best ensure we handle concurrent writes happening at near the same instant
400+
// in time, we include parts of the timestamp down to the millionths of a second.
401+
effectiveLogFileName = $"{DateTime.UtcNow.ToString("yyyy-MM-dd-HHmmssffffff")}-{effectiveLogFileName}";
386402
}
387403

388404
return effectiveLogFileName.ToLowerInvariant();

0 commit comments

Comments
 (0)