Plugin Trace Log implementation (#341)

* Evaluate ITracingService messages via String.Format and expose collected trace log

Trace messages with format args are now evaluated through String.Format so
invalid format strings surface during testing instead of being silently
swallowed. Arg-less messages remain verbatim, matching platform behavior.

Trace messages are also collected by the default tracing service factory and
exposed via XrmMockupBase.TraceLog (with ClearTraceLog) so tests can assert on
emitted trace output.

Co-Authored-By: Claude <noreply@anthropic.com> via Conducktor <conducktor@contextand.com>

* Group trace messages per plugin execution via PluginTraceLog

Trace messages are now grouped by the plugin execution that produced them,
mirroring the plugintracelog records of a real Dynamics 365 environment. Each
XrmMockupBase.PluginTraceLog entry captures the invoking type, message name,
primary entity, operation type, depth, correlation id, mode, request id,
execution start time, duration, the ordered list of trace messages and any
exception details.

PluginTrigger now times each sync/async plugin execution, captures thrown
exceptions and records an entry with the execution's own trace messages.
Internal XrmMockup system plugins are excluded. Configuration/secure
configuration and plugin step ids are not modeled by XrmMockup and remain null.

Co-Authored-By: Claude <noreply@anthropic.com> via Conducktor <conducktor@contextand.com>

* Extend grouped trace log to custom APIs and workflow activities

The per-execution trace grouping introduced for plugins now also covers custom
API executions and workflow activity executions (sync and async). A shared
PluginTraceRecorder helper centralizes the timing, exception capture and trace
message collection used by all three paths; CustomApiManager and WorkflowManager
now route their executions through it.

Custom API entries record the request name as the message and Plugin operation
type; workflow entries record the workflow name as the type, WorkflowActivity
operation type and the workflow's sync/async mode. Directly-invoked workflows
(ExecuteWorkflowRequest, which has no plugin context) are executed but not logged.

Co-Authored-By: Claude <noreply@anthropic.com> via Conducktor <conducktor@contextand.com>

* Address Copilot PR feedback on trace-log capture

- PluginTraceRecorder: fall back to the TargetInvocationException itself when
  it has no inner exception, so ExceptionDispatchInfo.Capture is never handed
  null (which would mask the original failure).
- TracingService: expose Messages as a read-only wrapper so callers cannot cast
  it back to List<string> and mutate recorded trace output.
- XrmMockupBase: return Array.Empty<string>() rather than allocating a new list
  on every TraceLog access when a custom tracing factory is configured.

Co-Authored-By: Claude <noreply@anthropic.com> via Conducktor <conducktor@contextand.com>

---------

Co-authored-by: Claude <noreply@anthropic.com> via Conducktor <conducktor@contextand.com>

Author: mkholt

src/XrmMockup365/Core.cs

@@ -837,6 +837,36 @@ public MockupServiceProviderAndFactory CreateServiceProviderAndFactory(PluginCon
             return new MockupServiceProviderAndFactory(this, pluginContext, TracingServiceFactory);
         }
 
+        private readonly List<PluginTraceLog> _pluginTraceLogs = new List<PluginTraceLog>();
+        private readonly object _pluginTraceLogLock = new object();
+
+        public void RecordPluginTrace(PluginTraceLog log)
+        {
+            lock (_pluginTraceLogLock)
+            {
+                _pluginTraceLogs.Add(log);
+            }
+        }
+
+        internal IReadOnlyList<PluginTraceLog> PluginTraceLogs
+        {
+            get
+            {
+                lock (_pluginTraceLogLock)
+                {
+                    return _pluginTraceLogs.ToList();
+                }
+            }
+        }
+
+        internal void ClearPluginTraceLogs()
+        {
+            lock (_pluginTraceLogLock)
+            {
+                _pluginTraceLogs.Clear();
+            }
+        }
+
         // ──────────────────────────────────────────────────────────────────────────
 
         internal void AddTime(TimeSpan offset)
@@ -1116,6 +1146,7 @@ internal void ResetEnvironment()
             this.TimeOffset = new TimeSpan();
             workflowManager.ResetWorkflows(settings.IncludeAllWorkflows);
 
+            ClearPluginTraceLogs();
             pluginManager.ResetPlugins();
             this.db = new XrmDb(metadata.EntityMetadata, OnlineDataService);
             this.RequestHandlers = GetRequestHandlers(db);

src/XrmMockup365/Internal/ICoreOperations.cs

@@ -55,6 +55,9 @@ internal interface ICoreOperations
         ITracingServiceFactory TracingServiceFactory { get; }
         MockupServiceProviderAndFactory CreateServiceProviderAndFactory(PluginContext pluginContext);
 
+        // Grouped trace log — PluginTrigger records one entry per plugin execution
+        void RecordPluginTrace(PluginTraceLog log);
+
         // Settings — used by WorkflowManager
         XrmMockupSettings GetMockupSettings();
     }

src/XrmMockup365/Plugin/CustomApiManager.cs

@@ -156,8 +156,20 @@ internal OrganizationResponse Execute(OrganizationRequest request, PluginContext
             thisPluginContext.Mode = 0;
 
             var serviceProvider = new MockupServiceProviderAndFactory(_core, thisPluginContext, _core.TracingServiceFactory);
-            registeredApis[request.RequestName](serviceProvider);
-            
+            var api = registeredApis[request.RequestName];
+            PluginTraceRecorder.Run(
+                _core,
+                serviceProvider,
+                thisPluginContext,
+                typeName: api.Target?.GetType().FullName,
+                messageName: request.RequestName,
+                primaryEntity: thisPluginContext.PrimaryEntityName,
+                operationType: PluginTraceOperationType.Plugin,
+                mode: XrmPluginCore.Enums.ExecutionMode.Synchronous,
+                execute: () => api(serviceProvider),
+                unwrapTargetInvocation: false,
+                record: true);
+
             pluginContext.OutputParameters.Clear();
             pluginContext.OutputParameters.AddRange(thisPluginContext.OutputParameters);
 

src/XrmMockup365/Plugin/PluginManager.cs

@@ -473,7 +473,9 @@ public void TriggerSystem(EventOperation operation, ExecutionStage stage,
                 return;
             }
 
-            plugins.ForEach(p => p.ExecuteIfMatch(entity, preImage, postImage, pluginContext, _core));
+            // System plugins are XrmMockup's own internal simulation, not user-registered steps,
+            // so they are excluded from the grouped plugin trace log.
+            plugins.ForEach(p => p.ExecuteIfMatch(entity, preImage, postImage, pluginContext, _core, recordTrace: false));
         }
 
         private string GeneratePluginCacheKey(IEnumerable<Type> basePluginTypes, IEnumerable<MetaPlugin> plugins)

src/XrmMockup365/Plugin/PluginTraceRecorder.cs

@@ -0,0 +1,86 @@
+using DG.Tools.XrmMockup.Internal;
+using Microsoft.Xrm.Sdk;
+using System;
+using System.Collections.Generic;
+using System.Diagnostics;
+using System.Linq;
+using System.Reflection;
+using System.Runtime.ExceptionServices;
+using XrmPluginCore.Enums;
+
+namespace DG.Tools.XrmMockup
+{
+    /// <summary>
+    /// Shared helper that runs a plugin, custom API or workflow execution while timing it and
+    /// capturing any thrown exception, then records a grouped <see cref="PluginTraceLog"/> entry
+    /// built from that execution's own trace messages together with the supplied metadata.
+    /// </summary>
+    internal static class PluginTraceRecorder
+    {
+        /// <param name="unwrapTargetInvocation">
+        /// When true, a <see cref="TargetInvocationException"/> is unwrapped and its inner exception
+        /// rethrown, preserving the plugin pipeline's historical behavior.
+        /// </param>
+        /// <param name="record">When false, the execution still runs but no trace entry is recorded (e.g. internal system plugins).</param>
+        public static void Run(
+            ICoreOperations core,
+            MockupServiceProviderAndFactory provider,
+            PluginContext ctx,
+            string typeName,
+            string messageName,
+            string primaryEntity,
+            PluginTraceOperationType operationType,
+            ExecutionMode mode,
+            Action execute,
+            bool unwrapTargetInvocation,
+            bool record)
+        {
+            var startTime = DateTime.UtcNow.Add(core.TimeOffset);
+            var stopwatch = Stopwatch.StartNew();
+            string exceptionDetails = null;
+            try
+            {
+                execute();
+            }
+            catch (TargetInvocationException e) when (unwrapTargetInvocation)
+            {
+                // Fall back to the TargetInvocationException itself when there is no inner
+                // exception, so Capture is never handed null (which would mask the failure).
+                var toThrow = e.InnerException ?? (Exception)e;
+                exceptionDetails = toThrow.ToString();
+                ExceptionDispatchInfo.Capture(toThrow).Throw();
+            }
+            catch (Exception e)
+            {
+                exceptionDetails = e.ToString();
+                throw;
+            }
+            finally
+            {
+                stopwatch.Stop();
+                if (record)
+                {
+                    var messages = (provider.GetService<ITracingService>() as TracingService)?.Messages.ToList()
+                        ?? new List<string>();
+
+                    core.RecordPluginTrace(new PluginTraceLog
+                    {
+                        TypeName = typeName,
+                        MessageName = messageName,
+                        PrimaryEntity = string.IsNullOrEmpty(primaryEntity) ? "none" : primaryEntity,
+                        OperationType = operationType,
+                        Depth = ctx.Depth,
+                        CorrelationId = ctx.CorrelationId,
+                        Mode = mode,
+                        RequestId = ctx.RequestId,
+                        ExecutionStartTime = startTime,
+                        ExecutionDurationMs = stopwatch.Elapsed.TotalMilliseconds,
+                        MessageBlock = messages,
+                        ExceptionDetails = exceptionDetails,
+                        // Configuration, SecureConfiguration and PluginStepId are not modeled by XrmMockup.
+                    });
+                }
+            }
+        }
+    }
+}

src/XrmMockup365/Plugin/PluginTrigger.cs

@@ -75,13 +75,18 @@ public PluginExecutionProvider ToPluginExecution(object entityObject, Entity pre
             {
                 // Create the plugin context
                 var thisPluginContext = CreatePluginContext(pluginContext, guid, logicalName, preImage, postImage);
-                return new PluginExecutionProvider(PluginExecute, core.CreateServiceProviderAndFactory(thisPluginContext));
+                var provider = core.CreateServiceProviderAndFactory(thisPluginContext);
+                // Preserve async exception semantics (no TargetInvocationException unwrapping), but
+                // still time the execution and capture its trace messages into the grouped trace log.
+                return new PluginExecutionProvider(
+                    p => ExecuteAndRecord(p, thisPluginContext, core, unwrapTargetInvocation: false, record: true),
+                    provider);
             }
 
             return null;
         }
 
-        public void ExecuteIfMatch(object entityObject, Entity preImage, Entity postImage, PluginContext pluginContext, ICoreOperations core)
+        public void ExecuteIfMatch(object entityObject, Entity preImage, Entity postImage, PluginContext pluginContext, ICoreOperations core, bool recordTrace = true)
         {
             // Check if it is supposed to execute. Returns preemptively, if it should not.
             var entity = entityObject as Entity;
@@ -107,14 +112,7 @@ public void ExecuteIfMatch(object entityObject, Entity preImage, Entity postImag
 
                 //Create Serviceprovider, and execute plugin
                 MockupServiceProviderAndFactory provider = core.CreateServiceProviderAndFactory(thisPluginContext);
-                try
-                {
-                    PluginExecute(provider);
-                }
-                catch (TargetInvocationException e)
-                {
-                    ExceptionDispatchInfo.Capture(e.InnerException).Throw();
-                }
+                ExecuteAndRecord(provider, thisPluginContext, core, unwrapTargetInvocation: true, record: recordTrace);
 
                 foreach (var parameter in thisPluginContext.SharedVariables)
                 {
@@ -123,6 +121,27 @@ public void ExecuteIfMatch(object entityObject, Entity preImage, Entity postImag
             }
         }
 
+        /// <summary>
+        /// Executes the plugin while timing it and capturing any thrown exception, then (when
+        /// <paramref name="record"/> is true) records a grouped <see cref="PluginTraceLog"/> entry
+        /// containing this execution's trace messages and metadata.
+        /// </summary>
+        private void ExecuteAndRecord(MockupServiceProviderAndFactory provider, PluginContext ctx, ICoreOperations core, bool unwrapTargetInvocation, bool record)
+        {
+            PluginTraceRecorder.Run(
+                core,
+                provider,
+                ctx,
+                typeName: PluginExecute.Target?.GetType().FullName,
+                messageName: !string.IsNullOrEmpty(ctx.MessageName) ? ctx.MessageName : Operation,
+                primaryEntity: ctx.PrimaryEntityName,
+                operationType: PluginTraceOperationType.Plugin,
+                mode: this.Mode,
+                execute: () => PluginExecute(provider),
+                unwrapTargetInvocation: unwrapTargetInvocation,
+                record: record);
+        }
+
         private void CheckInfiniteLoop(PluginContext pluginContext)
         {
             if (pluginContext.Depth > 8)

src/XrmMockup365/PluginTraceLog.cs

@@ -0,0 +1,85 @@
+using System;
+using System.Collections.Generic;
+using XrmPluginCore.Enums;
+
+namespace DG.Tools.XrmMockup
+{
+    /// <summary>
+    /// The type of operation that produced a <see cref="PluginTraceLog"/>, mirroring the
+    /// OperationType option set on the platform's plugintracelog entity.
+    /// </summary>
+    public enum PluginTraceOperationType
+    {
+        Unknown = 0,
+        Plugin = 1,
+        WorkflowActivity = 2,
+    }
+
+    /// <summary>
+    /// A single grouped trace-log entry, capturing all trace messages emitted by one
+    /// plugin (or workflow activity) execution together with the metadata identifying it,
+    /// mirroring the plugintracelog records produced by a real Dynamics 365 environment.
+    /// </summary>
+    public sealed class PluginTraceLog
+    {
+        /// <summary>The full name of the invoking type, e.g. the plugin class.</summary>
+        public string TypeName { get; internal set; }
+
+        /// <summary>The message being processed, e.g. Create, Update or a custom API name.</summary>
+        public string MessageName { get; internal set; }
+
+        /// <summary>The primary entity of the operation, or "none" if there is no bound entity.</summary>
+        public string PrimaryEntity { get; internal set; }
+
+        /// <summary>
+        /// The unsecure configuration supplied to the plugin step.
+        /// <para>Not currently modeled by XrmMockup and therefore always null.</para>
+        /// </summary>
+        public string Configuration { get; internal set; }
+
+        /// <summary>
+        /// The secure configuration supplied to the plugin step.
+        /// <para>Not currently modeled by XrmMockup and therefore always null.</para>
+        /// </summary>
+        public string SecureConfiguration { get; internal set; }
+
+        /// <summary>Whether the entry originated from a plugin or a workflow activity.</summary>
+        public PluginTraceOperationType OperationType { get; internal set; }
+
+        /// <summary>
+        /// The id of the plugin step (SDK message processing step) that was executed.
+        /// <para>Not currently modeled by XrmMockup and therefore always null.</para>
+        /// </summary>
+        public Guid? PluginStepId { get; internal set; }
+
+        /// <summary>The execution depth: 1 for a directly invoked plugin, 2 for a plugin invoked by a plugin, etc.</summary>
+        public int Depth { get; internal set; }
+
+        /// <summary>The correlation id shared across the whole execution chain.</summary>
+        public Guid CorrelationId { get; internal set; }
+
+        /// <summary>Whether the execution was synchronous or asynchronous.</summary>
+        public ExecutionMode Mode { get; internal set; }
+
+        /// <summary>The id of the request that triggered the execution, if available.</summary>
+        public Guid? RequestId { get; internal set; }
+
+        /// <summary>The time at which execution started, according to the mockup's (possibly offset) clock.</summary>
+        public DateTime ExecutionStartTime { get; internal set; }
+
+        /// <summary>The wall-clock duration of the execution, in milliseconds.</summary>
+        public double ExecutionDurationMs { get; internal set; }
+
+        /// <summary>
+        /// The trace messages emitted during the execution, in order. This is the platform's
+        /// "Message Block", kept as a list rather than a single concatenated string.
+        /// </summary>
+        public IReadOnlyList<string> MessageBlock { get; internal set; } = new List<string>();
+
+        /// <summary>The message and stack trace of the exception that ended the execution, or null if it succeeded.</summary>
+        public string ExceptionDetails { get; internal set; }
+
+        /// <summary>The <see cref="MessageBlock"/> joined into a single string, matching the platform's concatenated block.</summary>
+        public string MessageBlockText => string.Join(Environment.NewLine, MessageBlock ?? new List<string>());
+    }
+}

src/XrmMockup365/TracingService.cs

@@ -1,20 +1,43 @@
-using Microsoft.Xrm.Sdk;
+using Microsoft.Xrm.Sdk;
 using System;
+using System.Collections.Generic;
 
 namespace DG.Tools.XrmMockup
 {
 	internal sealed class TracingService : ITracingService
 	{
+		private readonly Action<string> _sink;
+		private readonly List<string> _messages = new List<string>();
+
+		public TracingService() : this(null) { }
+
+		/// <param name="sink">Optional callback invoked with each fully-evaluated trace message, allowing a consumer to collect them for assertions.</param>
+		public TracingService(Action<string> sink)
+		{
+			_sink = sink;
+		}
+
+		/// <summary>
+		/// The trace messages emitted through this service instance, in order. Because a fresh
+		/// service is created per plugin/workflow execution, this scopes the messages to that
+		/// single execution and lets them be grouped into a <see cref="PluginTraceLog"/>.
+		/// </summary>
+		public IReadOnlyList<string> Messages => _messages.AsReadOnly();
+
 		public void Trace(string format, params object[] args)
 		{
-			try
-			{
-				Console.WriteLine(format, args);
-			}
-			catch
-			{
-				Console.WriteLine(format);
-			}
+			// Match the platform's sandbox tracing service: a message supplied without
+			// arguments is emitted verbatim (so literal braces in e.g. XML/HTML are fine),
+			// while a message with arguments is evaluated through String.Format. We do NOT
+			// swallow a resulting FormatException, so invalid format strings surface during
+			// testing instead of silently slipping through to production.
+			var message = (args == null || args.Length == 0)
+				? format
+				: string.Format(format, args);
+
+			Console.WriteLine(message);
+			_messages.Add(message);
+			_sink?.Invoke(message);
 		}
 	}
 }