This is an automated email from the ASF dual-hosted git repository.
gnodet pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/maven.git
The following commit(s) were added to refs/heads/master by this push:
new aeec37f8e7 [MNG-8478] Fix formatting of timestamp in logger (#2046)
aeec37f8e7 is described below
commit aeec37f8e7f968c5faebd99db87f9b5974b1cc53
Author: Guillaume Nodet <gno...@gmail.com>
AuthorDate: Wed Jan 15 07:28:29 2025 +0100
[MNG-8478] Fix formatting of timestamp in logger (#2046)
---
.../java/org/apache/maven/api/MonotonicClock.java | 52 +++++++
.../org/apache/maven/api/MonotonicClockTest.java | 150 ++++++++++++++++++++
impl/maven-logging/pom.xml | 5 +
.../org/apache/maven/slf4j/MavenBaseLogger.java | 29 ++--
.../maven/slf4j/SimpleLoggerConfiguration.java | 8 +-
.../maven/slf4j/MavenBaseLoggerTimestampTest.java | 152 +++++++++++++++++++++
6 files changed, 375 insertions(+), 21 deletions(-)
diff --git
a/api/maven-api-core/src/main/java/org/apache/maven/api/MonotonicClock.java
b/api/maven-api-core/src/main/java/org/apache/maven/api/MonotonicClock.java
index 5fa3de655c..963618e59f 100644
--- a/api/maven-api-core/src/main/java/org/apache/maven/api/MonotonicClock.java
+++ b/api/maven-api-core/src/main/java/org/apache/maven/api/MonotonicClock.java
@@ -19,6 +19,7 @@
package org.apache.maven.api;
import java.time.Clock;
+import java.time.Duration;
import java.time.Instant;
import java.time.ZoneId;
import java.time.ZoneOffset;
@@ -77,6 +78,27 @@ public class MonotonicClock extends Clock {
return get().instant();
}
+ /**
+ * Returns the initialization time of this monotonic clock.
+ * This is a convenience method equivalent to {@code get().start()}.
+ *
+ * @return the instant when this monotonic clock was initialized
+ * @see #startInstant()
+ */
+ public static Instant start() {
+ return get().startInstant();
+ }
+
+ /**
+ * Returns the elapsed time since clock initialization.
+ * This is a convenience method equivalent to {@code get().elapsedTime()}.
+ *
+ * @return the duration since clock initialization
+ */
+ public static Duration elapsed() {
+ return get().elapsedTime();
+ }
+
/**
* Returns a monotonically increasing instant.
* <p>
@@ -93,6 +115,36 @@ public class MonotonicClock extends Clock {
return startInstant.plusNanos(elapsedNanos);
}
+ /**
+ * Returns the wall clock time captured when this monotonic clock was
initialized.
+ * <p>
+ * This instant serves as the base time from which all subsequent {@link
#instant()}
+ * calls are calculated by adding the elapsed monotonic duration. This
ensures
+ * consistency between the monotonic measurements and wall clock time.
+ *
+ * @return the initial wall clock instant when this clock was created
+ * @see #instant()
+ */
+ public Instant startInstant() {
+ return startInstant;
+ }
+
+ /**
+ * Returns the duration elapsed since this clock was initialized.
+ * <p>
+ * The returned duration is calculated using {@link System#nanoTime()}
+ * to ensure monotonic behavior. This duration represents the exact time
+ * span between clock initialization and the current instant.
+ *
+ * @return the duration since clock initialization
+ * @see #startInstant()
+ * @see #instant()
+ */
+ public Duration elapsedTime() {
+ long elapsedNanos = System.nanoTime() - startNanos;
+ return Duration.ofNanos(elapsedNanos);
+ }
+
/**
* Returns the zone ID of this clock, which is always UTC.
*
diff --git
a/api/maven-api-core/src/test/java/org/apache/maven/api/MonotonicClockTest.java
b/api/maven-api-core/src/test/java/org/apache/maven/api/MonotonicClockTest.java
new file mode 100644
index 0000000000..de561fb591
--- /dev/null
+++
b/api/maven-api-core/src/test/java/org/apache/maven/api/MonotonicClockTest.java
@@ -0,0 +1,150 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements. See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership. The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied. See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ */
+package org.apache.maven.api;
+
+import java.time.Clock;
+import java.time.Duration;
+import java.time.Instant;
+import java.time.ZoneId;
+import java.time.ZoneOffset;
+
+import org.junit.jupiter.api.DisplayName;
+import org.junit.jupiter.api.Nested;
+import org.junit.jupiter.api.Test;
+
+import static org.junit.jupiter.api.Assertions.assertEquals;
+import static org.junit.jupiter.api.Assertions.assertNotNull;
+import static org.junit.jupiter.api.Assertions.assertSame;
+import static org.junit.jupiter.api.Assertions.assertTrue;
+
+class MonotonicClockTest {
+
+ @Test
+ @DisplayName("MonotonicClock singleton instance should always return the
same instance")
+ void testSingletonInstance() {
+ MonotonicClock clock1 = MonotonicClock.get();
+ MonotonicClock clock2 = MonotonicClock.get();
+
+ assertSame(clock1, clock2, "Multiple calls to get() should return the
same instance");
+ }
+
+ @Test
+ @DisplayName("MonotonicClock should always use UTC timezone")
+ void testClockTimezone() {
+ MonotonicClock clock = MonotonicClock.get();
+
+ assertEquals(ZoneOffset.UTC, clock.getZone(), "Clock should use UTC
timezone");
+
+ // Verify that attempting to change timezone returns the same instance
+ Clock newClock = clock.withZone(ZoneId.systemDefault());
+ assertSame(clock, newClock, "withZone() should return the same clock
instance");
+ }
+
+ @Test
+ @DisplayName("MonotonicClock should maintain monotonic time progression")
+ void testMonotonicBehavior() throws InterruptedException {
+ Instant first = MonotonicClock.now();
+ Thread.sleep(10); // Small delay
+ Instant second = MonotonicClock.now();
+ Thread.sleep(10); // Small delay
+ Instant third = MonotonicClock.now();
+
+ assertTrue(first.isBefore(second), "Time should progress forward
between measurements");
+ assertTrue(second.isBefore(third), "Time should progress forward
between measurements");
+ }
+
+ @Test
+ @DisplayName("MonotonicClock elapsed time should increase")
+ void testElapsedTime() throws InterruptedException {
+ Duration initial = MonotonicClock.elapsed();
+ Thread.sleep(50); // Longer delay for more reliable measurement
+ Duration later = MonotonicClock.elapsed();
+
+ assertTrue(later.compareTo(initial) > 0, "Elapsed time should
increase");
+ assertTrue(
+ later.minus(initial).toMillis() >= 45,
+ "Elapsed time difference should be at least 45ms (accounting
for some timing variance)");
+ }
+
+ @Test
+ @DisplayName("MonotonicClock start time should remain constant")
+ void testStartTime() throws InterruptedException {
+ Instant start1 = MonotonicClock.start();
+ Thread.sleep(10);
+ Instant start2 = MonotonicClock.start();
+
+ assertEquals(start1, start2, "Start time should remain constant");
+ assertNotNull(start1, "Start time should not be null");
+ }
+
+ @Nested
+ @DisplayName("Time consistency tests")
+ class TimeConsistencyTests {
+
+ @Test
+ @DisplayName("Current time should be after start time")
+ void testCurrentTimeAfterStart() {
+ Instant now = MonotonicClock.now();
+ Instant start = MonotonicClock.start();
+
+ assertTrue(now.isAfter(start), "Current time should be after start
time");
+ }
+
+ @Test
+ @DisplayName("Elapsed time should match time difference")
+ void testElapsedTimeConsistency() {
+ MonotonicClock clock = MonotonicClock.get();
+ Instant now = clock.instant();
+ Duration elapsed = clock.elapsedTime();
+ Duration calculated = Duration.between(clock.startInstant(), now);
+
+ // Allow for small timing differences (1ms) due to execution time
between measurements
+ assertTrue(
+ Math.abs(elapsed.toMillis() - calculated.toMillis()) <= 1,
+ "Elapsed time should match calculated duration between
start and now");
+ }
+ }
+
+ @Test
+ @DisplayName("MonotonicClock should handle rapid successive calls")
+ void testRapidCalls() {
+ Instant[] instants = new Instant[1000];
+ for (int i = 0; i < instants.length; i++) {
+ instants[i] = MonotonicClock.now();
+ }
+
+ // Verify monotonic behavior across all measurements
+ for (int i = 1; i < instants.length; i++) {
+ assertTrue(
+ instants[i].compareTo(instants[i - 1]) >= 0,
+ "Time should never go backwards even with rapid successive
calls");
+ }
+ }
+
+ @Test
+ @DisplayName("MonotonicClock should maintain reasonable alignment with
system time")
+ void testSystemTimeAlignment() {
+ Instant monotonic = MonotonicClock.now();
+ Instant system = Instant.now();
+
+ // The difference should be relatively small (allow for 1 second max)
+ Duration difference = Duration.between(monotonic, system).abs();
+ assertTrue(difference.getSeconds() <= 1, "Monotonic time should be
reasonably aligned with system time");
+ }
+}
diff --git a/impl/maven-logging/pom.xml b/impl/maven-logging/pom.xml
index ed451909b2..f6fcc118c2 100644
--- a/impl/maven-logging/pom.xml
+++ b/impl/maven-logging/pom.xml
@@ -50,6 +50,11 @@ under the License.
<artifactId>junit-jupiter-api</artifactId>
<scope>test</scope>
</dependency>
+ <dependency>
+ <groupId>org.junit.jupiter</groupId>
+ <artifactId>junit-jupiter-params</artifactId>
+ <scope>test</scope>
+ </dependency>
<dependency>
<groupId>org.hamcrest</groupId>
<artifactId>hamcrest</artifactId>
diff --git
a/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenBaseLogger.java
b/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenBaseLogger.java
index 6115844046..cd8d1e19f0 100644
---
a/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenBaseLogger.java
+++
b/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenBaseLogger.java
@@ -19,9 +19,9 @@
package org.apache.maven.slf4j;
import java.io.PrintStream;
-import java.time.Clock;
-import java.time.Duration;
-import java.time.Instant;
+import java.time.ZoneId;
+import java.time.ZonedDateTime;
+import java.time.format.DateTimeFormatter;
import java.util.ArrayList;
import java.util.List;
@@ -146,9 +146,6 @@ import org.slf4j.spi.LocationAwareLogger;
*/
public class MavenBaseLogger extends LegacyAbstractLogger {
- private static final Clock MONOTONIC_CLOCK = Clock.tick(Clock.systemUTC(),
Duration.ofMillis(1));
- private static final Instant START_TIME = MonotonicClock.now();
-
protected static final int LOG_LEVEL_TRACE = LocationAwareLogger.TRACE_INT;
protected static final int LOG_LEVEL_DEBUG = LocationAwareLogger.DEBUG_INT;
protected static final int LOG_LEVEL_INFO = LocationAwareLogger.INFO_INT;
@@ -165,7 +162,7 @@ public class MavenBaseLogger extends LegacyAbstractLogger {
static final SimpleLoggerConfiguration CONFIG_PARAMS = new
SimpleLoggerConfiguration();
- private static boolean initialized = false;
+ static boolean initialized = false;
static void lazyInit() {
if (initialized) {
@@ -266,15 +263,6 @@ public class MavenBaseLogger extends LegacyAbstractLogger {
}
}
- protected String getFormattedDate() {
- Instant now = MonotonicClock.now();
- String dateText;
- synchronized (CONFIG_PARAMS.dateFormatter) {
- dateText = CONFIG_PARAMS.dateFormatter.format(now);
- }
- return dateText;
- }
-
protected String computeShortName() {
return name.substring(name.lastIndexOf(".") + 1);
}
@@ -380,11 +368,14 @@ public class MavenBaseLogger extends LegacyAbstractLogger
{
// Append date-time if so configured
if (CONFIG_PARAMS.showDateTime) {
- if (CONFIG_PARAMS.dateFormatter != null) {
- buf.append(getFormattedDate());
+ DateTimeFormatter formatter = CONFIG_PARAMS.dateFormatter;
+ if (formatter != null) {
+ ZonedDateTime zonedDateTime =
MonotonicClock.now().atZone(ZoneId.systemDefault());
+ String dateText = formatter.format(zonedDateTime);
+ buf.append(dateText);
buf.append(SP);
} else {
- buf.append(Duration.between(START_TIME,
MonotonicClock.now()).toMillis());
+ buf.append(MonotonicClock.elapsed().toMillis());
buf.append(SP);
}
}
diff --git
a/impl/maven-logging/src/main/java/org/apache/maven/slf4j/SimpleLoggerConfiguration.java
b/impl/maven-logging/src/main/java/org/apache/maven/slf4j/SimpleLoggerConfiguration.java
index 63b3667402..0ea1a33498 100644
---
a/impl/maven-logging/src/main/java/org/apache/maven/slf4j/SimpleLoggerConfiguration.java
+++
b/impl/maven-logging/src/main/java/org/apache/maven/slf4j/SimpleLoggerConfiguration.java
@@ -53,8 +53,6 @@ public class SimpleLoggerConfiguration {
boolean showDateTime = SHOW_DATE_TIME_DEFAULT;
private static final String DATE_TIME_FORMAT_STR_DEFAULT = null;
- private static String dateTimeFormatStr = DATE_TIME_FORMAT_STR_DEFAULT;
-
DateTimeFormatter dateFormatter = null;
private static final boolean SHOW_THREAD_NAME_DEFAULT = true;
@@ -90,6 +88,9 @@ public class SimpleLoggerConfiguration {
private final Properties properties = new Properties();
void init() {
+ // Reset state before initialization
+ dateFormatter = null;
+
loadProperties();
String defaultLogLevelString =
getStringProperty(MavenBaseLogger.DEFAULT_LOG_LEVEL_KEY, null);
@@ -97,6 +98,9 @@ public class SimpleLoggerConfiguration {
defaultLogLevel = stringToLevel(defaultLogLevelString);
}
+ // local variable,
+ String dateTimeFormatStr;
+
showLogName =
getBooleanProperty(MavenBaseLogger.SHOW_LOG_NAME_KEY,
SimpleLoggerConfiguration.SHOW_LOG_NAME_DEFAULT);
showShortLogName =
getBooleanProperty(MavenBaseLogger.SHOW_SHORT_LOG_NAME_KEY,
SHOW_SHORT_LOG_NAME_DEFAULT);
diff --git
a/impl/maven-logging/src/test/java/org/apache/maven/slf4j/MavenBaseLoggerTimestampTest.java
b/impl/maven-logging/src/test/java/org/apache/maven/slf4j/MavenBaseLoggerTimestampTest.java
new file mode 100644
index 0000000000..b79eb19984
--- /dev/null
+++
b/impl/maven-logging/src/test/java/org/apache/maven/slf4j/MavenBaseLoggerTimestampTest.java
@@ -0,0 +1,152 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements. See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership. The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied. See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ */
+package org.apache.maven.slf4j;
+
+import java.io.ByteArrayOutputStream;
+import java.io.PrintStream;
+
+import org.junit.jupiter.api.AfterEach;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Test;
+import org.junit.jupiter.params.ParameterizedTest;
+import org.junit.jupiter.params.provider.ValueSource;
+
+import static org.hamcrest.MatcherAssert.assertThat;
+import static org.hamcrest.Matchers.matchesPattern;
+
+class MavenBaseLoggerTimestampTest {
+ private ByteArrayOutputStream logOutput;
+ private PrintStream originalErr;
+ private static final String LOGGER_NAME = "test.logger";
+ private MavenBaseLogger logger;
+
+ @BeforeEach
+ void setUp() {
+ // Reset configuration before each test
+ System.clearProperty(MavenBaseLogger.SHOW_DATE_TIME_KEY);
+ System.clearProperty(MavenBaseLogger.DATE_TIME_FORMAT_KEY);
+
+ // Reset static initialization flag
+ MavenBaseLogger.initialized = false;
+
+ // Capture System.err
+ logOutput = new ByteArrayOutputStream();
+ originalErr = System.err;
+ System.setErr(new PrintStream(logOutput));
+ }
+
+ @AfterEach
+ void tearDown() {
+ System.setErr(originalErr);
+ System.clearProperty(MavenBaseLogger.SHOW_DATE_TIME_KEY);
+ System.clearProperty(MavenBaseLogger.DATE_TIME_FORMAT_KEY);
+ MavenBaseLogger.initialized = false;
+ }
+
+ @Test
+ void whenShowDateTimeIsFalse_shouldNotIncludeTimestamp() {
+ // Given
+ System.setProperty(MavenBaseLogger.SHOW_DATE_TIME_KEY, "false");
+ initializeLogger();
+
+ // When
+ logger.info("Test message");
+ String output = getLastLine(logOutput.toString());
+
+ // Then
+ assertThat(
+ "Should not include timestamp", output,
matchesPattern("^\\[main\\] INFO test.logger - Test message$"));
+ }
+
+ @Test
+ void whenShowDateTimeIsTrue_withoutFormat_shouldShowElapsedTime() { //
Changed test name and expectation
+ // Given
+ System.setProperty(MavenBaseLogger.SHOW_DATE_TIME_KEY, "true");
+ initializeLogger();
+
+ // When
+ logger.info("Test message");
+ String output = getLastLine(logOutput.toString());
+
+ // Then
+ assertThat(
+ "Should show elapsed time when no format specified",
+ output,
+ matchesPattern("^\\d+ \\[main\\] INFO test.logger - Test
message$"));
+ }
+
+ @ParameterizedTest
+ @ValueSource(strings = {"yyyy-MM-dd HH:mm:ss", "dd/MM/yyyy HH:mm:ss.SSS",
"HH:mm:ss"})
+ void whenCustomDateFormat_shouldFormatCorrectly(String dateFormat) {
+ // Given
+ System.setProperty(MavenBaseLogger.SHOW_DATE_TIME_KEY, "true");
+ System.setProperty(MavenBaseLogger.DATE_TIME_FORMAT_KEY, dateFormat);
+ initializeLogger();
+
+ // When
+ logger.info("Test message");
+ String output = getLastLine(logOutput.toString());
+
+ // Then
+ String patternStr = dateFormat
+ .replace("yyyy", "\\d{4}")
+ .replace("MM", "\\d{2}")
+ .replace("dd", "\\d{2}")
+ .replace("HH", "\\d{2}")
+ .replace("mm", "\\d{2}")
+ .replace("ss", "\\d{2}")
+ .replace("SSS", "\\d{3}")
+ .replace("/", "\\/")
+ .replace(".", "\\.");
+
+ assertThat(
+ "Should match custom date format",
+ output,
+ matchesPattern("^" + patternStr + " \\[main\\] INFO
test.logger - Test message$"));
+ }
+
+ @Test
+ void whenInvalidDateFormat_shouldUseElapsedMillis() {
+ // Given
+ System.setProperty(MavenBaseLogger.SHOW_DATE_TIME_KEY, "true");
+ System.setProperty(MavenBaseLogger.DATE_TIME_FORMAT_KEY,
"invalid-format");
+ initializeLogger();
+
+ // When
+ logger.info("Test message");
+ String output = getLastLine(logOutput.toString());
+
+ // Then
+ assertThat(
+ "Should show elapsed milliseconds when format is invalid",
+ output,
+ matchesPattern("^\\d+ \\[main\\] INFO test.logger - Test
message$"));
+ }
+
+ private void initializeLogger() {
+ MavenBaseLogger.CONFIG_PARAMS.init();
+ logger = new MavenBaseLogger(LOGGER_NAME);
+ logOutput.reset();
+ }
+
+ private String getLastLine(String output) {
+ String[] lines = output.split("\\R");
+ return lines[lines.length - 1].trim();
+ }
+}
