Fault path calls CreateErrorResponseMessage twice: error logged twice, ProvideFault invoked twice, and the message passed to BeforeSendReply is not the one sent

[juergotter]

Summary

When a service operation throws, the fault response is built twice. The error is written to the log twice, IFaultExceptionTransformer.ProvideFault is invoked twice, and the message that IMessageInspector2.BeforeSendReply receives is not the message that is sent to the client.

Code path

ProcessMessage catches the exception, builds a fault response, notifies the message inspectors, and rethrows (src/SoapCore/SoapEndpointMiddleware.cs, tag v1.2.1.15):

catch (Exception ex)
{
    responseMessage = CreateErrorResponseMessage(ex, serviceProvider, requestMessage, messageEncoder, httpContext);

    correlationObjects2.ForEach(mi => mi.inspector.BeforeSendReply(ref responseMessage, _service, mi.correlationObject));

    throw;
}

Because it rethrows, the exception reaches the catch in ProcessOperation, which calls CreateErrorResponseMessage again:

catch (Exception ex)
{
    responseMessage = CreateErrorResponseMessage(ex, serviceProvider, requestMessage, messageEncoder, httpContext);
}

That second message is the one written to the response. CreateErrorResponseMessage begins with

_logger.LogError(exception, "An error occurred processing the message");

and calls faultExceptionTransformer.ProvideFault(...).

Observed

Single POST to an operation that throws InvalidOperationException("boom"), SoapCore 1.2.1.15 on net8.0, SoapSerializer.XmlSerializer, MessageVersion.Soap12WSAddressingAugust2004:

	Observed
Error entries "An error occurred processing the message" from SoapCore.SoapEndpointMiddleware	2
IFaultExceptionTransformer.ProvideFault invocations	2
IMessageInspector2.AfterReceiveRequest invocations	1
IMessageInspector2.BeforeSendReply invocations	1
Header added by BeforeSendReply present in the fault received by the client	no

Expected

One fault response per faulting request: the error logged once, ProvideFault invoked once, and the message handed to BeforeSendReply being the message that is sent.

Affected versions

ProcessMessage in 1.1.0.51 has no catch around the operation invocation, only try/finally. The catch shown above is present in 1.1.0.53, 1.2.0.0, 1.2.1.0 and 1.2.1.15 (each read at its tag). 1.1.0.52 was not checked.

Reproduce

Repro.csproj

<Project Sdk="Microsoft.NET.Sdk.Web">
  <PropertyGroup>
    <TargetFramework>net8.0</TargetFramework>
    <ImplicitUsings>enable</ImplicitUsings>
  </PropertyGroup>
  <ItemGroup>
    <PackageReference Include="SoapCore" Version="1.2.1.15" />
  </ItemGroup>
</Project>

Program.cs

using System.ServiceModel;
using System.ServiceModel.Channels;
using SoapCore;
using SoapCore.Extensibility;
using SoapCore.ServiceModel;

[ServiceContract(Namespace = "urn:repro")]
public interface IReproService
{
    [OperationContract]
    string Boom(string input);
}

public class ReproService : IReproService
{
    public string Boom(string input) => throw new InvalidOperationException("boom");
}

public class CountingInspector : IMessageInspector2
{
    public static int AfterReceiveCalls;
    public static int BeforeSendReplyCalls;

    public object AfterReceiveRequest(ref Message message, ServiceDescription serviceDescription)
    {
        Interlocked.Increment(ref AfterReceiveCalls);
        return null;
    }

    public void BeforeSendReply(ref Message reply, ServiceDescription serviceDescription, object correlationState)
    {
        Interlocked.Increment(ref BeforeSendReplyCalls);
        reply.Headers.Add(MessageHeader.CreateHeader("InspectorStamp", "urn:repro", "was-here"));
    }
}

// Only used to count ProvideFault; register before AddSoapCore so the default is not added.
public class CountingFaultTransformer : IFaultExceptionTransformer
{
    public static int ProvideFaultCalls;

    public Message ProvideFault(Exception exception, MessageVersion messageVersion, Message requestMessage, ConcurrentXmlNamespaceLookup xmlNamespaceLookup)
    {
        Interlocked.Increment(ref ProvideFaultCalls);
        return Message.CreateMessage(messageVersion, action: null);
    }
}

public static class Program
{
    public static void Main(string[] args)
    {
        var builder = WebApplication.CreateBuilder(args);
        builder.Logging.ClearProviders();
        builder.Logging.AddSimpleConsole(o => o.SingleLine = true);

        if (args.Contains("--count-transformer"))
        {
            builder.Services.AddSingleton<IFaultExceptionTransformer, CountingFaultTransformer>();
        }

        builder.Services.AddSoapCore();
        builder.Services.AddSingleton<IReproService, ReproService>();
        builder.Services.AddSoapMessageInspector<CountingInspector>();

        var app = builder.Build();
        app.UseRouting();

        app.MapGet("/counters", () =>
            $"AfterReceiveRequest={CountingInspector.AfterReceiveCalls} "
            + $"BeforeSendReply={CountingInspector.BeforeSendReplyCalls} "
            + $"ProvideFault={CountingFaultTransformer.ProvideFaultCalls}");

        ((IApplicationBuilder)app).UseSoapEndpoint<IReproService>(
            path: "/Service.svc",
            new SoapEncoderOptions { MessageVersion = MessageVersion.Soap12WSAddressingAugust2004 },
            SoapSerializer.XmlSerializer);

        app.Run();
    }
}

Request:

POST /Service.svc
Content-Type: application/soap+xml; charset=utf-8; action="urn:repro/IReproService/Boom"

<s:Envelope xmlns:s="http://www.w3.org/2003/05/soap-envelope"
            xmlns:a="http://schemas.xmlsoap.org/ws/2004/08/addressing">
  <s:Header>
    <a:Action s:mustUnderstand="1">urn:repro/IReproService/Boom</a:Action>
    <a:To s:mustUnderstand="1">http://localhost:5000/Service.svc</a:To>
  </s:Header>
  <s:Body>
    <Boom xmlns="urn:repro"><input>x</input></Boom>
  </s:Body>
</s:Envelope>

Run without arguments to see the two log entries, the single BeforeSendReply call and the delivered fault without InspectorStamp. Run with --count-transformer to see ProvideFault=2; that run replaces the fault body, so use the two runs separately.
GET /counters returns the counters.

[andersjonsson]

Good catch!
It seems to have been introduced in this PR
#1113

My instinct would be to remove the first catch again and just move the call to
correlationObjects2.ForEach(mi => mi.inspector.BeforeSendReply(ref responseMessage, _service, mi.correlationObject));
to the catch block in ProcessOperation instead.

What do you think, and could you submit a PR with a fix? I don't have much time to work on SoapCore, but I try to look at issues and handle PRs

[juergotter]

What do you think, and could you submit a PR with a fix?

Done, PR #1193 - your suggestion, plus passing the correlation objects from ProcessMessage to ProcessOperation.
Details in the PR.