.NET: [Bug]: Executor fires spurious Invoked→Completed cycles before performing actual work

[e1em3ntoDX]

Description

We encountered this behavior while building an AI-powered feature for a DevExpress product, which uses the Microsoft Agent Framework as its multi-agent orchestration backbone. A key requirement for our UX is showing per-executor "thinking…" progress indicators — which we think is what ExecutorInvokedEvent can be used for. The spurious event pairs make this unreliable.

We'd love it if you review the sample implementation and let us know if this is the intended behavior. If so, please let us know what actions we need to take to achieve our goal.

What happened?

When running a multi-agent workflow, each AIAgent executor first produces one or two "empty" ExecutorInvokedEvent / ExecutorCompletedEvent pairs with small/near-zero deltas before the genuine invocation that does actual LLM work. The real call is only visible as a final ExecutorCompletedEvent with a large delta (hundreds to thousands of ms).

Example

[06:59:30.155] SuperStepStartedEvent         +85 ms      Δ85 ms                                                                       
[06:59:30.158] ExecutorInvokedEvent          +88 ms      Δ3 ms        FirstAgent — spurious                                      
[06:59:30.162] ExecutorCompletedEvent        +92 ms      Δ4 ms        FirstAgent — spurious                                 
[06:59:30.162] ExecutorInvokedEvent          +92 ms      Δ0 ms       FirstAgent — real work (?)                                    
[06:59:31.735] ExecutorCompletedEvent        +1665 ms    Δ1573 ms    FirstAgent — real work                                
[06:59:31.740] SuperStepCompletedEvent       +1671 ms    Δ5 ms                                                                        
[06:59:31.741] SuperStepStartedEvent         +1671 ms    Δ0 ms                                                                        
[06:59:31.741] ExecutorInvokedEvent          +1671 ms    Δ0 ms       SecondAgent — spurious                                        
[06:59:31.742] ExecutorCompletedEvent        +1672 ms    Δ0 ms       SecondAgent — spurious                                        
[06:59:31.742] ExecutorInvokedEvent          +1672 ms    Δ0 ms       SecondAgent — spurious                                       
[06:59:31.742] ExecutorCompletedEvent        +1672 ms    Δ0 ms       SecondAgent — spurious                                     
[06:59:31.742] ExecutorInvokedEvent          +1672 ms    Δ0 ms       SecondAgent — real work (?)                                      
[06:59:32.601] ExecutorCompletedEvent        +2531 ms    Δ859 ms     SecondAgent — real work 
[06:59:32.601] SuperStepCompletedEvent       +2531 ms    Δ0 ms                                                     

What did you expect to happen?

Each executor should probably produce exactly one logical lifecycle:
ExecutorInvokedEvent → (LLM call happens) → ExecutorCompletedEvent

Steps to reproduce the issue:

1. Clone https://github.com/art-denisov/WorkflowSample
2. Set AZURE_OPENAI_ENDPOINT and AZURE_OPENAI_API_KEY environment variables. Notice that the default model used in the sample is gpt-4.1
3. Run the project as-is (3-agent linear workflow: FirstAgent → SecondAgent → LastMessageExecutor)
4. Observe the streamed events via run.WatchStreamAsync()
5. Note the spurious Invoked→Completed pairs before the real invocation

Code Sample

var workflow = new WorkflowBuilder(firstAgent)
    .AddEdge(firstAgent, secondAgent)
    .AddEdge(secondAgent, outputExecutor)
    .WithOutputFrom(outputExecutor)
    .Build();

await using var run = await InProcessExecution.StreamAsync(workflow, "Say hello.");

await foreach (var evt in run.WatchStreamAsync())
{
    var timestamp = DateTime.Now.ToString("HH:mm:ss.fff");
    switch (evt)
    {
        case ExecutorInvokedEvent invoke:
            Console.WriteLine($"[{timestamp}] ExecutorInvokedEvent   {invoke.ExecutorId}");
            break;
        case ExecutorCompletedEvent complete:
            Console.WriteLine($"[{timestamp}] ExecutorCompletedEvent {complete.ExecutorId}");
            break;
        case WorkflowOutputEvent output:
            Console.WriteLine($"[{timestamp}] WorkflowOutputEvent    {output.Data}");
            return;
        case WorkflowErrorEvent error:
            Console.WriteLine($"[{timestamp}] WorkflowErrorEvent     {error.Exception}");
            return;
    }
}

Error Messages / Stack Traces

[11:48:56.429] ExecutorInvokedEvent   +62ms    Δ4ms     FirstAgent_02082627b99...   ← spurious
[11:48:56.442] ExecutorCompletedEvent +75ms    Δ12ms    FirstAgent_02082627b99...   ← spurious
[11:48:56.443] ExecutorInvokedEvent   +76ms    Δ1ms     FirstAgent_02082627b99...   ← spurious
[11:48:59.201] ExecutorCompletedEvent +2834ms  Δ2758ms  FirstAgent_02082627b99...   ← real work

Second agent shows the same pattern (Δ0ms spurious pairs). 
Moreover, sometimes there are one or two spurious pairs of events being invoked.
LastMessageExecutor (custom Executor subclass, no LLM call) shows the same pattern — rules out LLM latency as the cause.

Package Versions

Azure.AI.OpenAI 2.9.0-beta.1, Microsoft.Agents.AI 1.0.0-rc4, Microsoft.Agents.AI.Workflows 1.0.0-rc4, Microsoft.Extensions.AI 10.3.0, Microsoft.Extensions.AI.OpenAI 10.3.0

.NET Version

.NET 10

Additional Context

No response