WCF PerCall模式下Log4Net写入错误日志文件问题排查

我维护一个支持多用户近乎同时调用的WCF服务，使用Log4Net按用户维度创建并写入日志文件，通过LogicalThreadContext存储日志文件名。但并发调用时日志文件内容出现混乱，例如User1的日志条目会出现在User2的日志文件中，反之亦然。怀疑是Log4Net的LogicalThreadContext实现存在问题，或是RollingLogFile Appender在高请求量下出现错误写入的情况。

期望日志效果 #

LogFile1.log:
Text1ForLogFile1
Text2ForLogFile1

LogFile2.log:
Text1ForLogFile2
Text2ForLogFile2

实际日志效果 #

LogFile1.log:
Text1ForLogFile1

LogFile2.log:
Text1ForLogFile2
Text2ForLogFile1
Text2ForLogFile2

相关代码与配置 #

服务代码 #

[ServiceContract]
public interface IService
{
    [OperationContract]
    Task TestAsync(string value);
}

[ServiceBehavior(InstanceContextMode = InstanceContextMode.PerCall, ConcurrencyMode = ConcurrencyMode.Multiple)]
public class Service
    : IService
{
    public async Task TestAsync(string value)
    {
        LogicalThreadContext.Properties["logFileName"] = value;

        var log = LogManager.GetLogger(nameof(Service));
        XmlConfigurator.Configure();

        log.Info($"BEGIN: {value}");
        for (int i = 0; i < 25; i++)
        {
            //Simulate some work...
            await Task.Run(() => Thread.Sleep(500));

            log.Info($"{value}: #{i}");
        }
        log.Info($"END: {value}");
    }
}

服务配置 #

<configuration>
<configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler,log4net" />
</configSections>
<log4net>
    <root>
        <level value="DEBUG" />
        <appender-ref ref="RollingLogFileAppender" />
    </root>
    <appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender">
        <file type="log4net.Util.PatternString" value="Logs\%property{logFileName}_log-file.txt" />
        <appendToFile value="true" />
        <maxSizeRollBackups value="-1" />
        <maximumFileSize value="2MB" />
        <rollingStyle value="Size" />
        <staticLogFileName value="true" />
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%date ; %-5level ; %logger ; %message%newline" />
        </layout>
    </appender>
</log4net>

<system.serviceModel>       
    <bindings>
        <netTcpBinding>
            <binding name="defaultEndpoint" closeTimeout="00:20:00" openTimeout="00:20:00" receiveTimeout="00:20:00" sendTimeout="00:20:00" maxReceivedMessageSize="20971520">
                <readerQuotas maxDepth="32" maxStringContentLength="20971520" maxArrayLength="16384" maxBytesPerRead="4096" maxNameTableCharCount="16384" />
                <security mode="Transport">
                    <transport clientCredentialType="Windows" protectionLevel="EncryptAndSign" />
                    <message clientCredentialType="Windows" />
                </security>
            </binding>              
        </netTcpBinding>
    </bindings>
    <services>
        <service name="WindowsService1.Service">
            <clear />
            <endpoint address="net.tcp://localhost:9001/WindowsService1/Service/tcp"
                      binding="netTcpBinding"
                      bindingConfiguration="defaultEndpoint"
                      contract="WindowsService1.IService" >
                <identity>
                    <dns value="localhost" />
                </identity>
            </endpoint>

            <endpoint address="mex" binding="mexHttpBinding" contract="IMetadataExchange" />
            <host>
                <baseAddresses>
                    <add baseAddress="http://localhost:9000/WindowsService1/Service" />
                </baseAddresses>
            </host>
        </service>
    </services>
    <behaviors>
        <serviceBehaviors>
            <behavior>
                <serviceMetadata httpGetEnabled="true" />                   
                <serviceDebug includeExceptionDetailInFaults="true" />
            </behavior>
        </serviceBehaviors>
    </behaviors>
</system.serviceModel>

<startup>
    <supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.8" />
</startup>  
</configuration>

客户端代码 #

[TestClass]
public class UnitTest1
{
    [TestMethod]
    public async Task TestAsync()
    {
        using (var client = new ServiceReference1.ServiceClient())
        {
            var ids = new[] { 1, 2, 3, 4, 5 };
            Task.WaitAll(ids.Select(i => client.TestAsync($"FileName_{i}")).ToArray());
        }
    }
}

客户端配置 #

<configuration>
<system.serviceModel>
    <bindings>
        <netTcpBinding>
            <binding name="NetTcpBinding_IService">
                <security>
                    <transport sslProtocols="None" />
                </security>
            </binding>
        </netTcpBinding>
    </bindings>
    <client>
        <endpoint address="net.tcp://localhost:9001/WindowsService1/Service/tcp"
            binding="netTcpBinding" bindingConfiguration="NetTcpBinding_IService"
            contract="ServiceReference1.IService" name="NetTcpBinding_IService">
            <identity>
                <dns value="localhost" />
            </identity>
        </endpoint>
    </client>
</system.serviceModel>
</configuration>

我已尝试使用GlobalContext存储数据，以及ASP.NET环境下的延迟取值workaround，但问题仍存在。是否需要为每个用户在运行时创建独立的Appender？

内容的提问来源于stack exchange，提问作者Andre_IRIS