You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "LeadAssimilator (via GitHub)" <gi...@apache.org> on 2025/05/22 06:56:18 UTC
[I] Using %date/%utcdate with ABSOLUTE and ISO8601 causes one of the dates to get partially stuck (logging-log4net)
LeadAssimilator opened a new issue, #247:
URL: https://github.com/apache/logging-log4net/issues/247
Using %date/%utcdate with ABSOLUTE and ISO8601 causes one of the dates to not change:
```xml
<appender name="Console" type="log4net.Appender.ConsoleAppender">
<layout type="log4net.Layout.PatternLayout" value="%utcdate{ABSOLUTE} %utcdate{ISO8601}%n" />
</appender>
```
yields:
```
06:48:26,722 2025-05-22 06:48:26,722
06:48:27,725 2025-05-22 06:48:26,725
```
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}.
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.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Using %date/%utcdate with ABSOLUTE and ISO8601 causes one of the dates to get partially stuck (logging-log4net)
Posted by "LeadAssimilator (via GitHub)" <gi...@apache.org>.
LeadAssimilator commented on issue #247:
URL: https://github.com/apache/logging-log4net/issues/247#issuecomment-2900822954
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:
```csharp
private static readonly ConcurrentDictionary<Type, (long timeToTheSecond, string timeString)> _sLastTimeStrings = new();
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Using %date/%utcdate with ABSOLUTE and ISO8601 causes one of the dates to get partially stuck (logging-log4net)
Posted by "FreeAndNil (via GitHub)" <gi...@apache.org>.
FreeAndNil commented on issue #247:
URL: https://github.com/apache/logging-log4net/issues/247#issuecomment-2900209210
Hi @LeadAssimilator,
what framework are you using?
.net4x or .net8+?
Can you add what your expected output would look like?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Using %date/%utcdate with ABSOLUTE and ISO8601 causes one of the dates to get partially stuck (logging-log4net)
Posted by "FreeAndNil (via GitHub)" <gi...@apache.org>.
FreeAndNil commented on issue #247:
URL: https://github.com/apache/logging-log4net/issues/247#issuecomment-2900737845
Sorry, I overlooked, that that the seconds were constant, but the ms changed.
I've created a unit test reproducing your issue: https://github.com/apache/logging-log4net/commit/6f9b7116993d6353e6587e579bc3d2f4269b97fe
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Using %date/%utcdate with ABSOLUTE and ISO8601 causes one of the dates to get partially stuck (logging-log4net)
Posted by "LeadAssimilator (via GitHub)" <gi...@apache.org>.
LeadAssimilator commented on issue #247:
URL: https://github.com/apache/logging-log4net/issues/247#issuecomment-2900562386
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!
No, I've already provided a full repro and all the details required. Can you please just run it?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Using multiple date patterns causes one of the dates to get partially stuck (logging-log4net)
Posted by "LeadAssimilator (via GitHub)" <gi...@apache.org>.
LeadAssimilator commented on issue #247:
URL: https://github.com/apache/logging-log4net/issues/247#issuecomment-2902629854
Yes, it works correctly now thanks!
You may wish to revisit the caching in general and consider making it optional or removing it. In my testing on net8, you need a log rate of at least ~1/65ms on average to match the overhead introduced by the caching logic vs. directly writing the time to the text writer each call. Exceeding 1/65ms on average seems rather unlikely in most applications. While the caching would speed up bursts of many statements within the same second, that would really have to be the overwhelmingly common case. Not to mention my tests were single threaded - for multithreaded logging, the caching logic's overhead would only increase when there is contention on the dictionary (though that could be mitigated by making the dictionary thread-local). Unless I'm missing something, I generally think this caching logic provides no material benefit to most applications (doesn't ever pay for its cpu cycle overhead cost) and really only serves to boost the times of naive/unrealistic benchmarks to the detriment
of real total/average performance.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Using %date/%utcdate with ABSOLUTE and ISO8601 causes one of the dates to get partially stuck (logging-log4net)
Posted by "FreeAndNil (via GitHub)" <gi...@apache.org>.
FreeAndNil commented on issue #247:
URL: https://github.com/apache/logging-log4net/issues/247#issuecomment-2900902249
I had the same idea ;-)
Can you please check whether #248 fixes your problem?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Using %date/%utcdate with ABSOLUTE and ISO8601 causes one of the dates to get partially stuck (logging-log4net)
Posted by "FreeAndNil (via GitHub)" <gi...@apache.org>.
FreeAndNil commented on issue #247:
URL: https://github.com/apache/logging-log4net/issues/247#issuecomment-2900547858
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.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Using %date/%utcdate with ABSOLUTE and ISO8601 causes one of the dates to get partially stuck (logging-log4net)
Posted by "LeadAssimilator (via GitHub)" <gi...@apache.org>.
LeadAssimilator commented on issue #247:
URL: https://github.com/apache/logging-log4net/issues/247#issuecomment-2900579427
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.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Using %date/%utcdate with ABSOLUTE and ISO8601 causes one of the dates to get partially stuck (logging-log4net)
Posted by "FreeAndNil (via GitHub)" <gi...@apache.org>.
FreeAndNil commented on issue #247:
URL: https://github.com/apache/logging-log4net/issues/247#issuecomment-2900496804
> 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?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Using %date/%utcdate with ABSOLUTE and ISO8601 causes one of the dates to get partially stuck (logging-log4net)
Posted by "LeadAssimilator (via GitHub)" <gi...@apache.org>.
LeadAssimilator commented on issue #247:
URL: https://github.com/apache/logging-log4net/issues/247#issuecomment-2900506443
> > 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).
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Using %date/%utcdate with ABSOLUTE and ISO8601 causes one of the dates to get partially stuck (logging-log4net)
Posted by "LeadAssimilator (via GitHub)" <gi...@apache.org>.
LeadAssimilator commented on issue #247:
URL: https://github.com/apache/logging-log4net/issues/247#issuecomment-2900409463
net48
expected output should be the dates/times always updated - in the above example, the second date never changes (the milliseconds do however, the rest of the date never does).
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Using multiple date patterns causes one of the dates to get partially stuck (logging-log4net)
Posted by "FreeAndNil (via GitHub)" <gi...@apache.org>.
FreeAndNil closed issue #247: Using multiple date patterns causes one of the dates to get partially stuck
URL: https://github.com/apache/logging-log4net/issues/247
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Using %date/%utcdate with ABSOLUTE and ISO8601 causes one of the dates to get partially stuck (logging-log4net)
Posted by "LeadAssimilator (via GitHub)" <gi...@apache.org>.
LeadAssimilator commented on issue #247:
URL: https://github.com/apache/logging-log4net/issues/247#issuecomment-2900431675
Same behavior in net8.
The example is easier to see with more lines:
```
08:55:08,749 2025-05-22 08:55:08,749
08:55:09,752 2025-05-22 08:55:08,752
08:55:10,754 2025-05-22 08:55:08,754
08:55:11,756 2025-05-22 08:55:08,756
08:55:12,758 2025-05-22 08:55:08,758
08:55:13,758 2025-05-22 08:55:08,758
08:55:14,759 2025-05-22 08:55:08,759
08:55:15,760 2025-05-22 08:55:08,760
08:55:16,762 2025-05-22 08:55:08,762
08:55:17,762 2025-05-22 08:55:08,762
08:55:18,764 2025-05-22 08:55:08,764
08:55:19,765 2025-05-22 08:55:08,765
08:55:20,767 2025-05-22 08:55:08,767
08:55:21,768 2025-05-22 08:55:08,768
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org