I have a WCF service which can get called by several users near-simultaneously. I am using using Log4Net to create and write to a log-file on a per-user basis. The LogicalThreadContext stores the fileName which we are using.
I've noticed that when the service gets called, the log files are all garbled up. There's log entries of (e.g.) User1 in the logfile of (e.g.) User2, and vice-versa.
I am suspecting that there is a bug in Log4Net's LogicalThreadContext implementation (which I'm using to store the logFile's name), or a bug with the RollingLogFile appender where it gets overwhelmed by the amount of requests and starts to write in an incorrect file.
I think this is a related post: Log4net LogicalThreadContext not working as expected
I want to achieve this:
LogFile1.log:
Text1ForLogFile1
Text2ForLogFile1
LogFile2.log:
Text1ForLogFile2
Text2ForLogFile2
I am getting this:
LogFile1.log:
Text1ForLogFile1
LogFile2.log:
Text1ForLogFile2
Text2ForLogFile1
Text2ForLogFile2
See below my code.
== Service code ==
[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}");
}
}
== Service config ==
<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>
== Client code ==
[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());
}
}
}
== Client config ==
<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>
I've tried to use GlobalContext to store the data and I've tried to use a workaround (which worked for other people in ASP.NET), where you create an object and use it's .ToString() overload to defer the value for Log4Net. Could it be that I need to create a separate appender, per user, at run-time?
I've made a simple project which can be used to replicate the bug and it can be found here: https://www.dropbox.com/scl/fi/62jl7hud7v5wnd7iza7f1/WindowsService1.zip?rlkey=c34amymuhfdpqu34118nwsvzr&dl=0
I've resolved the issue. When using a single Appender in Log4Net when servicing multiple threads near-simultaneously and using the Properties to specify a fileName, the Appender gets "overloaded". It seems like the Appender is unable to flush its contents to the file in time.
The fix is to create an Appender for each request and assign it to the logger you need. Then when you are done, remove the Appender so it doesn't linger around and doesn't keep a lock on the file.
See my new code and new config below.
In my code below there is a mention of a "CoreLog", which is a separate logger I use for generic logging. You don't need to use it and instead you can create the new logger without referencing the "CoreLog".
== Service code ==
[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();
}
}
}
}
== Service config ==
<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>