Skip to content

Commit

Permalink
Refactor ILogger.LogSystemEvents methods to be support a more precise…
Browse files Browse the repository at this point in the history 
… Event schema/contract.
  • Loading branch information
@brdeyo
brdeyo committed Oct 28, 2024
1 parent 76b8deb commit f3e788d
Show file tree
Hide file tree
Showing 8 changed files with 205 additions and 149 deletions.
2 changes: 1 addition & 1 deletion VERSION
View file
Original file line number Diff line number Diff line change
@@ -1 +1 @@
1.16.2
1.16.3
12 changes: 6 additions & 6 deletions ...tualClient/VirtualClient.Actions.FunctionalTests/Memcached/MemcachedServerProfileTests.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -63,13 +63,9 @@ await executor.ExecuteAsync(ProfileTiming.OneIteration(), CancellationToken.None
[TestCase("PERF-MEMCACHED.json")]
public async Task MemcachedMemtierWorkloadProfileExecutesTheWorkloadAsExpectedOfServerOnUnixPlatformMultiVM(string profile)
{
this.mockFixture.PlatformSpecifics.EnvironmentVariables.Add(
EnvironmentVariable.SUDO_USER,
"mockuser");

IEnumerable<string> expectedCommands = new List<string>
{
$"sudo -u mockuser bash -c \"numactl -C {string.Join(",", Enumerable.Range(0, Environment.ProcessorCount))} /.+/memcached -p 6379 -t 4 -m 30720 -c 16384 :: &\""
$"sudo -u [a-z]+ bash -c \"numactl -C {string.Join(",", Enumerable.Range(0, Environment.ProcessorCount))} /.+/memcached -p 6379 -t 4 -m 30720 -c 16384 :: &\""
};

// Setup the expectations for the workload
Expand All @@ -91,7 +87,11 @@ public async Task MemcachedMemtierWorkloadProfileExecutesTheWorkloadAsExpectedOf
await apiClient.CreateStateAsync(nameof(ServerState), state, CancellationToken.None);
this.mockFixture.ProcessManager.OnCreateProcess = (command, arguments, workingDir) =>
{
IProcessProxy process = this.mockFixture.CreateProcess(command, arguments, workingDir);
InMemoryProcess process = this.mockFixture.CreateProcess(command, arguments, workingDir);
process.EnvironmentVariables.Add(
EnvironmentVariable.SUDO_USER,
"mockuser");
return process;
};

Expand Down
15 changes: 13 additions & 2 deletions src/VirtualClient/VirtualClient.Actions/Examples/ExampleWorkloadExecutor.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -359,8 +359,11 @@ await this.LogProcessDetailsAsync(workloadProcess, telemetryContext, "ExampleWor
.ConfigureAwait(false);
this.Logger.LogSystemEvent(
"Process.Details",
new Dictionary<string, IConvertible>
"ProcessResult",
"ExampleWorkload",
"The results of the example workload process",
workloadProcess.ExitCode,
new Dictionary<string, object>
{
{ "toolset", "ExampleWorkload" },
{ "command", $"{this.WorkloadExecutablePath} {commandArguments}" },
Expand All @@ -372,6 +375,14 @@ await this.LogProcessDetailsAsync(workloadProcess, telemetryContext, "ExampleWor
workloadProcess.ExitCode == 0 ? LogLevel.Information : LogLevel.Error,
telemetryContext);
this.Logger.LogSystemEvent(
"KeyResult",
"ExampleWorkload",
"The results of the example workload process",
100,
workloadProcess.ExitCode == 0 ? LogLevel.Information : LogLevel.Error,
telemetryContext);
// If the workload process returned a non-success exit code, we throw an exception typically. The ErrorReason used here
// will NOT cause VC to crash.
workloadProcess.ThrowIfErrored<WorkloadException>(ProcessProxy.DefaultSuccessCodes, errorReason: ErrorReason.WorkloadFailed);
Expand Down
129 changes: 103 additions & 26 deletions src/VirtualClient/VirtualClient.Contracts.UnitTests/VirtualClientLoggingExtensionsTests.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2224,61 +2224,130 @@ public void LogSuccessMetricExtensionOnComponentLogsTheExpectedInformation_scena
}

[Test]
public void LogSystemEventsExtensionLogsTheExpectedEvents()
[TestCase(LogLevel.Critical)]
[TestCase(LogLevel.Debug)]
[TestCase(LogLevel.Error)]
[TestCase(LogLevel.Information)]
[TestCase(LogLevel.None)]
[TestCase(LogLevel.Trace)]
[TestCase(LogLevel.Warning)]
public void LogSystemEventExtensionLogsTheExpectedEvents(LogLevel expectedEventLevel)
{
string expectedMessage = "RealtimeDataMonitorCounters";
IDictionary<string, object> expectedSystemEvents = new Dictionary<string, object>
string expectedEventType = "EventResult";
string expectedEventSource = "AnySource";
string expectedEventDescription = "Test of the system event telemetry system.";
long expectedEventId = 100;

IDictionary<string, object> expectedEventInfo = new Dictionary<string, object>
{
["SystemEventLog"] = "Process shutdown unexpectedly.",
["SystemFileChange"] = "ntdll.dll version 1.2.3 replaced."
["property1"] = "Process shutdown unexpectedly.",
["property2"] = 1234,
};

this.mockLogger.Object.LogSystemEvents(expectedMessage, expectedSystemEvents, this.mockEventContext);
this.mockLogger.Object.LogSystemEvent(
expectedEventType,
expectedEventSource,
expectedEventDescription,
expectedEventId,
expectedEventInfo,
expectedEventLevel,
this.mockEventContext);

this.mockLogger.Verify(logger => logger.Log(
LogLevel.Information,
It.Is<EventId>(eventId => eventId.Id == (int)LogType.SystemEvent && eventId.Name == expectedMessage),
expectedEventLevel,
It.Is<EventId>(eventId => eventId.Id == (int)LogType.SystemEvent && eventId.Name == expectedEventType),
It.Is<EventContext>(context => context.ActivityId == this.mockEventContext.ActivityId
&& context.ParentActivityId == this.mockEventContext.ParentActivityId
&& context.Properties.ContainsKey("eventType")
&& context.Properties.ContainsKey("eventInfo")),
null,
null),
Times.Exactly(2)); // Each performance counter is logged as an individual message
Times.Exactly(1));
}

[Test]
public void LogSystemEventExtensionIncludesTheSystemEventInformationInTheEventContext_1()
{
string expectedEventType = "EventResult";
string expectedEventSource = "AnySource";
string expectedEventDescription = "Test of the system event telemetry system.";
long expectedEventId = 100;

this.mockLogger
.Setup(logger => logger.Log(It.IsAny<LogLevel>(), It.IsAny<EventId>(), It.IsAny<EventContext>(), null, null))
.Callback<LogLevel, EventId, EventContext, Exception, Func<EventContext, Exception, string>>((level, eventId, state, exc, formatter) =>
{
Assert.IsNotNull(state);
Assert.IsTrue(state.Properties.ContainsKey("eventType"));
Assert.IsTrue(state.Properties.ContainsKey("eventInfo"));
Assert.AreEqual(expectedEventType, state.Properties["eventType"]);
IDictionary<string, object> actualEventInfo = state.Properties["eventInfo"] as IDictionary<string, object>;
Assert.IsNotNull(actualEventInfo);
Assert.AreEqual(expectedEventDescription, actualEventInfo["eventDescription"]);
Assert.AreEqual(expectedEventSource, actualEventInfo["eventSource"]);
Assert.AreEqual(expectedEventId, actualEventInfo["eventId"]);
});

this.mockLogger.Object.LogSystemEvent(
expectedEventType,
expectedEventSource,
expectedEventDescription,
expectedEventId,
LogLevel.Information,
this.mockEventContext);
}

[Test]
public void LogSystemEventsExtensionIncludesTheSystemEventInformationInTheEventContext()
public void LogSystemEventExtensionIncludesTheSystemEventInformationInTheEventContext_2()
{
string expectedMessage = "RealtimeDataMonitorCounters";
IDictionary<string, object> expectedSystemEvents = new Dictionary<string, object>
string expectedEventType = "EventResult";
string expectedEventSource = "AnySource";
string expectedEventDescription = "Test of the system event telemetry system.";
long expectedEventId = 100;

IDictionary<string, object> expectedEventInfo = new Dictionary<string, object>
{
["SystemEventLog"] = "Process shutdown unexpectedly.",
["SystemFileChange"] = "ntdll.dll version 1.2.3 replaced.",
["MicrocodeVersion"] = 1234
["property1"] = "Process shutdown unexpectedly.",
["property2"] = 1234,
};

int counterIndex = 0;

this.mockLogger
.Setup(logger => logger.Log(It.IsAny<LogLevel>(), It.IsAny<EventId>(), It.IsAny<EventContext>(), null, null))
.Callback<LogLevel, EventId, EventContext, Exception, Func<EventContext, Exception, string>>((level, eventId, state, exc, formatter) =>
{
Assert.IsNotNull(state);
Assert.IsTrue(state.Properties.ContainsKey("eventType"));
Assert.IsTrue(state.Properties.ContainsKey("eventInfo"));
Assert.AreEqual(state.Properties["eventType"].ToString(), expectedSystemEvents.ElementAt(counterIndex).Key);
Assert.AreEqual(state.Properties["eventInfo"], expectedSystemEvents.ElementAt(counterIndex).Value);
counterIndex++;
Assert.AreEqual(expectedEventType, state.Properties["eventType"]);
IDictionary<string, object> actualEventInfo = state.Properties["eventInfo"] as IDictionary<string, object>;
Assert.IsNotNull(actualEventInfo);
Assert.AreEqual(expectedEventInfo["property1"], actualEventInfo["property1"]);
Assert.AreEqual(expectedEventInfo["property2"], actualEventInfo["property2"]);
Assert.AreEqual(expectedEventDescription, actualEventInfo["eventDescription"]);
Assert.AreEqual(expectedEventSource, actualEventInfo["eventSource"]);
Assert.AreEqual(expectedEventId, actualEventInfo["eventId"]);
});

this.mockLogger.Object.LogSystemEvents(expectedMessage, expectedSystemEvents, this.mockEventContext);
this.mockLogger.Object.LogSystemEvent(
expectedEventType,
expectedEventSource,
expectedEventDescription,
expectedEventId,
expectedEventInfo,
LogLevel.Information,
this.mockEventContext);
}


[Test]
public void LogSystemEventsExtensionDoesNotSideEffectOrChangeAnEventContextProvided()
public void LogSystemEventExtensionDoesNotSideEffectOrChangeAnEventContextProvided()
{
string expectedEventType = "EventResult";
string expectedEventSource = "AnySource";
string expectedEventDescription = "Test of the system event telemetry system.";
long expectedEventId = 100;

EventContext originalContext = new EventContext(Guid.NewGuid(), new Dictionary<string, object>
{
["property1"] = "Any Value",
Expand All @@ -2287,9 +2356,10 @@ public void LogSystemEventsExtensionDoesNotSideEffectOrChangeAnEventContextProvi

EventContext cloneOfOriginal = originalContext.Clone();

IDictionary<string, object> systemEvents = new Dictionary<string, object>
IDictionary<string, object> expectedEventInfo = new Dictionary<string, object>
{
["SystemEventLog"] = "Process shutdown unexpectedly."
["property1"] = "Process shutdown unexpectedly.",
["property2"] = 1234,
};

this.mockLogger
Expand All @@ -2301,7 +2371,14 @@ public void LogSystemEventsExtensionDoesNotSideEffectOrChangeAnEventContextProvi
Assert.IsFalse(object.ReferenceEquals(originalContext, actualContext));
});

this.mockLogger.Object.LogSystemEvents("AnyMessage", systemEvents, this.mockEventContext);
this.mockLogger.Object.LogSystemEvent(
expectedEventType,
expectedEventSource,
expectedEventDescription,
expectedEventId,
expectedEventInfo,
LogLevel.Information,
this.mockEventContext);

// The original should not have been changed.
Assert.AreEqual(originalContext.ActivityId, cloneOfOriginal.ActivityId);
Expand Down
37 changes: 0 additions & 37 deletions ...lClient.Contracts.UnitTests/VirtualClientLoggingExtensionsTests_BackwardsCompatibility.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -109,43 +109,6 @@ public void LogPerformanceCountersExtensionLogsTheExpectedEventsWhenSupportForOr
null));
}

[Test]
public void LogSystemEventsExtensionLogsTheExpectedEventsWhenSupportForOriginalSchemaIsRequested()
{
string expectedMessage = "RealtimeDataMonitorCounters";
IDictionary<string, object> expectedSystemEvents = new Dictionary<string, object>
{
["SystemEventLog"] = "Process shutdown unexpectedly.",
["SystemFileChange"] = "ntdll.dll version 1.2.3 replaced."
};

this.mockLogger.Object.LogSystemEvents(expectedMessage, expectedSystemEvents, this.mockEventContext, supportOriginalSchema: true);

// Original Schema
this.mockLogger.Verify(logger => logger.Log(
LogLevel.Information,
It.Is<EventId>(eventId => eventId.Id == (int)LogType.SystemEvent && eventId.Name == expectedMessage),
It.Is<EventContext>(context => context.ActivityId == this.mockEventContext.ActivityId
&& context.ParentActivityId == this.mockEventContext.ParentActivityId
&& context.Properties.ContainsKey("name")
&& context.Properties.ContainsKey("value")),
null,
null),
Times.Exactly(2)); // Each performance counter is logged as an individual message

// New Schema
this.mockLogger.Verify(logger => logger.Log(
LogLevel.Information,
It.Is<EventId>(eventId => eventId.Id == (int)LogType.SystemEvent && eventId.Name == expectedMessage),
It.Is<EventContext>(context => context.ActivityId == this.mockEventContext.ActivityId
&& context.ParentActivityId == this.mockEventContext.ParentActivityId
&& context.Properties.ContainsKey("eventType")
&& context.Properties.ContainsKey("eventInfo")),
null,
null),
Times.Exactly(2)); // Each performance counter is logged as an individual message
}

[Test]
public void LogMetricsExtensionLogsTheExpectedEventsWhenSupportForOriginalSchemaIsRequested()
{
Expand Down
Loading

0 comments on commit f3e788d

Please sign in to comment.