[MNG-8478] Fix formatting of timestamp in logger (#2046)

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 static Instant now() {
         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 Instant instant() {
         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.
      *

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");
+    }
+}

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>

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 @@
  */
 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 @@ protected void writeThrowable(Throwable t, PrintStream targetStream) {
         }
     }
 
-    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 @@ private void innerHandleNormalizedLoggingCall(
 
         // 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);
             }
         }

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,13 +88,19 @@ 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);
         if (defaultLogLevelString != null) {
             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);