diff --git a/eng/Versions.props b/eng/Versions.props index ad0283439a0745..50d929abea061a 100644 --- a/eng/Versions.props +++ b/eng/Versions.props @@ -109,7 +109,7 @@ 2.0.0 17.10.0-beta1.24272.1 - 3.1.16 + 3.1.28 0.2.621003 2.1.0 2.0.3 @@ -124,6 +124,7 @@ 1.6.0 17.4.0-preview-20220707-01 + 0.1.32221 3.12.0 4.5.0 6.0.4 diff --git a/src/tests/Common/helixpublishwitharcade.proj b/src/tests/Common/helixpublishwitharcade.proj index fa4ecc1faf92e4..b613c275deeb69 100644 --- a/src/tests/Common/helixpublishwitharcade.proj +++ b/src/tests/Common/helixpublishwitharcade.proj @@ -412,12 +412,28 @@ $(XUnitLogCheckerHelixPath)XUnitLogChecker$(ExeSuffix) $(XUnitLogCheckerArgs) + + <_ExtraTestExecutablesListFiles Remote="@(_ExtraTestExecutablesListFiles)" /> + <_ExtraTestExecutablesListFiles Include="@(_MergedPayloadFiles)" + Condition="$([System.String]::Copy('%(Identity)').ToLower().EndsWith('helix-extra-executables.list'))" /> + <_ExtraTestExecutables Remove="@(_ExtraTestExecutables)" /> + + + + + + <_ExtraTestExecutables Remove="@(_ExtraTestExecutables)" Condition="'%(Identity)' == ''" /> + + + + + diff --git a/src/tests/build.proj b/src/tests/build.proj index 8ba1b4eb2f3ed6..c2f21ca2877dc5 100644 --- a/src/tests/build.proj +++ b/src/tests/build.proj @@ -40,6 +40,7 @@ + diff --git a/src/tests/issues.targets b/src/tests/issues.targets index 185634263fe8be..02d5b76e8ac6f4 100644 --- a/src/tests/issues.targets +++ b/src/tests/issues.targets @@ -1535,6 +1535,9 @@ Test issue. The test relies on overriding the process return code. + + Record-Trace's diagnostic port detection logic relies on memfd-based double mapping + diff --git a/src/tests/tracing/userevents/README.md b/src/tests/tracing/userevents/README.md new file mode 100644 index 00000000000000..71df5e9c7fccf1 --- /dev/null +++ b/src/tests/tracing/userevents/README.md @@ -0,0 +1,29 @@ +# User Events Functional Tests + +This directory contains **functional tests** for the .NET user_events scenario. These tests validate that .NET Runtime user events can be emitted via EventPipe and collected by [one-collect](https://github.com/microsoft/one-collect/)'s `record-trace` tool. + +## High-level Test Flow + +Each scenario (for example, `basic`) uses the same pattern: + +1. **Scenario invokes the shared test runner** + + User events scenarios can differ in their tracee logic, the events expected in the .nettrace, the record-trace script used to collect those events, and how long it takes for the tracee to emit them and for record-trace to resolve symbols and write the .nettrace. To handle this variance, UserEventsTestRunner lets each scenario pass in its scenario-specific record-trace script path, the path to its test assembly (used to spawn the tracee process), a validator that checks for the expected events from the tracee, and optional timeouts for both the tracee and record-trace to exit gracefully. + +2. **`UserEventsTestRunner` orchestrates tracing and validation** + + Using this configuration, UserEventsTestRunner first checks whether user events are supported. It then starts record-trace with the scenario’s script and launches the tracee process so it can emit events. After the run completes, the runner stops both the tracee and record-trace, opens the resulting .nettrace with EventPipeEventSource, and applies the scenario’s validator to confirm that the expected events were recorded. Finally, it returns an exit code indicating whether the scenario passed or failed. + +## Layout + +- `common/` + - `UserEventsRequirements.cs` - Checks whether the environment supports user events. + - `UserEventsTestRunner.cs` - Shared runner that coordinates `record-trace`, the tracee process, and event validation. + - `userevents_common.csproj` - Common project for shared user events test logic. + - `NuGet.config` - Configures dotnet-diagnostics-tests nuget source which transports Microsoft.OneCollect.RecordTrace. +- `/` + - `.cs` - The tracee workload logic used when invoked with the `tracee` argument. + - `.csproj` - Project file for the scenario. + - `.script` - `record-trace` script that configures how to collect the trace for the scenario. + +Each scenario reuses the common runner and shared `record-trace` deployable instead of duplicating binaries or orchestration logic. The `basic` scenario serves as a concrete example of how to add additional scenarios. diff --git a/src/tests/tracing/userevents/activity/activity.cs b/src/tests/tracing/userevents/activity/activity.cs new file mode 100644 index 00000000000000..3e711af20a9ad9 --- /dev/null +++ b/src/tests/tracing/userevents/activity/activity.cs @@ -0,0 +1,182 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Diagnostics.Tracing; +using System.Threading.Tasks; +using Tracing.UserEvents.Tests.Common; +using Microsoft.Diagnostics.Tracing; + +namespace Tracing.UserEvents.Tests.Activity +{ + public static class Activity + { + public static void ActivityTracee() + { + ActivityTraceeAsync().GetAwaiter().GetResult(); + } + + private static async Task ActivityTraceeAsync() + { + Task requestA = ProcessRequest("RequestA"); + Task requestB = ProcessRequest("RequestB"); + + await Task.WhenAll(requestA, requestB); + } + + private static async Task ProcessRequest(string requestName) + { + ActivityEventSource.Log.WorkStart(requestName); + + Task query1 = Query("Query1 for " + requestName); + Task query2 = Query("Query2 for " + requestName); + + await Task.WhenAll(query1, query2); + + ActivityEventSource.Log.WorkStop(); + } + + private static async Task Query(string query) + { + ActivityEventSource.Log.QueryStart(query); + await Task.Delay(50); + ActivityEventSource.Log.DebugMessage("processing " + query); + await Task.Delay(50); + ActivityEventSource.Log.QueryStop(); + } + + private static readonly Func s_traceValidator = source => + { + Guid firstWorkActivityId = Guid.Empty; + Guid secondWorkActivityId = Guid.Empty; + + Guid firstWorkQuery1ActivityId = Guid.Empty; + Guid firstWorkQuery2ActivityId = Guid.Empty; + Guid secondWorkQuery1ActivityId = Guid.Empty; + Guid secondWorkQuery2ActivityId = Guid.Empty; + + Guid firstWorkQuery1RelatedActivityId = Guid.Empty; + Guid firstWorkQuery2RelatedActivityId = Guid.Empty; + Guid secondWorkQuery1RelatedActivityId = Guid.Empty; + Guid secondWorkQuery2RelatedActivityId = Guid.Empty; + + source.Dynamic.All += e => + { + if (!string.Equals(e.ProviderName, "DemoActivityIDs", StringComparison.Ordinal)) + { + return; + } + + if (e.EventName is null) + { + return; + } + + if (e.EventName.Equals("Work/Start", StringComparison.OrdinalIgnoreCase)) + { + string requestName = e.PayloadByName("requestName") as string ?? string.Empty; + + if (string.Equals(requestName, "RequestA", StringComparison.Ordinal)) + { + firstWorkActivityId = e.ActivityID; + } + else if (string.Equals(requestName, "RequestB", StringComparison.Ordinal)) + { + secondWorkActivityId = e.ActivityID; + } + } + else if (e.EventName.Equals("Query/Start", StringComparison.OrdinalIgnoreCase)) + { + string queryText = e.PayloadByName("query") as string ?? string.Empty; + + if (string.Equals(queryText, "Query1 for RequestA", StringComparison.Ordinal)) + { + firstWorkQuery1ActivityId = e.ActivityID; + firstWorkQuery1RelatedActivityId = e.RelatedActivityID; + } + else if (string.Equals(queryText, "Query2 for RequestA", StringComparison.Ordinal)) + { + firstWorkQuery2ActivityId = e.ActivityID; + firstWorkQuery2RelatedActivityId = e.RelatedActivityID; + } + else if (string.Equals(queryText, "Query1 for RequestB", StringComparison.Ordinal)) + { + secondWorkQuery1ActivityId = e.ActivityID; + secondWorkQuery1RelatedActivityId = e.RelatedActivityID; + } + else if (string.Equals(queryText, "Query2 for RequestB", StringComparison.Ordinal)) + { + secondWorkQuery2ActivityId = e.ActivityID; + secondWorkQuery2RelatedActivityId = e.RelatedActivityID; + } + } + }; + + source.Process(); + + if (firstWorkActivityId == Guid.Empty || secondWorkActivityId == Guid.Empty) + { + Console.Error.WriteLine("The trace did not contain two WorkStart events with ActivityIds for RequestA and RequestB."); + return false; + } + + if (firstWorkQuery1ActivityId == Guid.Empty || firstWorkQuery2ActivityId == Guid.Empty || + secondWorkQuery1ActivityId == Guid.Empty || secondWorkQuery2ActivityId == Guid.Empty) + { + Console.Error.WriteLine("The trace did not contain all expected QueryStart events with ActivityIds for both requests."); + return false; + } + + if (firstWorkQuery1RelatedActivityId == Guid.Empty || firstWorkQuery2RelatedActivityId == Guid.Empty || + secondWorkQuery1RelatedActivityId == Guid.Empty || secondWorkQuery2RelatedActivityId == Guid.Empty) + { + Console.Error.WriteLine("The trace did not contain RelatedActivityIds on all QueryStart events."); + return false; + } + + if (firstWorkQuery1RelatedActivityId != firstWorkActivityId || + firstWorkQuery2RelatedActivityId != firstWorkActivityId || + secondWorkQuery1RelatedActivityId != secondWorkActivityId || + secondWorkQuery2RelatedActivityId != secondWorkActivityId) + { + Console.Error.WriteLine("QueryStart RelatedActivityIds did not match their corresponding WorkStart ActivityIds."); + return false; + } + + return true; + }; + + public static int Main(string[] args) + { + return UserEventsTestRunner.Run( + args, + "activity", + typeof(Activity).Assembly.Location, + ActivityTracee, + s_traceValidator); + } + } + + [EventSource(Name = "DemoActivityIDs")] + internal sealed class ActivityEventSource : EventSource + { + public static readonly ActivityEventSource Log = new ActivityEventSource(); + + private ActivityEventSource() {} + + [Event(1)] + public void WorkStart(string requestName) => WriteEvent(1, requestName); + + [Event(2)] + public void WorkStop() => WriteEvent(2); + + [Event(3)] + public void DebugMessage(string message) => WriteEvent(3, message); + + [Event(4)] + public void QueryStart(string query) => WriteEvent(4, query); + + [Event(5)] + public void QueryStop() => WriteEvent(5); + } +} diff --git a/src/tests/tracing/userevents/activity/activity.csproj b/src/tests/tracing/userevents/activity/activity.csproj new file mode 100644 index 00000000000000..1b701787d37286 --- /dev/null +++ b/src/tests/tracing/userevents/activity/activity.csproj @@ -0,0 +1,19 @@ + + + true + true + false + + + + + + + + + + Always + activity.script + + + diff --git a/src/tests/tracing/userevents/activity/activity.script b/src/tests/tracing/userevents/activity/activity.script new file mode 100644 index 00000000000000..f0303375493623 --- /dev/null +++ b/src/tests/tracing/userevents/activity/activity.script @@ -0,0 +1,5 @@ +let DemoActivityIds_flags = new_dotnet_provider_flags(); +record_dotnet_provider("DemoActivityIDs", 0x0, 5, DemoActivityIds_flags); + +let System_Threading_Tasks_TplEventSource_flags = new_dotnet_provider_flags(); +record_dotnet_provider("System.Threading.Tasks.TplEventSource", 0x80, 5, System_Threading_Tasks_TplEventSource_flags); \ No newline at end of file diff --git a/src/tests/tracing/userevents/basic/basic.cs b/src/tests/tracing/userevents/basic/basic.cs new file mode 100644 index 00000000000000..180a59f6e7ab20 --- /dev/null +++ b/src/tests/tracing/userevents/basic/basic.cs @@ -0,0 +1,63 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Diagnostics; +using System.Threading; +using Tracing.UserEvents.Tests.Common; +using Microsoft.Diagnostics.Tracing; + +namespace Tracing.UserEvents.Tests.Basic +{ + public class Basic + { + private static byte[] s_array; + + public static void BasicTracee() + { + long startTimestamp = Stopwatch.GetTimestamp(); + long targetTicks = Stopwatch.Frequency; // 1s + + while (Stopwatch.GetTimestamp() - startTimestamp < targetTicks) + { + s_array = new byte[1024 * 100]; + Thread.Sleep(100); + } + } + + private readonly static Func s_traceValidator = source => + { + bool allocationSampledEventFound = false; + + source.Dynamic.All += (TraceEvent e) => + { + if (e.ProviderName == "Microsoft-Windows-DotNETRuntime") + { + // TraceEvent's ClrTraceEventParser does not know about the AllocationSampled Event, so it shows up as "Unknown(303)" + if (e.EventName.StartsWith("Unknown") && e.ID == (TraceEventID)303) + { + allocationSampledEventFound = true; + } + } + }; + + source.Process(); + + if (!allocationSampledEventFound) + { + Console.Error.WriteLine("The trace did not contain an AllocationSampled event."); + } + return allocationSampledEventFound; + }; + + public static int Main(string[] args) + { + return UserEventsTestRunner.Run( + args, + "basic", + typeof(Basic).Assembly.Location, + BasicTracee, + s_traceValidator); + } + } +} diff --git a/src/tests/tracing/userevents/basic/basic.csproj b/src/tests/tracing/userevents/basic/basic.csproj new file mode 100644 index 00000000000000..6e47928f023a62 --- /dev/null +++ b/src/tests/tracing/userevents/basic/basic.csproj @@ -0,0 +1,19 @@ + + + true + true + false + + + + + + + + + + Always + basic.script + + + diff --git a/src/tests/tracing/userevents/basic/basic.script b/src/tests/tracing/userevents/basic/basic.script new file mode 100644 index 00000000000000..d6ac4f6ee89060 --- /dev/null +++ b/src/tests/tracing/userevents/basic/basic.script @@ -0,0 +1,2 @@ +let Microsoft_Windows_DotNETRuntime_flags = new_dotnet_provider_flags(); +record_dotnet_provider("Microsoft-Windows-DotNETRuntime", 0x80000000000, 4, Microsoft_Windows_DotNETRuntime_flags); diff --git a/src/tests/tracing/userevents/common/NuGet.config b/src/tests/tracing/userevents/common/NuGet.config new file mode 100644 index 00000000000000..583af9d11bb787 --- /dev/null +++ b/src/tests/tracing/userevents/common/NuGet.config @@ -0,0 +1,6 @@ + + + + + + diff --git a/src/tests/tracing/userevents/common/UserEventsRequirements.cs b/src/tests/tracing/userevents/common/UserEventsRequirements.cs new file mode 100644 index 00000000000000..313cdd942b21b2 --- /dev/null +++ b/src/tests/tracing/userevents/common/UserEventsRequirements.cs @@ -0,0 +1,186 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Diagnostics; +using System.IO; + +namespace Tracing.UserEvents.Tests.Common +{ + internal static class UserEventsRequirements + { + private static readonly Version s_minKernelVersion = new(6, 4); + private const string TracefsPath = "/sys/kernel/tracing"; + private const string UserEventsDataPath = "/sys/kernel/tracing/user_events_data"; + // https://github.com/microsoft/one-collect/issues/225 + private static readonly Version s_minGlibcVersion = new(2, 35); + + internal static bool IsSupported() + { + if (Environment.OSVersion.Version < s_minKernelVersion) + { + Console.WriteLine($"Kernel version '{Environment.OSVersion.Version}' is less than the minimum required '{s_minKernelVersion}'"); + return false; + } + + return IsGlibcAtLeast(s_minGlibcVersion) && + IsTracefsMounted() && + IsUserEventsDataAvailable(); + } + + private static bool IsTracefsMounted() + { + ProcessStartInfo checkTracefsStartInfo = new(); + checkTracefsStartInfo.FileName = "sudo"; + checkTracefsStartInfo.Arguments = $"-n test -d {TracefsPath}"; + checkTracefsStartInfo.UseShellExecute = false; + checkTracefsStartInfo.RedirectStandardOutput = true; + checkTracefsStartInfo.RedirectStandardError = true; + + using Process checkTracefs = new() { StartInfo = checkTracefsStartInfo }; + checkTracefs.OutputDataReceived += (_, e) => + { + if (!string.IsNullOrEmpty(e.Data)) + { + Console.WriteLine($"[tracefs-check] {e.Data}"); + } + }; + checkTracefs.ErrorDataReceived += (_, e) => + { + if (!string.IsNullOrEmpty(e.Data)) + { + Console.Error.WriteLine($"[tracefs-check] {e.Data}"); + } + }; + + checkTracefs.Start(); + checkTracefs.BeginOutputReadLine(); + checkTracefs.BeginErrorReadLine(); + checkTracefs.WaitForExit(); + if (checkTracefs.ExitCode == 0) + { + return true; + } + + Console.WriteLine($"Tracefs not mounted at '{TracefsPath}'."); + return false; + } + + private static bool IsUserEventsDataAvailable() + { + ProcessStartInfo checkUserEventsDataStartInfo = new(); + checkUserEventsDataStartInfo.FileName = "sudo"; + checkUserEventsDataStartInfo.Arguments = $"-n test -e {UserEventsDataPath}"; + checkUserEventsDataStartInfo.UseShellExecute = false; + checkUserEventsDataStartInfo.RedirectStandardOutput = true; + checkUserEventsDataStartInfo.RedirectStandardError = true; + + using Process checkUserEventsData = new() { StartInfo = checkUserEventsDataStartInfo }; + checkUserEventsData.OutputDataReceived += (_, e) => + { + if (!string.IsNullOrEmpty(e.Data)) + { + Console.WriteLine($"[user-events-check] {e.Data}"); + } + }; + checkUserEventsData.ErrorDataReceived += (_, e) => + { + if (!string.IsNullOrEmpty(e.Data)) + { + Console.Error.WriteLine($"[user-events-check] {e.Data}"); + } + }; + + checkUserEventsData.Start(); + checkUserEventsData.BeginOutputReadLine(); + checkUserEventsData.BeginErrorReadLine(); + checkUserEventsData.WaitForExit(); + if (checkUserEventsData.ExitCode == 0) + { + return true; + } + + Console.WriteLine($"User events data not available at '{UserEventsDataPath}'."); + return false; + } + + private static bool IsGlibcAtLeast(Version minVersion) + { + ProcessStartInfo lddStartInfo = new(); + lddStartInfo.FileName = "ldd"; + lddStartInfo.Arguments = "--version"; + lddStartInfo.UseShellExecute = false; + lddStartInfo.RedirectStandardOutput = true; + lddStartInfo.RedirectStandardError = true; + + using Process lddProcess = new() { StartInfo = lddStartInfo }; + string? detectedVersionLine = null; + + lddProcess.OutputDataReceived += (_, e) => + { + if (!string.IsNullOrEmpty(e.Data) && detectedVersionLine is null) + { + detectedVersionLine = e.Data; + } + }; + lddProcess.ErrorDataReceived += (_, e) => + { + if (!string.IsNullOrEmpty(e.Data)) + { + Console.Error.WriteLine($"[ldd] {e.Data}"); + } + }; + + try + { + lddProcess.Start(); + } + catch (Exception ex) + { + Console.WriteLine($"Failed to start 'ldd --version': {ex.Message}"); + return false; + } + + lddProcess.BeginOutputReadLine(); + lddProcess.BeginErrorReadLine(); + lddProcess.WaitForExit(); + + if (lddProcess.ExitCode != 0) + { + Console.WriteLine($"'ldd --version' exited with code {lddProcess.ExitCode}."); + return false; + } + + if (string.IsNullOrEmpty(detectedVersionLine)) + { + Console.WriteLine("Could not read glibc version from 'ldd --version' output."); + return false; + } + + string[] tokens = detectedVersionLine.Split(' ', StringSplitOptions.RemoveEmptyEntries); + Version? glibcVersion = null; + foreach (string token in tokens) + { + if (Version.TryParse(token, out Version? parsedVersion)) + { + glibcVersion = parsedVersion; + break; + } + } + + if (glibcVersion is null) + { + Console.WriteLine($"Failed to parse glibc version from 'ldd --version' output line: {detectedVersionLine}"); + return false; + } + + if (glibcVersion < minVersion) + { + Console.WriteLine($"glibc version '{glibcVersion}' is less than required '{minVersion}'."); + return false; + } + + return true; + } + } +} diff --git a/src/tests/tracing/userevents/common/UserEventsTestRunner.cs b/src/tests/tracing/userevents/common/UserEventsTestRunner.cs new file mode 100644 index 00000000000000..567aec069a4802 --- /dev/null +++ b/src/tests/tracing/userevents/common/UserEventsTestRunner.cs @@ -0,0 +1,267 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.IO; +using System.Linq; +using System.Runtime.InteropServices; +using System.Text.RegularExpressions; +using System.Threading; +using Microsoft.Diagnostics.Tracing; + +namespace Tracing.UserEvents.Tests.Common +{ + public class UserEventsTestRunner + { + private const int SIGINT = 2; + private const int DefaultTraceeExitTimeoutMs = 5000; + private const int DefaultRecordTraceExitTimeoutMs = 20000; + private const int DefaultTraceeDelayToSetupTracepointsMs = 200; + + [DllImport("libc", EntryPoint = "kill", SetLastError = true)] + private static extern int Kill(int pid, int sig); + + public static int Run( + string[] args, + string scenarioName, + string traceeAssemblyPath, + Action traceeAction, + Func traceValidator, + int traceeExitTimeout = DefaultTraceeExitTimeoutMs, + int recordTraceExitTimeout = DefaultRecordTraceExitTimeoutMs, + int traceeDelayToSetupTracepoints = DefaultTraceeDelayToSetupTracepointsMs) + { + if (args.Length > 0 && args[0].Equals("tracee", StringComparison.OrdinalIgnoreCase)) + { + if (traceeDelayToSetupTracepoints > 0) + { + Thread.Sleep(traceeDelayToSetupTracepoints); + } + + traceeAction(); + return 0; + } + + return RunOrchestrator( + scenarioName, + traceeAssemblyPath, + traceValidator, + traceeExitTimeout, + recordTraceExitTimeout); + } + + private static int RunOrchestrator( + string scenarioName, + string traceeAssemblyPath, + Func traceValidator, + int traceeExitTimeout, + int recordTraceExitTimeout) + { + string userEventsScenarioDir = Path.GetDirectoryName(traceeAssemblyPath); + string recordTracePath = ResolveRecordTracePath(userEventsScenarioDir); + string scriptFilePath = Path.Combine(userEventsScenarioDir, $"{scenarioName}.script"); + + if (!UserEventsRequirements.IsSupported()) + { + Console.WriteLine("Skipping test: environment does not support user events."); + return 100; + } + if (!File.Exists(recordTracePath)) + { + Console.Error.WriteLine($"record-trace not found at `{recordTracePath}`. Test cannot run."); + return -1; + } + if (!File.Exists(scriptFilePath)) + { + Console.Error.WriteLine($"record-trace script-file not found at `{scriptFilePath}`. Test cannot run."); + return -1; + } + + string traceFilePath = Path.GetTempFileName(); + // In the past, it's been observed that record-trace has trouble overwriting newly created temp files + // in `/tmp` (e.g. mktemp or Path.GetTempFileName). It's suspected to be a permissions issue. + // As a workaround, deleting the temp file and allowing record-trace to create it works reliably. + File.Delete(traceFilePath); + traceFilePath = Path.ChangeExtension(traceFilePath, ".nettrace"); + + ProcessStartInfo recordTraceStartInfo = new(); + recordTraceStartInfo.FileName = "sudo"; + recordTraceStartInfo.Arguments = $"-n {recordTracePath} --script-file {scriptFilePath} --out {traceFilePath}"; + recordTraceStartInfo.WorkingDirectory = userEventsScenarioDir; + recordTraceStartInfo.UseShellExecute = false; + recordTraceStartInfo.RedirectStandardOutput = true; + recordTraceStartInfo.RedirectStandardError = true; + + Console.WriteLine($"Starting record-trace: {recordTraceStartInfo.FileName} {recordTraceStartInfo.Arguments}"); + using Process recordTraceProcess = Process.Start(recordTraceStartInfo); + recordTraceProcess.OutputDataReceived += (_, args) => + { + if (!string.IsNullOrEmpty(args.Data)) + { + Console.WriteLine($"[record-trace] {args.Data}"); + } + }; + recordTraceProcess.BeginOutputReadLine(); + recordTraceProcess.ErrorDataReceived += (_, args) => + { + if (!string.IsNullOrEmpty(args.Data)) + { + Console.Error.WriteLine($"[record-trace] {args.Data}"); + } + }; + recordTraceProcess.BeginErrorReadLine(); + Console.WriteLine($"record-trace started with PID: {recordTraceProcess.Id}"); + + ProcessStartInfo traceeStartInfo = new(); + traceeStartInfo.FileName = Process.GetCurrentProcess().MainModule!.FileName; + traceeStartInfo.Arguments = $"{traceeAssemblyPath} tracee"; + traceeStartInfo.WorkingDirectory = userEventsScenarioDir; + traceeStartInfo.RedirectStandardOutput = true; + traceeStartInfo.RedirectStandardError = true; + + // record-trace currently only searches /tmp/ for diagnostic ports https://github.com/microsoft/one-collect/issues/183 + string diagnosticPortDir = "/tmp"; + traceeStartInfo.Environment["TMPDIR"] = diagnosticPortDir; + + // TMPDIR is configured on Helix, but the diagnostic port is created outside of Helix's default temp datadisk path. + // The diagnostic port should be automatically cleaned up when the tracee shuts down, but zombie sockets can be left + // behind after catastrophic exits. Clean them before launching the tracee to avoid deleting sockets from a reused PID. + // When https://github.com/microsoft/one-collect/issues/183 is fixed, this and the above TMPDIR should be removed. + EnsureCleanDiagnosticPorts(diagnosticPortDir); + + Console.WriteLine($"Starting tracee process: {traceeStartInfo.FileName} {traceeStartInfo.Arguments}"); + using Process traceeProcess = Process.Start(traceeStartInfo); + int traceePid = traceeProcess.Id; + Console.WriteLine($"Tracee process started with PID: {traceePid}"); + traceeProcess.OutputDataReceived += (_, args) => + { + if (!string.IsNullOrEmpty(args.Data)) + { + Console.WriteLine($"[tracee] {args.Data}"); + } + }; + traceeProcess.BeginOutputReadLine(); + traceeProcess.ErrorDataReceived += (_, args) => + { + if (!string.IsNullOrEmpty(args.Data)) + { + Console.Error.WriteLine($"[tracee] {args.Data}"); + } + }; + traceeProcess.BeginErrorReadLine(); + + Console.WriteLine($"Waiting for tracee process to exit..."); + if (!traceeProcess.HasExited && !traceeProcess.WaitForExit(traceeExitTimeout)) + { + Console.WriteLine($"Tracee process did not exit within the {traceeExitTimeout}ms timeout, killing it."); + traceeProcess.Kill(); + } + traceeProcess.WaitForExit(); // flush async output + + if (!recordTraceProcess.HasExited) + { + // Until record-trace supports duration, the only way to stop it is to send SIGINT (ctrl+c) + Console.WriteLine($"Stopping record-trace with SIGINT."); + Kill(recordTraceProcess.Id, SIGINT); + Console.WriteLine($"Waiting for record-trace to exit..."); + if (!recordTraceProcess.WaitForExit(recordTraceExitTimeout)) + { + // record-trace needs to stop gracefully to generate the trace file + Console.WriteLine($"record-trace did not exit within the {recordTraceExitTimeout}ms timeout, killing it."); + recordTraceProcess.Kill(); + } + } + else + { + Console.WriteLine($"record-trace unexpectedly exited without SIGINT with code {recordTraceProcess.ExitCode}."); + } + recordTraceProcess.WaitForExit(); // flush async output + + if (!File.Exists(traceFilePath)) + { + Console.Error.WriteLine($"Expected trace file not found at `{traceFilePath}`"); + return -1; + } + + using EventPipeEventSource source = new EventPipeEventSource(traceFilePath); + if (!traceValidator(source)) + { + Console.Error.WriteLine($"Trace file `{traceFilePath}` does not contain expected events."); + UploadTraceFileFromHelix(traceFilePath, scenarioName); + return -1; + } + + return 100; + } + + private static string ResolveRecordTracePath(string userEventsScenarioDir) + { + // scenario dir: .../tracing/userevents// + string usereventsRoot = Path.GetFullPath(Path.Combine(userEventsScenarioDir, "..", "..")); + // common dir: .../tracing/userevents/common/userevents_common + string commonDir = Path.Combine(usereventsRoot, "common", "userevents_common"); + string recordTracePath = Path.Combine(commonDir, "record-trace"); + return recordTracePath; + } + + // Similar to IpcTraceTest.EnsureCleanEnvironment, but scoped to the provided diagnosticPortDir. + // Check for zombie diagnostic IPC sockets left behind by previous runs and remove them. + // If multiple sockets exist for a running PID, delete all but the newest. + private static void EnsureCleanDiagnosticPorts(string diagnosticPortDir) + { + if (!Directory.Exists(diagnosticPortDir)) + { + return; + } + + Func<(IEnumerable>, List)> getPidsAndSockets = () => + { + IEnumerable> currentIpcs = Directory.GetFiles(diagnosticPortDir, "dotnet-diagnostic*") + .Select(filename => new { pid = int.Parse(Regex.Match(filename, @"dotnet-diagnostic-(?\d+)").Groups["pid"].Value), fileInfo = new FileInfo(filename) }) + .GroupBy(fileInfos => fileInfos.pid, fileInfos => fileInfos.fileInfo); + List currentPids = System.Diagnostics.Process.GetProcesses().Select(pid => pid.Id).ToList(); + return (currentIpcs, currentPids); + }; + + var (currentIpcs, currentPids) = getPidsAndSockets(); + + foreach (var ipc in currentIpcs) + { + if (!currentPids.Contains(ipc.Key)) + { + foreach (FileInfo fi in ipc) + { + Console.WriteLine($"Deleting zombie diagnostic port: {fi.FullName}"); + fi.Delete(); + } + } + else + { + if (ipc.Count() > 1) + { + // delete zombied pipes except newest which is owned + var duplicates = ipc.OrderBy(fileInfo => fileInfo.CreationTime.Ticks).SkipLast(1); + foreach (FileInfo fi in duplicates) + { + Console.WriteLine($"Deleting duplicate diagnostic port: {fi.FullName}"); + fi.Delete(); + } + } + } + } + } + + private static void UploadTraceFileFromHelix(string traceFilePath, string scenarioName) + { + var helixWorkItemDirectory = Environment.GetEnvironmentVariable("HELIX_WORKITEM_UPLOAD_ROOT"); + if (helixWorkItemDirectory != null && Directory.Exists(helixWorkItemDirectory)) + { + var destPath = Path.Combine(helixWorkItemDirectory, $"{scenarioName}.nettrace"); + Console.WriteLine($"Uploading trace file to Helix work item directory: {destPath}"); + File.Copy(traceFilePath, destPath, overwrite: true); + } + } + } +} \ No newline at end of file diff --git a/src/tests/tracing/userevents/common/userevents_common.csproj b/src/tests/tracing/userevents/common/userevents_common.csproj new file mode 100644 index 00000000000000..dff80ae7a50008 --- /dev/null +++ b/src/tests/tracing/userevents/common/userevents_common.csproj @@ -0,0 +1,41 @@ + + + BuildOnly + false + + + + + + + + + + + + + + <_DestDir>$(TargetDir) + <_DestDir Condition="'$(_DestDir)' == ''">$(OutputPath) + <_RecordTraceSource>$(NuGetPackageRoot)microsoft.onecollect.recordtrace/$(MicrosoftOneCollectRecordTraceVersion)/runtimes/linux-$(TargetArchitecture)/native/record-trace + <_RecordTraceRelative Condition="$(BuildProjectRelativeDir) != ''">$(BuildProjectRelativeDir)record-trace + <_RecordTraceRelative Condition="'$(_RecordTraceRelative)' == ''">$([System.IO.Path]::GetRelativePath('$(TestBinDir)', '$(_DestDir)record-trace')) + + + + + + + + + + + + + + diff --git a/src/tests/tracing/userevents/custommetadata/custommetadata.cs b/src/tests/tracing/userevents/custommetadata/custommetadata.cs new file mode 100644 index 00000000000000..50fdc3d242d48a --- /dev/null +++ b/src/tests/tracing/userevents/custommetadata/custommetadata.cs @@ -0,0 +1,92 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Diagnostics; +using System.Diagnostics.Tracing; +using Tracing.UserEvents.Tests.Common; +using Microsoft.Diagnostics.Tracing; + +namespace Tracing.UserEvents.Tests.CustomMetadata +{ + public static class CustomMetadata + { + public static void CustomMetadataTracee() + { + CustomMetadataEventSource.Log.WorkItem(1, "Item1"); + } + + private static readonly Func s_traceValidator = source => + { + bool anyMatching = false; + + source.Dynamic.All += (TraceEvent e) => + { + if (!string.Equals(e.ProviderName, "DemoCustomMetadata", StringComparison.Ordinal)) + { + return; + } + + if (!string.Equals(e.EventName, "WorkItem", StringComparison.Ordinal)) + { + return; + } + + try + { + object? idObj = e.PayloadByName("id"); + object? nameObj = e.PayloadByName("name"); + int id = idObj is null ? -1 : Convert.ToInt32(idObj); + string? name = nameObj as string; + + if (id != 1 || !string.Equals(name, "Item1", StringComparison.Ordinal)) + { + Console.Error.WriteLine($"Unexpected payload values: id={id}, name={name}"); + } + else + { + anyMatching = true; + Console.WriteLine($"CustomMetadata event: Id={id}, Name={name}"); + } + } + catch (Exception ex) + { + Console.Error.WriteLine($"Exception while reading CustomMetadata payload: {ex}"); + } + }; + + source.Process(); + + if (!anyMatching) + { + Console.Error.WriteLine("The trace did not contain the expected CustomMetadata event."); + } + + return anyMatching; + }; + + public static int Main(string[] args) + { + return UserEventsTestRunner.Run( + args, + "custommetadata", + typeof(CustomMetadata).Assembly.Location, + CustomMetadataTracee, + s_traceValidator); + } + } + + [EventSource(Name = "DemoCustomMetadata")] + public sealed class CustomMetadataEventSource : EventSource + { + public static readonly CustomMetadataEventSource Log = new CustomMetadataEventSource(); + + private CustomMetadataEventSource() : base(EventSourceSettings.EtwSelfDescribingEventFormat) {} + + [Event(1, Level = EventLevel.Informational)] + public void WorkItem(int id, string name) + { + WriteEvent(1, id, name); + } + } +} diff --git a/src/tests/tracing/userevents/custommetadata/custommetadata.csproj b/src/tests/tracing/userevents/custommetadata/custommetadata.csproj new file mode 100644 index 00000000000000..2e5c43fafccd4e --- /dev/null +++ b/src/tests/tracing/userevents/custommetadata/custommetadata.csproj @@ -0,0 +1,19 @@ + + + true + true + false + + + + + + + + + + Always + custommetadata.script + + + diff --git a/src/tests/tracing/userevents/custommetadata/custommetadata.script b/src/tests/tracing/userevents/custommetadata/custommetadata.script new file mode 100644 index 00000000000000..e0d6fe0b50830d --- /dev/null +++ b/src/tests/tracing/userevents/custommetadata/custommetadata.script @@ -0,0 +1,2 @@ +let DemoCustomMetadata_flags = new_dotnet_provider_flags(); +record_dotnet_provider("DemoCustomMetadata", 0x0, 5, DemoCustomMetadata_flags); diff --git a/src/tests/tracing/userevents/managedevent/managedevent.cs b/src/tests/tracing/userevents/managedevent/managedevent.cs new file mode 100644 index 00000000000000..798a86a723d2dd --- /dev/null +++ b/src/tests/tracing/userevents/managedevent/managedevent.cs @@ -0,0 +1,75 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Diagnostics; +using System.Diagnostics.Tracing; +using System.Threading; +using Tracing.UserEvents.Tests.Common; +using Microsoft.Diagnostics.Tracing; + +namespace Tracing.UserEvents.Tests.ManagedEvent +{ + public class ManagedEvent + { + public static void ManagedEventTracee() + { + long startTimestamp = Stopwatch.GetTimestamp(); + long targetTicks = Stopwatch.Frequency; // 1s + + while (Stopwatch.GetTimestamp() - startTimestamp < targetTicks) + { + ManagedUserEventSource.Log.SampleEvent("SampleWork"); + Thread.Sleep(100); + } + } + + private static readonly Func s_traceValidator = source => + { + bool sampleEventFound = false; + + source.Dynamic.All += (TraceEvent e) => + { + if (!string.Equals(e.ProviderName, "ManagedUserEvent", StringComparison.OrdinalIgnoreCase)) + { + return; + } + + if (e.EventName is null) + { + return; + } + + sampleEventFound = true; + }; + + source.Process(); + + if (!sampleEventFound) + { + Console.Error.WriteLine("The trace did not contain the expected managed event."); + } + + return sampleEventFound; + }; + + public static int Main(string[] args) + { + return UserEventsTestRunner.Run( + args, + "managedevent", + typeof(ManagedEvent).Assembly.Location, + ManagedEventTracee, + s_traceValidator); + } + } + + [EventSource(Name = "ManagedUserEvent")] + internal sealed class ManagedUserEventSource : EventSource + { + public static readonly ManagedUserEventSource Log = new ManagedUserEventSource(); + + [Event(1)] + public void SampleEvent(string requestName) => WriteEvent(1, requestName); + } +} \ No newline at end of file diff --git a/src/tests/tracing/userevents/managedevent/managedevent.csproj b/src/tests/tracing/userevents/managedevent/managedevent.csproj new file mode 100644 index 00000000000000..d3ed72c432a53d --- /dev/null +++ b/src/tests/tracing/userevents/managedevent/managedevent.csproj @@ -0,0 +1,19 @@ + + + true + true + false + + + + + + + + + + Always + managedevent.script + + + diff --git a/src/tests/tracing/userevents/managedevent/managedevent.script b/src/tests/tracing/userevents/managedevent/managedevent.script new file mode 100644 index 00000000000000..5d2e512acf1733 --- /dev/null +++ b/src/tests/tracing/userevents/managedevent/managedevent.script @@ -0,0 +1,2 @@ +let manageduserevent_flags = new_dotnet_provider_flags(); +record_dotnet_provider("ManagedUserEvent", 0x0, 5, manageduserevent_flags); diff --git a/src/tests/tracing/userevents/multithread/multithread.cs b/src/tests/tracing/userevents/multithread/multithread.cs new file mode 100644 index 00000000000000..eb7230f6922f76 --- /dev/null +++ b/src/tests/tracing/userevents/multithread/multithread.cs @@ -0,0 +1,105 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Diagnostics.Tracing; +using System.Threading; +using System.Threading.Tasks; +using Tracing.UserEvents.Tests.Common; +using Microsoft.Diagnostics.Tracing; + +namespace Tracing.UserEvents.Tests.MultiThread +{ + [EventSource(Name = "DemoMultiThread")] + public sealed class MultiThreadEventSource : EventSource + { + public static readonly MultiThreadEventSource Log = new MultiThreadEventSource(); + + private MultiThreadEventSource() {} + + [Event(1, Level = EventLevel.Informational)] + public void WorkerEvent(int workerId) + { + WriteEvent(1, workerId); + } + } + + public static class MultiThread + { + private const int WorkerCount = 4; + + public static void MultiThreadTracee() + { + Task[] tasks = new Task[WorkerCount]; + + for (int i = 0; i < WorkerCount; i++) + { + int workerId = i; + tasks[i] = Task.Run(() => + { + MultiThreadEventSource.Log.WorkerEvent(workerId); + }); + } + + Task.WaitAll(tasks); + } + + private static readonly Func s_traceValidator = source => + { + HashSet seenWorkers = new HashSet(); + + source.Dynamic.All += (TraceEvent e) => + { + if (!string.Equals(e.ProviderName, "DemoMultiThread", StringComparison.Ordinal)) + { + return; + } + + if (e.EventName is not "WorkerEvent") + { + return; + } + + int workerId = -1; + try + { + workerId = (int)(e.PayloadByName("workerId") ?? -1); + } + catch (Exception ex) + { + Console.Error.WriteLine($"Exception while reading workerId payload: {ex}"); + } + + if (workerId >= 0) + { + seenWorkers.Add(workerId); + } + }; + + source.Process(); + + for (int i = 0; i < WorkerCount; i++) + { + if (!seenWorkers.Contains(i)) + { + Console.Error.WriteLine($"Did not observe event for worker {i}."); + return false; + } + } + + return true; + }; + + public static int Main(string[] args) + { + return UserEventsTestRunner.Run( + args, + "multithread", + typeof(MultiThread).Assembly.Location, + MultiThreadTracee, + s_traceValidator); + } + } +} diff --git a/src/tests/tracing/userevents/multithread/multithread.csproj b/src/tests/tracing/userevents/multithread/multithread.csproj new file mode 100644 index 00000000000000..3fe2c9de43d545 --- /dev/null +++ b/src/tests/tracing/userevents/multithread/multithread.csproj @@ -0,0 +1,19 @@ + + + true + true + false + + + + + + + + + + Always + multithread.script + + + diff --git a/src/tests/tracing/userevents/multithread/multithread.script b/src/tests/tracing/userevents/multithread/multithread.script new file mode 100644 index 00000000000000..d874f623445c18 --- /dev/null +++ b/src/tests/tracing/userevents/multithread/multithread.script @@ -0,0 +1,2 @@ +let DemoMultiThread_flags = new_dotnet_provider_flags(); +record_dotnet_provider("DemoMultiThread", 0x0, 5, DemoMultiThread_flags);