Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 4 commits into from
Jan 15, 2025
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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>
Expand All @@ -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.
*
Expand Down
Original file line number Diff line number Diff line change
@@ -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");
}
}
5 changes: 5 additions & 0 deletions impl/maven-logging/pom.xml
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand Down Expand Up @@ -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;
Expand All @@ -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) {
Expand Down Expand Up @@ -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);
}
Expand Down Expand Up @@ -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);
}
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
Expand Down
Loading
Loading