sharanggupta opened a new issue, #4399:
URL: https://github.com/apache/logging-log4j2/issues/4399
## Description
Instants before `1970-01-01T00:00:00Z` are mishandled in two places, so `%d`
prints wrong or garbage seconds for an event whose timestamp is negative.
1. `MutableInstant.initFromEpochMilli(long, int)` divides `epochMilli` by
1000 with a truncating division. For a negative `epochMilli` that is not a
whole number of seconds, the result violates the invariant `0 <= nanoOfSecond <
1_000_000_000`, which `initFromEpochSecond` enforces and every consumer
expects: `initFromEpochMilli(-61_500, 0)` gives `epochSecond=-61` and
`nanoOfSecond=-500_000_000`, instead of `-62` and `500_000_000`.
2. `InstantPatternDynamicFormatter` (used by `%d` since 2.25.0) keys its
per-minute cache with `epochSecond / 60` and renders the seconds with
`epochSecond % 60`. Both truncate towards zero, so before the epoch the cached
minute is wrong and the seconds are negative: `ss` prints characters such as
`+'` and `,0`, and `s` prints `-59`.
Both are fixed by `Math.floorDiv` and `Math.floorMod`. I will open a pull
request.
Pre-1970 timestamps are rare in logs, so this is not urgent. It does make
the formatter disagree with `java.time` for a valid input.
## Configuration
**Version:** `2.x` at `c0de1b8` (2.27.0-SNAPSHOT). I did not test older
releases.
**Operating system:** any (arithmetic only); reproduced on macOS
**JDK:** Corretto 17
## Logs
None.
## Reproduction
```java
@Test
void mutableInstantBeforeTheEpoch() {
final MutableInstant instant = new MutableInstant();
instant.initFromEpochMilli(-61_500, 0);
assertEquals(-62, instant.getEpochSecond()); // actual: -61
assertEquals(500_000_000, instant.getNanoOfSecond()); // actual:
-500_000_000
}
@Test
void patternLayoutBeforeTheEpoch() { // with a UTC default time zone
final PatternLayout layout =
PatternLayout.newBuilder().withPattern("%d{HH:mm:ss.SSS}").build();
final LogEvent event =
Log4jLogEvent.newBuilder().setTimeMillis(-59_000).build();
assertEquals("23:59:01.000", layout.toSerializable(event)); // actual:
23:59:+'.000
}
```
With the default `%d`, an event at `-59_000` ms prints `1969-12-31
23:59:+',000` instead of `1969-12-31 23:59:01,000`.
A differential check of `InstantPatternDynamicFormatter` against
`DateTimeFormatter` over random patterns, zones and instants, about 230,000
comparisons per run, differs only for instants before the epoch (and for zones
whose offset has seconds, such as `Africa/Monrovia` before 1972, which
`InstantPatternDynamicFormatterTest` already excludes). After the change the
only remaining differences are those zones and the case described under
"Related".
## Related
`InstantPatternThreadLocalCachedFormatter` starts its per-thread cache with
the epoch instant `-1`. The first event on a thread whose epoch second (or
epoch millisecond, depending on the precision) is exactly `-1` therefore hits
the empty initial buffer and prints an empty string. That is a separate defect,
which I have left out of the pull request because #4322 rewrites that class.
--
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: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
