CODEWITHSUNDEEP
log4net
justSteve
justSteve

Reputation: 5524

Log4Net not displaying an accurate Timestamp

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&#13;&#10;" />
      <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

Answers (1)

Helder Sepulveda
Helder Sepulveda

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,..." />

Update:

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

Related Questions