Using multiple date patterns causes one of the dates to get partially stuck

[LeadAssimilator]

With log4net 3.1.0 on all frameworks, using %date/%utcdate with ABSOLUTE and ISO8601 causes one of the dates to not change:

<?xml version="1.0" encoding="utf-8" ?>
<log4net>
  <appender name="Console1" type="log4net.Appender.ConsoleAppender">
    <layout type="log4net.Layout.PatternLayout" value="%utcdate{ABSOLUTE} &lt;- OK | STUCK -&gt; %utcdate{ISO8601}%n" />
  </appender>
  <appender name="Console2" type="log4net.Appender.ConsoleAppender">
    <layout type="log4net.Layout.PatternLayout" value="%23utcdate{ABSOLUTE} &lt;- OK%n" />
  </appender>
  <appender name="Console3" type="log4net.Appender.ConsoleAppender">
    <layout type="log4net.Layout.PatternLayout" value="%utcdate{ISO8601} &lt;- STUCK%n" />
  </appender>
  <root>
    <appender-ref ref="Console1" />
    <!--
    <appender-ref ref="Console2" />
    <appender-ref ref="Console3" />
    -->
  </root>
</log4net>

using System.Xml;
using log4net;
using log4net.Config;

namespace L4NTest;
internal class Program
{
  private static readonly ILog log = LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod()!.DeclaringType!);

  static void Main(string[] args)
  {
    XmlConfigurator.Configure(new FileInfo("log4net.config"));
    for (var i = 0; i < 125; ++i)
    {
      log.Debug("DOH");
      Thread.Sleep(1000);
    }
  }
}

yields:

08:58:17,140 <- OK | STUCK -> 2025-05-22 08:58:16,140
08:58:18,140 <- OK | STUCK -> 2025-05-22 08:58:16,140
08:58:19,141 <- OK | STUCK -> 2025-05-22 08:58:16,141
08:58:20,142 <- OK | STUCK -> 2025-05-22 08:58:16,142
08:58:21,143 <- OK | STUCK -> 2025-05-22 08:58:16,143
08:58:22,145 <- OK | STUCK -> 2025-05-22 08:58:16,145
08:58:23,146 <- OK | STUCK -> 2025-05-22 08:58:16,146
08:58:24,146 <- OK | STUCK -> 2025-05-22 08:58:16,146
08:58:25,148 <- OK | STUCK -> 2025-05-22 08:58:16,148
08:58:26,150 <- OK | STUCK -> 2025-05-22 08:58:16,150
08:58:27,152 <- OK | STUCK -> 2025-05-22 08:58:16,152
08:58:28,153 <- OK | STUCK -> 2025-05-22 08:58:16,153
08:58:29,154 <- OK | STUCK -> 2025-05-22 08:58:16,154

While it is uncommon to have two dates in the same layout, the same problem also occurs if using two different appenders with different layouts, one with %date/utcdate{ABSOLUTE} and the other with {ISO8601} (comment out Console1 and uncomment Console2 and Console3).

           09:10:12,194 <- OK
2025-05-22 09:10:11,194 <- STUCK
           09:10:13,196 <- OK
2025-05-22 09:10:11,196 <- STUCK
           09:10:14,197 <- OK
2025-05-22 09:10:11,197 <- STUCK
           09:10:15,199 <- OK
2025-05-22 09:10:11,199 <- STUCK
           09:10:16,199 <- OK
2025-05-22 09:10:11,199 <- STUCK
           09:10:17,200 <- OK
2025-05-22 09:10:11,200 <- STUCK
           09:10:18,201 <- OK
2025-05-22 09:10:11,201 <- STUCK

Notice that which date gets partially stuck depends on the order they appear in the layout, or if using multiple appenders/layouts, the order in which the appenders are referenced.

While both of the examples are somewhat contrived for simplicity of the repro, a real world example of this bug is when using both a Console appender and a File appender at the same time, one with %date/%utcdate{ABSOLUTE} and the other with {ISO8601} which causes one of them, depending on the reference order, to yield the correct date/time and the other to be incorrect and stuck with the initial value (except for the milliseconds).

[FreeAndNil]

Hi @LeadAssimilator,

what framework are you using?
.net4x or .net8+?

Can you add what your expected output would look like?

[LeadAssimilator]

net48

expected output should be the dates/times always update - in the above example, the second date never changes (the milliseconds do however, the rest of the date never does).

[LeadAssimilator]

Same behavior in net8.

The example is easier to see with more lines:

08:58:17,140 <- OK | STUCK -> 2025-05-22 08:58:16,140
08:58:18,140 <- OK | STUCK -> 2025-05-22 08:58:16,140
08:58:19,141 <- OK | STUCK -> 2025-05-22 08:58:16,141
08:58:20,142 <- OK | STUCK -> 2025-05-22 08:58:16,142
08:58:21,143 <- OK | STUCK -> 2025-05-22 08:58:16,143
08:58:22,145 <- OK | STUCK -> 2025-05-22 08:58:16,145
08:58:23,146 <- OK | STUCK -> 2025-05-22 08:58:16,146
08:58:24,146 <- OK | STUCK -> 2025-05-22 08:58:16,146
08:58:25,148 <- OK | STUCK -> 2025-05-22 08:58:16,148
08:58:26,150 <- OK | STUCK -> 2025-05-22 08:58:16,150
08:58:27,152 <- OK | STUCK -> 2025-05-22 08:58:16,152
08:58:28,153 <- OK | STUCK -> 2025-05-22 08:58:16,153
08:58:29,154 <- OK | STUCK -> 2025-05-22 08:58:16,154

That is logging once per second...

[FreeAndNil]

Same behavior in net8.

The example is easier to see with more lines:

08:58:16,137 <- OK | STUCK -> 2025-05-22 08:58:16,137
08:58:17,140 <- OK | STUCK -> 2025-05-22 08:58:16,140
08:58:18,140 <- OK | STUCK -> 2025-05-22 08:58:16,140
08:58:19,141 <- OK | STUCK -> 2025-05-22 08:58:16,141
08:58:20,142 <- OK | STUCK -> 2025-05-22 08:58:16,142
08:58:21,143 <- OK | STUCK -> 2025-05-22 08:58:16,143
08:58:22,145 <- OK | STUCK -> 2025-05-22 08:58:16,145
08:58:23,146 <- OK | STUCK -> 2025-05-22 08:58:16,146
08:58:24,146 <- OK | STUCK -> 2025-05-22 08:58:16,146
08:58:25,148 <- OK | STUCK -> 2025-05-22 08:58:16,148
08:58:26,150 <- OK | STUCK -> 2025-05-22 08:58:16,150
08:58:27,152 <- OK | STUCK -> 2025-05-22 08:58:16,152
08:58:28,153 <- OK | STUCK -> 2025-05-22 08:58:16,153
08:58:29,154 <- OK | STUCK -> 2025-05-22 08:58:16,154

That is logging once per second...

What is your expectation for this output to look like?

[LeadAssimilator]

Same behavior in net8.
The example is easier to see with more lines:

08:58:16,137 <- OK | STUCK -> 2025-05-22 08:58:16,137
08:58:17,140 <- OK | STUCK -> 2025-05-22 08:58:16,140
08:58:18,140 <- OK | STUCK -> 2025-05-22 08:58:16,140
08:58:19,141 <- OK | STUCK -> 2025-05-22 08:58:16,141
08:58:20,142 <- OK | STUCK -> 2025-05-22 08:58:16,142
08:58:21,143 <- OK | STUCK -> 2025-05-22 08:58:16,143
08:58:22,145 <- OK | STUCK -> 2025-05-22 08:58:16,145
08:58:23,146 <- OK | STUCK -> 2025-05-22 08:58:16,146
08:58:24,146 <- OK | STUCK -> 2025-05-22 08:58:16,146
08:58:25,148 <- OK | STUCK -> 2025-05-22 08:58:16,148
08:58:26,150 <- OK | STUCK -> 2025-05-22 08:58:16,150
08:58:27,152 <- OK | STUCK -> 2025-05-22 08:58:16,152
08:58:28,153 <- OK | STUCK -> 2025-05-22 08:58:16,153
08:58:29,154 <- OK | STUCK -> 2025-05-22 08:58:16,154

That is logging once per second...

What is your expectation for this output to look like?

I've answered this...the date/time should ALWAYS change/update - the left time should equal the right time (minus the date).

[FreeAndNil]

But in
08:58:16,137 <- OK | STUCK -> 2025-05-22 08:58:16,137
the left time equals the right time.

Can you add something like the following?
expected: abc
actual: acb

I hope this will help to understand your problem better.

[LeadAssimilator]

Omg, of course the very first line has the times match, it has to start from something/somewhere! It isn't magic. EVERY LINE AFTER THAT IS OF COURSE WRONG. HENCE THIS BUG!

Perhaps you missed the word ALWAYS. In the example, only the first line has the times match and the rest do not. That violates ALWAYS, i.e. it isn't true for all and it should be!

No, I've already provided a full repro and all the details required. Can you please just run it?

[LeadAssimilator]

I've deleted the first lines so you can't see them now unless you actually run the repo, so they won't confuse you.

[FreeAndNil]

Sorry, I overlooked, that that the seconds were constant, but the ms changed.
I've created a unit test reproducing your issue: 7851bb0

[LeadAssimilator]

The caching logic is broken in AbsoluteTimeDateFormatter.FormatDate. _sLastTimeToTheSecond is set by the first FormatDate call on type A with the current time, then when type B calls FormatDate with the same time, it thinks the nothing has changed and returns its really old, cached time string.

Also ConcurrentDictionary's update lambda provides no useful synchronization outside of itself afaik making the usage of _sLastTimeToTheSecond potentially unsafe (even if the code was otherwise working properly, the wrong string could still get returned sometimes).

I think the quickest/easiest solution to both problems is to move _sLastTimeToTheSecond into the dictionary value - i.e. store a tuple of both timeToTheSecond and timeString in the dictionary:

public virtual void FormatDate(DateTime dateToFormat, TextWriter writer)
{
  // Calculate the current time precise only to the second
  long currentTimeToTheSecond = dateToFormat.Ticks - (dateToFormat.Ticks % TimeSpan.TicksPerSecond);

  var lastTime = _sLastTimes.AddOrUpdate(GetType(),
    _ => (currentTimeToTheSecond, BuildTimeString()),
    (_, existing) =>
    {
      // Compare this time with the stored last time
      // If we are in the same second then append
      // the previously calculated time string
      if (existing.timeToTheSecond == currentTimeToTheSecond)
      {
        return existing;
      }

      return (currentTimeToTheSecond, BuildTimeString());
    });
  writer.EnsureNotNull().Write(lastTime.timeString);

  // Append the current millisecond info
  writer.Write(',');
  int millis = dateToFormat.Millisecond;
  if (millis < 100)
  {
    writer.Write('0');
  }
  if (millis < 10)
  {
    writer.Write('0');
  }
  writer.Write(millis);

  string BuildTimeString()
  {
    var sb = new StringBuilder();
    FormatDateWithoutMillis(dateToFormat, sb);
    return sb.ToString();
  }
}

/// <summary>
/// Last stored times with precision up to the second as both a long and formatted
/// as a string.
/// </summary>
private static readonly ConcurrentDictionary<Type, (long timeToTheSecond, string timeString)> _sLastTimes = new();

[FreeAndNil]

I had the same idea ;-)
Can you please check whether #248 fixes your problem?