Middleware crashing after Worker.Extensions.DurableTask v1.11.0 and later releases

[jcageman]

Description

We have the following middleware:

internal class CurrentUserMiddleware : IFunctionsWorkerMiddleware
{
    private readonly ILogger<CurrentUserMiddleware> _logger;

    public CurrentUserMiddleware(ILogger<CurrentUserMiddleware> logger)
    {
        _logger = logger;
    }

    public async Task Invoke(FunctionContext context, FunctionExecutionDelegate next)
    {
        var inputBindingFeature = context.Features.Get<Microsoft.Azure.Functions.Worker.Context.Features.IFunctionInputBindingFeature>();
        var inputBindingResult = await inputBindingFeature.BindFunctionInputAsync(context);

        var baseInputParameter = inputBindingResult.Values.OfType<BaseFunctionInput>().SingleOrDefault();
        if (baseInputParameter is not null)
        {
            CurrentUser.Value = baseInputParameter.User;
        }

        await next(context);
    }
}

The idea of this middleware is that any function (durable/activity/trigger) with a BaseFunctionInput set's a async local value that is automatically available in all code called by those functions.

Note: the problem occurs simply because of calling var inputBindingResult = await inputBindingFeature.BindFunctionInputAsync(context); here.

Expected behavior

This should correctly parse the function inputs typed such that this middleware can act on the function inputs.

Actual behavior

This used to work just fine in 1.10 and earlier versions, but now we get the following callstack in orchestrations:

 	System.Text.Json.dll!System.Text.Json.ThrowHelper.ThrowJsonReaderException(ref System.Text.Json.Utf8JsonReader json, System.Text.Json.ExceptionResource resource, byte nextByte, System.ReadOnlySpan<byte> bytes)	Unknown
 	System.Text.Json.dll!System.Text.Json.Utf8JsonReader.ConsumeValue(byte marker)	Unknown
 	System.Text.Json.dll!System.Text.Json.Utf8JsonReader.ReadFirstToken(byte first)	Unknown
 	System.Text.Json.dll!System.Text.Json.Utf8JsonReader.ReadSingleSegment()	Unknown
 	System.Text.Json.dll!System.Text.Json.Utf8JsonReader.Read()	Unknown
 	System.Text.Json.dll!System.Text.Json.Serialization.JsonConverter<Microsoft.DurableTask.TaskOrchestrationContext>.ReadCore(ref System.Text.Json.Utf8JsonReader reader, out Microsoft.DurableTask.TaskOrchestrationContext value, System.Text.Json.JsonSerializerOptions options, ref System.Text.Json.ReadStack state)	Unknown
 	System.Text.Json.dll!System.Text.Json.Serialization.Metadata.JsonTypeInfo<System.__Canon>.ContinueDeserialize<System.Text.Json.Serialization.StreamReadBufferState, System.__Canon>(ref System.Text.Json.Serialization.StreamReadBufferState bufferState, ref System.Text.Json.JsonReaderState jsonReaderState, ref System.Text.Json.ReadStack readStack, out System.__Canon value)	Unknown
 	System.Text.Json.dll!System.Text.Json.Serialization.Metadata.JsonTypeInfo<Microsoft.DurableTask.TaskOrchestrationContext>.DeserializeAsync<System.Text.Json.Serialization.StreamReadBufferState, System.IO.Stream>(System.IO.Stream utf8Json, System.Text.Json.Serialization.StreamReadBufferState bufferState, System.Threading.CancellationToken cancellationToken)	Unknown
 	System.Text.Json.dll!System.Text.Json.Serialization.Metadata.JsonTypeInfo<Microsoft.DurableTask.TaskOrchestrationContext>.DeserializeAsObjectAsync(System.IO.Stream utf8Json, System.Threading.CancellationToken cancellationToken)	Unknown
 	Azure.Core.dll!Azure.Core.Serialization.JsonObjectSerializer.DeserializeAsync(System.IO.Stream stream, System.Type returnType, System.Threading.CancellationToken cancellationToken)	Unknown
>	Microsoft.Azure.Functions.Worker.Core.dll!Microsoft.Azure.Functions.Worker.Converters.JsonPocoConverter.GetConversionResultFromDeserialization(byte[] bytes, System.Type type) Line 66	C#
 	Microsoft.Azure.Functions.Worker.Core.dll!Microsoft.Azure.Functions.Worker.Converters.JsonPocoConverter.ConvertAsync(Microsoft.Azure.Functions.Worker.Converters.ConverterContext context) Line 55	C#
 	Microsoft.Azure.Functions.Worker.Core.dll!Microsoft.Azure.Functions.Worker.Context.Features.DefaultInputConversionFeature.ConvertAsyncUsingConverter(Microsoft.Azure.Functions.Worker.Converters.IInputConverter converter, Microsoft.Azure.Functions.Worker.Converters.ConverterContext context) Line 94	C#
 	Microsoft.Azure.Functions.Worker.Core.dll!Microsoft.Azure.Functions.Worker.Context.Features.DefaultInputConversionFeature.ConvertAsync(Microsoft.Azure.Functions.Worker.Converters.ConverterContext converterContext) Line 78	C#
 	Microsoft.Azure.Functions.Worker.Core.dll!Microsoft.Azure.Functions.Worker.Context.Features.DefaultFunctionInputBindingFeature.ConvertAsync(Microsoft.Azure.Functions.Worker.FunctionContext context, Microsoft.Azure.Functions.Worker.FunctionParameter parameter, Microsoft.Azure.Functions.Worker.Converters.IConverterContextFactory converterContextFactory, Microsoft.Azure.Functions.Worker.Context.Features.IInputConversionFeature inputConversionFeature, object source) Line 160	C#
 	Microsoft.Azure.Functions.Worker.Core.dll!Microsoft.Azure.Functions.Worker.Context.Features.DefaultFunctionInputBindingFeature.BindFunctionInputAsync(Microsoft.Azure.Functions.Worker.FunctionContext context) Line 58	C#
 	My.App.Application.Functions.dll!My.App.Application.Functions.User.CurrentUserMiddleware.Invoke(Microsoft.Azure.Functions.Worker.FunctionContext context, Microsoft.Azure.Functions.Worker.Middleware.FunctionExecutionDelegate next) Line 40	C#
 	Microsoft.Azure.Functions.Worker.Core.dll!Microsoft.Extensions.Hosting.MiddlewareWorkerApplicationBuilderExtensions.UseMiddleware.AnonymousMethod__1(Microsoft.Azure.Functions.Worker.FunctionContext context) Line 105	C#
 	Microsoft.Azure.Functions.Worker.Extensions.DurableTask.dll!Microsoft.Azure.Functions.Worker.Extensions.DurableTask.DurableTaskFunctionsMiddleware.Invoke(Microsoft.Azure.Functions.Worker.FunctionContext functionContext, Microsoft.Azure.Functions.Worker.Middleware.FunctionExecutionDelegate next) Line 26	C#
 	Microsoft.Azure.Functions.Worker.Core.dll!Microsoft.Extensions.Hosting.MiddlewareWorkerApplicationBuilderExtensions.UseMiddleware.AnonymousMethod__1(Microsoft.Azure.Functions.Worker.FunctionContext context) Line 105	C#
 	Microsoft.Azure.Functions.Worker.Core.dll!Microsoft.Azure.Functions.Worker.FunctionsApplication.InvokeFunctionAsync(Microsoft.Azure.Functions.Worker.FunctionContext context) Line 76	C#
 	Microsoft.Azure.Functions.Worker.Grpc.dll!Microsoft.Azure.Functions.Worker.Handlers.InvocationHandler.InvokeAsync(Microsoft.Azure.Functions.Worker.Grpc.Messages.InvocationRequest request) Line 89	C#
 	Microsoft.Azure.Functions.Worker.Grpc.dll!Microsoft.Azure.Functions.Worker.GrpcWorker.InvocationRequestHandlerAsync(Microsoft.Azure.Functions.Worker.Grpc.Messages.InvocationRequest request) Line 121	C#
 	Microsoft.Azure.Functions.Worker.Grpc.dll!Microsoft.Azure.Functions.Worker.GrpcWorker.ProcessRequestCoreAsync(Microsoft.Azure.Functions.Worker.Grpc.Messages.StreamingMessage request) Line 80	C#
 	Microsoft.Azure.Functions.Worker.Grpc.dll!Microsoft.Azure.Functions.Worker.GrpcWorker.Microsoft.Azure.Functions.Worker.Grpc.IMessageProcessor.ProcessMessageAsync.AnonymousMethod__0() Line 65	C#

App Details

• Worker.Extensions.DurableTask v1.11 or higher (1.11 broke it and was removed from the nuget feed, but was never fixed afterwards)
• .NET 10

[jviau]

In 1.11.0 we made a change to delay the binding of durable types until the end of the middleware pipeline. This was done to avoid interfering with middleware execution context, which orchestration binding was previously doing (it would break any async work).

To workaround this, I recommend implementing your own IFunctionInputBindingFeature which wraps the existing IFunctionInputBindingFeature.

1. Call the wrapped IFunctionInputBindingFeature
2. Setup your async state afterwards in your wrapping IFunctionInputBindingFeature
3. In your middleware, call context.Features.Get<IFunctionInputBindingFeature>() (to get the current one for wrapping) and context.Features.Set<IFunctionInputBindingFeature>(wrapped) (to replace with your custom one)

This has the added benefit of always ensuring your code runs after binding is complete. The typical expectation is binding doesn't run until the very end of middleware. Your middleware moved binding to a much earlier time, where other components may not yet be ready for it.

[jcageman]

Thanks for the quick response, will give it a go!

[SuyliuMS]

Hi @jviau , I have a instrumentation middleware which records elapse time, like:

public async Task InvokeAsync(FunctionContext context, FunctionExecutionDelegate next)
{
    long startTime = await this.GetCurrentTime(context);

    try
    {
        await next(context);
    }
    finally
    {
        long endTime = await this.GetCurrentTime(context);
       
        long elapsedTime = this.CalculateElapsedTime(startTime, endTime);

        this.logger?.LogInformationWithColumns(
            "ExecutionInfo",
            new KeyValuePair<string, object>("FunctionName", functionName),
            new KeyValuePair<string, object>(nameof(context.InvocationId), context.InvocationId),
            new KeyValuePair<string, object>("StatusCode", statusCode),
            new KeyValuePair<string, object>("ElapsedTimeMs", elapsedTime.ToString()),
            new KeyValuePair<string, object>("TriggerType", triggerType));
}

 protected async Task<long> GetCurrentTime(FunctionContext context)
 {
     IFunctionInputBindingFeature inputBindingFeature = context.Features.Get<IFunctionInputBindingFeature>();
     FunctionInputBindingResult result = await inputBindingFeature.BindFunctionInputAsync(context);
     TaskOrchestrationContext orchestrationContext = (TaskOrchestrationContext)Array.Find(result.Values, x => x is TaskOrchestrationContext);
     return orchestrationContext.CurrentUtcDateTime.Ticks;
 }

This middleware can record logical duration for orchestrator and activity.

After upgrade package version, I tried to get a start time after inner function input binding, like:

public async ValueTask<FunctionInputBindingResult> BindFunctionInputAsync(FunctionContext context)
{
    // IMPORTANT: Let the worker + Durable extension do binding at the correct time
    var result = await this.inner.BindFunctionInputAsync(context);

    // After binding, orchestration trigger invocations will have TaskOrchestrationContext available
    var durableCtx = result.Values.OfType<TaskOrchestrationContext>().FirstOrDefault();
    if (durableCtx is not null)
    {
        context.Items[Key] = durableCtx;
        context.Items[StartTimeKey] = durableCtx.CurrentUtcDateTime.Ticks;
    }

    return result;
}

Then get start time and end time in middleware like:

// before next
await next(context);
// after next

// other code...

if (context.Items.TryGetValue(DurableContextCapturingBindingFeature.StartTimeKey, out var time))
{
    startTime = (long)time;
    context.Items.TryGetValue(DurableContextCapturingBindingFeature.Key, out var v);
    endTime = ((TaskOrchestrationContext)v).CurrentUtcDateTime.Ticks;
}

// log and metrics

But for second activity duration (my orchestrator call 2 activities), the elapse time seems much logger than normal (normal 5ms but ~1000ms now). I'm also not sure if other timestamp is correct.
Could you give me some suggestions for getting correct logic start time and end time for both orchestrator and activities?