How can log4net support microseconds?

[ringchenhao]

I change the config like this and the timestamp shows microseconds:

<conversionPattern value="[%date{yyyyMMdd HH:mm:ss.ffffff}] [%-5level] [%thread] - %message%newline"/>

[20250210 18:37:40.286202] [INFO ] [ListenClientConnect] - Service has startup.

But does it really work? learned from the internet that log4net does not support microseconds.

[FreeAndNil]

@ringchenhao yes, it will work.

But only for .net8 or higher, not for .net4x.

For more details see #230 (reply in thread)

[ringchenhao]

Let me explain my scenario in detail：
I am using log4net 2.0.17.0， and my project need microseconds in timestamps. It is said that the precision of log4net can only reach milliseconds.
To verify the possibility，I first change the conversionPattern like this,

<conversionPattern value="[%date{yyyyMMdd HH:mm:ss.ffffff}] [%-5level] [%thread] - %message%newline"/>

and add 10000 prints :

 for (int i = 0; i < 10000; i++)
   CLog.Info("Service has startup.");

The timestamps do show microseconds, but the values seem to be incorrect, same timestamp has been repeated thousands of times, and suddenly, time changed, and then it continues to repeat again:

[20250211 10:31:46.242503] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.242503] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.242503] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.242503] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.242503] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.242503] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.242503] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.242503] [INFO ] [ListenClientConnect] - Service has startup.
...
[20250211 10:31:46.242503] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.255387] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.255387] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.255387] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.255387] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.255387] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.255387] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.255387] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.255387] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.255387] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.255387] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.255387] [INFO ] [ListenClientConnect] - Service has startup.
[20250211 10:31:46.255387] [INFO ] [ListenClientConnect] - Service has startup.

I have seen 159984 , but I don't know how to use it ?
Can you give some more guidance？

thanks,very much

[FreeAndNil]

@ringchenhao f159984 is just a unit test to prove that your use case must work.
I've added another test in 1946fed.
This test uses exactly your conversion pattern.

Can you please do the following?

• upgrade to log4net 3.0.3
• post your complete config file

[ringchenhao]

my config file:

<configuration>
    <configSections>
        <section name="log4net" type="System.Configuration.IgnoreSectionHandler"/>
    </configSections>
    <log4net>
        <root>
            <level value="DEBUG"/>
            <appender-ref ref="RollingFileAppender"/>
        </root>
        <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
            <file value="./Log/"/>
            <rollingStyle value="Date"/>
            <datePattern value="yyyy-MM-dd&quot;.log&quot;"/>
            <staticLogFileName value="false"/>
            <appendToFile value="false"/>
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="[%date{yyyyMMdd HH:mm:ss.ffffff}] [%-5level] [%thread] - %message%newline"/>
            </layout>
            <Encoding value="utf-8"/>
        </appender>
    </log4net>
    <startup>
        <supportedRuntime version="v4.0" sku=".NETFramework,,Version=v4.8"/>
    </startup>
</configuration>

[ringchenhao]

using 3.0.3, and with config above, log print like this, it seems that timestamps change every 1 millisecond, and in other times timestamps remain unchanged :
...
[20250212 09:35:22.428768] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.428768] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.428768] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.428768] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.428768] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.428768] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.428768] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.428768] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.428768] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.428768] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.428768] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.428768] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.428768] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.428768] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.429769] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.429769] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.429769] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.429769] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.429769] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.429769] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.429769] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.429769] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.429769] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.429769] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.429769] [INFO ] [ListenClientConnect] - Service has startup.
[20250212 09:35:22.429769] [INFO ] [ListenClientConnect] - Service has startup.
...

[FreeAndNil]

Hi @ringchenhao,

I've stripped your problem down to

  [Test]
  public void DuplicateTimestampsTest()
  {
    const int maxDates = 100;
    List<DateTime> dates = new(maxDates);
    for (int i = 0; i < maxDates; i++)
    {
      dates.Add(DateTime.Now); // same result with DateTime.UtcNow
    }
    Assert.That(dates, Has.Count.EqualTo(dates.Distinct().Count()), "no duplicate timestamps allowed");
  }

This unit test is successful on .net8, but fails on .net4x.
As you may see there is nothing from log4net involved in this test.

DateTime.(Utc)Now seems to cache the current time for some time ;-)

If you need microseconds in your log file, you will need to move to .net8 or higher.

Hope this helps.