使用 InstanceContextMode.PerCall 时，Log4Net 在 WCF 服务中写入错误的日志文件

Question

我有一个 WCF 服务，可以由多个用户几乎同时调用。 我正在使用 Log4Net 基于每个用户创建并写入日志文件。 LogicalThreadContext 存储我们正在使用的文件名。

我注意到当服务被调用时，日志文件都是乱码。 （例如）User2 的日志文件中有（例如）User1 的日志条目，反之亦然。

我怀疑 Log4Net 的 LogicalThreadContext 实现（我用它来存储 logFile 的名称）存在错误，或者 RollingLogFile 附加程序存在错误，它被请求量淹没并开始写入不正确的文件.

我认为这是一个相关的帖子： Log4net LogicalThreadContext 未按预期工作

我想实现这个：

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>  

== 客户端代码==

[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>

我尝试使用 GlobalContext 来存储数据，并且尝试使用一种解决方法（这对 ASP.NET 中的其他人有效），您可以创建一个对象并使用它的 .ToString() 重载来推迟值对于 Log4Net。我是否需要在运行时为每个用户创建一个单独的附加程序？

我制作了一个简单的项目，可用于复制该错误，可以在此处找到： https://www.dropbox.com/scl/fi/62jl7hud7v5wnd7iza7f1/WindowsService1.zip?rlkey=c34amymuhfdpqu34118nwsvzr&dl=0

Answer 1

我已经解决了这个问题。 当在 Log4Net 中使用单个 Appender 几乎同时服务多个线程并使用属性指定文件名时，Appender 会“过载”。看来 Appender 无法及时将其内容刷新到文件中。

解决方法是为每个请求创建一个 Appender 并将其分配给您需要的记录器。然后，完成后，删除 Appender，这样它就不会徘徊，也不会锁定文件。

请参阅下面我的新代码和新配置。

在下面的代码中提到了“CoreLog”，它是我用于通用日志记录的单独记录器。您不需要使用它，而是可以创建新的记录器而不引用“CoreLog”。

==服务代码==

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

[ServiceBehavior(InstanceContextMode = InstanceContextMode.PerCall, ConcurrencyMode = ConcurrencyMode.Multiple)]
public class Service
    : IService
{
    private static readonly log4net.ILog _coreLog = null;

    static Service()
    {
        _coreLog = log4net.LogManager.GetLogger("CoreLog");
        log4net.Config.XmlConfigurator.Configure();
    }

    private log4net.ILog CreateLogger(string logFileName)
    {
        _coreLog.Info($"Creating '{logFileName}' appender...");

        var existingAppender = _coreLog
            .Logger
            .Repository
            .GetAppenders()
            .OfType<log4net.Appender.RollingFileAppender>()
            .FirstOrDefault();

        var appender = new log4net.Appender.RollingFileAppender
        {
            Name = logFileName,
            File = Path.Combine("Logs", $"{logFileName}_log-file.log"),
            AppendToFile = existingAppender.AppendToFile,
            MaxSizeRollBackups = existingAppender.MaxSizeRollBackups,
            MaxFileSize = existingAppender.MaxFileSize,
            RollingStyle = existingAppender.RollingStyle,
            StaticLogFileName = existingAppender.StaticLogFileName,
            Layout = existingAppender.Layout
        };

        appender.ActivateOptions();

        var logger = log4net.LogManager.GetLogger(logFileName);
        ((log4net.Repository.Hierarchy.Logger)logger.Logger).AddAppender(appender);

        return logger;
    }

    public async Task TestAsync(string value)
    {
        log4net.ILog log = null;

        try
        {
            log = CreateLogger(value);

            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}");
        }
        finally
        {
            //Cleanup, remove appender
            if (log != null)
            {
                ((log4net.Repository.Hierarchy.Logger)log.Logger).RemoveAllAppenders();
            }
        }
    }        
}

== 服务配置==

<configuration>
<configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler,log4net" />
</configSections>
<log4net>
    <root>
        <level value="DEBUG" />
    </root>
    <logger name="CoreLog">
        <appender-ref ref="RollingLogFileAppender" />
    </logger>
    <appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender">
        <file type="log4net.Util.PatternString" value="Logs\CoreLog_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>