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 5fa3de655cb9..963618e59fcb 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 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. *

@@ -93,6 +115,36 @@ public Instant instant() { return startInstant.plusNanos(elapsedNanos); } + /** + * Returns the wall clock time captured when this monotonic clock was initialized. + *

+ * 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. + *

+ * 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 000000000000..de561fb591a4 --- /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 ed451909b27d..f6fcc118c233 100644 --- a/impl/maven-logging/pom.xml +++ b/impl/maven-logging/pom.xml @@ -50,6 +50,11 @@ under the License. junit-jupiter-api test + + org.junit.jupiter + junit-jupiter-params + test + org.hamcrest hamcrest 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 611584404611..cd8d1e19f034 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 @@ */ 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); } } 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 63b3667402e3..0ea1a33498ca 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 @@ void init() { 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 000000000000..b79eb19984cf --- /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(); + } +}