Skip to content

Commit aeec37f

Browse files
gnodetgnodet
authored
[MNG-8478] Fix formatting of timestamp in logger (apache#2046)
1 parent 81b7565 commit aeec37f

File tree

6 files changed

+375
-21
lines changed

6 files changed

+375
-21
lines changed

‎api/maven-api-core/src/main/java/org/apache/maven/api/MonotonicClock.java‎

Lines changed: 52 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@
1919
package org.apache.maven.api;
2020

2121
import java.time.Clock;
22+
import java.time.Duration;
2223
import java.time.Instant;
2324
import java.time.ZoneId;
2425
import java.time.ZoneOffset;
@@ -77,6 +78,27 @@ public static Instant now() {
7778
return get().instant();
7879
}
7980

81+
/**
82+
* Returns the initialization time of this monotonic clock.
83+
* This is a convenience method equivalent to {@code get().start()}.
84+
*
85+
* @return the instant when this monotonic clock was initialized
86+
* @see #startInstant()
87+
*/
88+
public static Instant start() {
89+
return get().startInstant();
90+
}
91+
92+
/**
93+
* Returns the elapsed time since clock initialization.
94+
* This is a convenience method equivalent to {@code get().elapsedTime()}.
95+
*
96+
* @return the duration since clock initialization
97+
*/
98+
public static Duration elapsed() {
99+
return get().elapsedTime();
100+
}
101+
80102
/**
81103
* Returns a monotonically increasing instant.
82104
* <p>
@@ -93,6 +115,36 @@ public Instant instant() {
93115
return startInstant.plusNanos(elapsedNanos);
94116
}
95117

118+
/**
119+
* Returns the wall clock time captured when this monotonic clock was initialized.
120+
* <p>
121+
* This instant serves as the base time from which all subsequent {@link #instant()}
122+
* calls are calculated by adding the elapsed monotonic duration. This ensures
123+
* consistency between the monotonic measurements and wall clock time.
124+
*
125+
* @return the initial wall clock instant when this clock was created
126+
* @see #instant()
127+
*/
128+
public Instant startInstant() {
129+
return startInstant;
130+
}
131+
132+
/**
133+
* Returns the duration elapsed since this clock was initialized.
134+
* <p>
135+
* The returned duration is calculated using {@link System#nanoTime()}
136+
* to ensure monotonic behavior. This duration represents the exact time
137+
* span between clock initialization and the current instant.
138+
*
139+
* @return the duration since clock initialization
140+
* @see #startInstant()
141+
* @see #instant()
142+
*/
143+
public Duration elapsedTime() {
144+
long elapsedNanos = System.nanoTime() - startNanos;
145+
return Duration.ofNanos(elapsedNanos);
146+
}
147+
96148
/**
97149
* Returns the zone ID of this clock, which is always UTC.
98150
*

‎api/maven-api-core/src/test/java/org/apache/maven/api/MonotonicClockTest.java‎

Lines changed: 150 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,150 @@
1+
/*
2+
* Licensed to the Apache Software Foundation (ASF) under one
3+
* or more contributor license agreements. See the NOTICE file
4+
* distributed with this work for additional information
5+
* regarding copyright ownership. The ASF licenses this file
6+
* to you under the Apache License, Version 2.0 (the
7+
* "License"); you may not use this file except in compliance
8+
* with the License. You may obtain a copy of the License at
9+
*
10+
* http://www.apache.org/licenses/LICENSE-2.0
11+
*
12+
* Unless required by applicable law or agreed to in writing,
13+
* software distributed under the License is distributed on an
14+
* "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
15+
* KIND, either express or implied. See the License for the
16+
* specific language governing permissions and limitations
17+
* under the License.
18+
*/
19+
package org.apache.maven.api;
20+
21+
import java.time.Clock;
22+
import java.time.Duration;
23+
import java.time.Instant;
24+
import java.time.ZoneId;
25+
import java.time.ZoneOffset;
26+
27+
import org.junit.jupiter.api.DisplayName;
28+
import org.junit.jupiter.api.Nested;
29+
import org.junit.jupiter.api.Test;
30+
31+
import static org.junit.jupiter.api.Assertions.assertEquals;
32+
import static org.junit.jupiter.api.Assertions.assertNotNull;
33+
import static org.junit.jupiter.api.Assertions.assertSame;
34+
import static org.junit.jupiter.api.Assertions.assertTrue;
35+
36+
class MonotonicClockTest {
37+
38+
@Test
39+
@DisplayName("MonotonicClock singleton instance should always return the same instance")
40+
void testSingletonInstance() {
41+
MonotonicClock clock1 = MonotonicClock.get();
42+
MonotonicClock clock2 = MonotonicClock.get();
43+
44+
assertSame(clock1, clock2, "Multiple calls to get() should return the same instance");
45+
}
46+
47+
@Test
48+
@DisplayName("MonotonicClock should always use UTC timezone")
49+
void testClockTimezone() {
50+
MonotonicClock clock = MonotonicClock.get();
51+
52+
assertEquals(ZoneOffset.UTC, clock.getZone(), "Clock should use UTC timezone");
53+
54+
// Verify that attempting to change timezone returns the same instance
55+
Clock newClock = clock.withZone(ZoneId.systemDefault());
56+
assertSame(clock, newClock, "withZone() should return the same clock instance");
57+
}
58+
59+
@Test
60+
@DisplayName("MonotonicClock should maintain monotonic time progression")
61+
void testMonotonicBehavior() throws InterruptedException {
62+
Instant first = MonotonicClock.now();
63+
Thread.sleep(10); // Small delay
64+
Instant second = MonotonicClock.now();
65+
Thread.sleep(10); // Small delay
66+
Instant third = MonotonicClock.now();
67+
68+
assertTrue(first.isBefore(second), "Time should progress forward between measurements");
69+
assertTrue(second.isBefore(third), "Time should progress forward between measurements");
70+
}
71+
72+
@Test
73+
@DisplayName("MonotonicClock elapsed time should increase")
74+
void testElapsedTime() throws InterruptedException {
75+
Duration initial = MonotonicClock.elapsed();
76+
Thread.sleep(50); // Longer delay for more reliable measurement
77+
Duration later = MonotonicClock.elapsed();
78+
79+
assertTrue(later.compareTo(initial) > 0, "Elapsed time should increase");
80+
assertTrue(
81+
later.minus(initial).toMillis() >= 45,
82+
"Elapsed time difference should be at least 45ms (accounting for some timing variance)");
83+
}
84+
85+
@Test
86+
@DisplayName("MonotonicClock start time should remain constant")
87+
void testStartTime() throws InterruptedException {
88+
Instant start1 = MonotonicClock.start();
89+
Thread.sleep(10);
90+
Instant start2 = MonotonicClock.start();
91+
92+
assertEquals(start1, start2, "Start time should remain constant");
93+
assertNotNull(start1, "Start time should not be null");
94+
}
95+
96+
@Nested
97+
@DisplayName("Time consistency tests")
98+
class TimeConsistencyTests {
99+
100+
@Test
101+
@DisplayName("Current time should be after start time")
102+
void testCurrentTimeAfterStart() {
103+
Instant now = MonotonicClock.now();
104+
Instant start = MonotonicClock.start();
105+
106+
assertTrue(now.isAfter(start), "Current time should be after start time");
107+
}
108+
109+
@Test
110+
@DisplayName("Elapsed time should match time difference")
111+
void testElapsedTimeConsistency() {
112+
MonotonicClock clock = MonotonicClock.get();
113+
Instant now = clock.instant();
114+
Duration elapsed = clock.elapsedTime();
115+
Duration calculated = Duration.between(clock.startInstant(), now);
116+
117+
// Allow for small timing differences (1ms) due to execution time between measurements
118+
assertTrue(
119+
Math.abs(elapsed.toMillis() - calculated.toMillis()) <= 1,
120+
"Elapsed time should match calculated duration between start and now");
121+
}
122+
}
123+
124+
@Test
125+
@DisplayName("MonotonicClock should handle rapid successive calls")
126+
void testRapidCalls() {
127+
Instant[] instants = new Instant[1000];
128+
for (int i = 0; i < instants.length; i++) {
129+
instants[i] = MonotonicClock.now();
130+
}
131+
132+
// Verify monotonic behavior across all measurements
133+
for (int i = 1; i < instants.length; i++) {
134+
assertTrue(
135+
instants[i].compareTo(instants[i - 1]) >= 0,
136+
"Time should never go backwards even with rapid successive calls");
137+
}
138+
}
139+
140+
@Test
141+
@DisplayName("MonotonicClock should maintain reasonable alignment with system time")
142+
void testSystemTimeAlignment() {
143+
Instant monotonic = MonotonicClock.now();
144+
Instant system = Instant.now();
145+
146+
// The difference should be relatively small (allow for 1 second max)
147+
Duration difference = Duration.between(monotonic, system).abs();
148+
assertTrue(difference.getSeconds() <= 1, "Monotonic time should be reasonably aligned with system time");
149+
}
150+
}

‎impl/maven-logging/pom.xml‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -50,6 +50,11 @@ under the License.
5050
<artifactId>junit-jupiter-api</artifactId>
5151
<scope>test</scope>
5252
</dependency>
53+
<dependency>
54+
<groupId>org.junit.jupiter</groupId>
55+
<artifactId>junit-jupiter-params</artifactId>
56+
<scope>test</scope>
57+
</dependency>
5358
<dependency>
5459
<groupId>org.hamcrest</groupId>
5560
<artifactId>hamcrest</artifactId>

‎impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenBaseLogger.java‎

Lines changed: 10 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -19,9 +19,9 @@
1919
package org.apache.maven.slf4j;
2020

2121
import java.io.PrintStream;
22-
import java.time.Clock;
23-
import java.time.Duration;
24-
import java.time.Instant;
22+
import java.time.ZoneId;
23+
import java.time.ZonedDateTime;
24+
import java.time.format.DateTimeFormatter;
2525
import java.util.ArrayList;
2626
import java.util.List;
2727

@@ -146,9 +146,6 @@
146146
*/
147147
public class MavenBaseLogger extends LegacyAbstractLogger {
148148

149-
private static final Clock MONOTONIC_CLOCK = Clock.tick(Clock.systemUTC(), Duration.ofMillis(1));
150-
private static final Instant START_TIME = MonotonicClock.now();
151-
152149
protected static final int LOG_LEVEL_TRACE = LocationAwareLogger.TRACE_INT;
153150
protected static final int LOG_LEVEL_DEBUG = LocationAwareLogger.DEBUG_INT;
154151
protected static final int LOG_LEVEL_INFO = LocationAwareLogger.INFO_INT;
@@ -165,7 +162,7 @@ public class MavenBaseLogger extends LegacyAbstractLogger {
165162

166163
static final SimpleLoggerConfiguration CONFIG_PARAMS = new SimpleLoggerConfiguration();
167164

168-
private static boolean initialized = false;
165+
static boolean initialized = false;
169166

170167
static void lazyInit() {
171168
if (initialized) {
@@ -266,15 +263,6 @@ protected void writeThrowable(Throwable t, PrintStream targetStream) {
266263
}
267264
}
268265

269-
protected String getFormattedDate() {
270-
Instant now = MonotonicClock.now();
271-
String dateText;
272-
synchronized (CONFIG_PARAMS.dateFormatter) {
273-
dateText = CONFIG_PARAMS.dateFormatter.format(now);
274-
}
275-
return dateText;
276-
}
277-
278266
protected String computeShortName() {
279267
return name.substring(name.lastIndexOf(".") + 1);
280268
}
@@ -380,11 +368,14 @@ private void innerHandleNormalizedLoggingCall(
380368

381369
// Append date-time if so configured
382370
if (CONFIG_PARAMS.showDateTime) {
383-
if (CONFIG_PARAMS.dateFormatter != null) {
384-
buf.append(getFormattedDate());
371+
DateTimeFormatter formatter = CONFIG_PARAMS.dateFormatter;
372+
if (formatter != null) {
373+
ZonedDateTime zonedDateTime = MonotonicClock.now().atZone(ZoneId.systemDefault());
374+
String dateText = formatter.format(zonedDateTime);
375+
buf.append(dateText);
385376
buf.append(SP);
386377
} else {
387-
buf.append(Duration.between(START_TIME, MonotonicClock.now()).toMillis());
378+
buf.append(MonotonicClock.elapsed().toMillis());
388379
buf.append(SP);
389380
}
390381
}

‎impl/maven-logging/src/main/java/org/apache/maven/slf4j/SimpleLoggerConfiguration.java‎

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -53,8 +53,6 @@ public class SimpleLoggerConfiguration {
5353
boolean showDateTime = SHOW_DATE_TIME_DEFAULT;
5454

5555
private static final String DATE_TIME_FORMAT_STR_DEFAULT = null;
56-
private static String dateTimeFormatStr = DATE_TIME_FORMAT_STR_DEFAULT;
57-
5856
DateTimeFormatter dateFormatter = null;
5957

6058
private static final boolean SHOW_THREAD_NAME_DEFAULT = true;
@@ -90,13 +88,19 @@ public class SimpleLoggerConfiguration {
9088
private final Properties properties = new Properties();
9189

9290
void init() {
91+
// Reset state before initialization
92+
dateFormatter = null;
93+
9394
loadProperties();
9495

9596
String defaultLogLevelString = getStringProperty(MavenBaseLogger.DEFAULT_LOG_LEVEL_KEY, null);
9697
if (defaultLogLevelString != null) {
9798
defaultLogLevel = stringToLevel(defaultLogLevelString);
9899
}
99100

101+
// local variable,
102+
String dateTimeFormatStr;
103+
100104
showLogName =
101105
getBooleanProperty(MavenBaseLogger.SHOW_LOG_NAME_KEY, SimpleLoggerConfiguration.SHOW_LOG_NAME_DEFAULT);
102106
showShortLogName = getBooleanProperty(MavenBaseLogger.SHOW_SHORT_LOG_NAME_KEY, SHOW_SHORT_LOG_NAME_DEFAULT);

0 commit comments

Comments
 (0)