Reputation: 5524
I'm logging an Azure-based webapp using a Log4Net CSV appender with:
I'm seeing multiple entries with an identical timestamp - clearly not logging the actual instant of a given event on the server:
2018-03-19 21:59:52.000 OrderId: 191096 Starts to validate, multi:
2018-03-19 21:59:52.000 OrderId: 191096 validation request:
2018-03-19 21:59:52.000 OrderId: 191096 passed validation. AuthKey:6128994
2018-03-19 21:59:52.000 OrderId: 191096 Single starts
2018-03-19 21:59:52.000 OrderId: 191096 submits:
2018-03-19 21:59:52.000 SaveOrderChanges: 191096
2018-03-19 21:59:52.000 SaveOrderChanges: 191096
I had thought perhaps it take to do with when the logs are written out to file vs. when the entry is literally generated but unless I'm mis-reading the context, this answer indicates otherwise.
Clearly I have something misconfigured. My CSV is built using code found at: http://element533.blogspot.com/2010/05/writing-to-csv-using-log4net.html
Full appender:
<appender name="CsvFileAppender" type="log4net.Appender.FileAppender">
<file value="D:/home/logfiles/log4netCSV.log" />
<lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
<appendToFile value="true"/>
<threshold value="INFO" />
<layout type=" myWeb.CsvPatternLayout, myWeb">
<header value="DateTime,Thread,Level,Logger,Message,Exception " />
<conversionPattern value="%date%newfield[%thread]%newfield %-5level%newfield% %property{Ip} _+ %aspnet-request{ASP.NET_SessionId} _+ %logger %newfield%message%newfield%exception%endrow" />
</layout>
</appender>
Upvotes: 4
Views: 2168
Reputation: 17674
It is very strange that your dates are showing
2018-03-19 21:59:52.000
The default format is Iso8601 and separator between second and milisec is a comma:
https://github.com/apache/logging-log4net/blob/master/src/DateFormatter/Iso8601DateFormatter.cs#L26
I recommend you to use explicit dates:
%date{yyyy-MM-dd HH:mm:ss.fff}
Also if you want a CSV file you need to separate the values with commas:
<conversionPattern value="%date{yyyy-MM-dd HH:mm:ss.fff},[%thread],%level,..." />
I just tested this on Azure to see if it had anything to do, and it shows correctly:
http://swagger-net-test.azurewebsites.net/log4net.log
I have two log actions one right after the other and they do show different time stamps
DateTime,Thread,Level,Logger,Message
2018-04-08 13:19:48.658,[20],INFO,Swagger_Test.Controllers.LogController,Test1
2018-04-08 13:19:48.689,[20],ERROR,Swagger_Test.Controllers.LogController,Test2
Upvotes: 2