From cb318cb24bd5db6e590f6e75dcd21efbbb351f0d Mon Sep 17 00:00:00 2001 From: Joshua Adams Date: Fri, 31 Oct 2025 16:17:44 +0000 Subject: [PATCH 1/8] Improve Snapshot Logging Clean up the reported logging start/end milliseconds into human-readable string dates Relates to: ES-12794 --- .../elasticsearch/common/date/DateUtils.java | 30 ++++++++++ .../blobstore/BlobStoreRepository.java | 8 ++- .../SnapshotShutdownProgressTracker.java | 7 ++- .../common/date/DateUtilsTests.java | 59 +++++++++++++++++++ 4 files changed, 100 insertions(+), 4 deletions(-) create mode 100644 server/src/main/java/org/elasticsearch/common/date/DateUtils.java create mode 100644 server/src/test/java/org/elasticsearch/common/date/DateUtilsTests.java diff --git a/server/src/main/java/org/elasticsearch/common/date/DateUtils.java b/server/src/main/java/org/elasticsearch/common/date/DateUtils.java new file mode 100644 index 0000000000000..f6317be46ed79 --- /dev/null +++ b/server/src/main/java/org/elasticsearch/common/date/DateUtils.java @@ -0,0 +1,30 @@ +/* + * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one + * or more contributor license agreements. Licensed under the "Elastic License + * 2.0", the "GNU Affero General Public License v3.0 only", and the "Server Side + * Public License v 1"; you may not use this file except in compliance with, at + * your election, the "Elastic License 2.0", the "GNU Affero General Public + * License v3.0 only", or the "Server Side Public License, v 1". + */ + +package org.elasticsearch.common.date; + +import java.time.Instant; +import java.time.ZoneId; +import java.time.format.DateTimeFormatter; + +/** + * Utils class containing methods that convert between different java date formats + */ +public class DateUtils { + + /** + * Converts milliseconds to a human-readable date time format + * @param millis The epoch in milliseconds + * @return A human-readable string containing the date time + */ + public static String convertMillisToDateTime(long millis) { + DateTimeFormatter formatter = DateTimeFormatter.ISO_LOCAL_DATE_TIME.withZone(ZoneId.of("UTC")); + return formatter.format(Instant.ofEpochMilli(millis)); + } +} diff --git a/server/src/main/java/org/elasticsearch/repositories/blobstore/BlobStoreRepository.java b/server/src/main/java/org/elasticsearch/repositories/blobstore/BlobStoreRepository.java index fdac63cc5466c..82b87746aa7b6 100644 --- a/server/src/main/java/org/elasticsearch/repositories/blobstore/BlobStoreRepository.java +++ b/server/src/main/java/org/elasticsearch/repositories/blobstore/BlobStoreRepository.java @@ -64,6 +64,7 @@ import org.elasticsearch.common.component.AbstractLifecycleComponent; import org.elasticsearch.common.compress.DeflateCompressor; import org.elasticsearch.common.compress.NotXContentException; +import org.elasticsearch.common.date.DateUtils; import org.elasticsearch.common.io.Streams; import org.elasticsearch.common.io.stream.BytesStreamOutput; import org.elasticsearch.common.io.stream.InputStreamStreamInput; @@ -4220,14 +4221,17 @@ private void checkAborted() { logger.trace("[{}] Writing [{}] to [{}]", metadata.name(), partName, shardContainer.path()); final long startMillis = threadPool.rawRelativeTimeInMillis(); shardContainer.writeBlob(OperationPurpose.SNAPSHOT_DATA, partName, inputStream, partBytes, false); - final long uploadTimeInMillis = threadPool.rawRelativeTimeInMillis() - startMillis; + final long endMillis = threadPool.rawRelativeTimeInMillis(); + final long uploadTimeInMillis = endMillis - startMillis; blobStoreSnapshotMetrics.incrementCountersForPartUpload(partBytes, uploadTimeInMillis); logger.trace( - "[{}] Writing [{}] of size [{}b] to [{}] took [{}ms]", + "[{}] Writing [{}] of size [{}b] to [{}]. Started at [{}], ended at [{}] and took [{}ms]", metadata.name(), partName, partBytes, shardContainer.path(), + DateUtils.convertMillisToDateTime(startMillis), + DateUtils.convertMillisToDateTime(endMillis), uploadTimeInMillis ); } diff --git a/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java b/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java index 45f2fb96fce4e..1119aa626ff77 100644 --- a/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java +++ b/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java @@ -13,6 +13,7 @@ import org.apache.logging.log4j.Logger; import org.elasticsearch.action.ResultDeduplicator; import org.elasticsearch.common.Strings; +import org.elasticsearch.common.date.DateUtils; import org.elasticsearch.common.settings.ClusterSettings; import org.elasticsearch.common.settings.Setting; import org.elasticsearch.common.util.concurrent.ConcurrentCollections; @@ -136,14 +137,16 @@ private void logProgressReport() { logger.info( """ Current active shard snapshot stats on data node [{}]. \ - Node shutdown cluster state update received at [{} millis]. \ - Finished signalling shard snapshots to pause at [{} millis]. \ + Node shutdown cluster state update received at [{}] [{} millis]. \ + Finished signalling shard snapshots to pause at [{}] [{} millis]. \ Number shard snapshots running [{}]. \ Number shard snapshots waiting for master node reply to status update request [{}] \ Shard snapshot completion stats since shutdown began: Done [{}]; Failed [{}]; Aborted [{}]; Paused [{}]\ """, getLocalNodeId.get(), + DateUtils.convertMillisToDateTime(shutdownStartMillis), shutdownStartMillis, + DateUtils.convertMillisToDateTime(shutdownFinishedSignallingPausingMillis), shutdownFinishedSignallingPausingMillis, numberOfShardSnapshotsInProgressOnDataNode.get(), shardSnapshotRequests.size(), diff --git a/server/src/test/java/org/elasticsearch/common/date/DateUtilsTests.java b/server/src/test/java/org/elasticsearch/common/date/DateUtilsTests.java new file mode 100644 index 0000000000000..86546e00d4aa3 --- /dev/null +++ b/server/src/test/java/org/elasticsearch/common/date/DateUtilsTests.java @@ -0,0 +1,59 @@ +/* + * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one + * or more contributor license agreements. Licensed under the "Elastic License + * 2.0", the "GNU Affero General Public License v3.0 only", and the "Server Side + * Public License v 1"; you may not use this file except in compliance with, at + * your election, the "Elastic License 2.0", the "GNU Affero General Public + * License v3.0 only", or the "Server Side Public License, v 1". + */ + +package org.elasticsearch.common.date; + +import org.elasticsearch.test.ESTestCase; + +import java.time.Instant; +import java.time.ZoneId; +import java.time.format.DateTimeFormatter; + +public class DateUtilsTests extends ESTestCase { + + public void testConvertMillisToDateTime() { + long millis = randomLong(); + String expected = DateTimeFormatter.ISO_LOCAL_DATE_TIME + .withZone(ZoneId.of("UTC")) + .format(Instant.ofEpochMilli(millis)); + String actual = DateUtils.convertMillisToDateTime(millis); + assertEquals(expected, actual); + } + + public void testConvertMillisToDateTimeWithEpochZero() { + long millis = 0L; + String expected = "1970-01-01T00:00:00"; + String actual = DateUtils.convertMillisToDateTime(millis); + assertEquals(expected, actual); + } + + public void testConvertMillisToDateTimeWithEpochNegativeOne() { + long millis = -1L; // Just before epoch + String expected = "1969-12-31T23:59:59.999"; + String actual = DateUtils.convertMillisToDateTime(millis); + assertEquals(expected, actual); + } + + public void testConvertMillisToDateTimeWithCurrentTime() { + long millis = System.currentTimeMillis(); + String expected = DateTimeFormatter.ISO_LOCAL_DATE_TIME + .withZone(ZoneId.of("UTC")) + .format(Instant.ofEpochMilli(millis)); + String actual = DateUtils.convertMillisToDateTime(millis); + assertEquals(expected, actual); + } + + public void testConvertMillisToDateTimeConsistency() { + // The method should be consistent for the same input + long millis = randomLong(); + String first = DateUtils.convertMillisToDateTime(millis); + String second = DateUtils.convertMillisToDateTime(millis); + assertEquals(first, second); + } +} From 229e3ab194c06cde64a08a3183a2aa8e404ba8e9 Mon Sep 17 00:00:00 2001 From: elasticsearchmachine Date: Fri, 31 Oct 2025 16:26:13 +0000 Subject: [PATCH 2/8] [CI] Auto commit changes from spotless --- .../org/elasticsearch/common/date/DateUtilsTests.java | 8 ++------ 1 file changed, 2 insertions(+), 6 deletions(-) diff --git a/server/src/test/java/org/elasticsearch/common/date/DateUtilsTests.java b/server/src/test/java/org/elasticsearch/common/date/DateUtilsTests.java index 86546e00d4aa3..0e8ca0f33afda 100644 --- a/server/src/test/java/org/elasticsearch/common/date/DateUtilsTests.java +++ b/server/src/test/java/org/elasticsearch/common/date/DateUtilsTests.java @@ -19,9 +19,7 @@ public class DateUtilsTests extends ESTestCase { public void testConvertMillisToDateTime() { long millis = randomLong(); - String expected = DateTimeFormatter.ISO_LOCAL_DATE_TIME - .withZone(ZoneId.of("UTC")) - .format(Instant.ofEpochMilli(millis)); + String expected = DateTimeFormatter.ISO_LOCAL_DATE_TIME.withZone(ZoneId.of("UTC")).format(Instant.ofEpochMilli(millis)); String actual = DateUtils.convertMillisToDateTime(millis); assertEquals(expected, actual); } @@ -42,9 +40,7 @@ public void testConvertMillisToDateTimeWithEpochNegativeOne() { public void testConvertMillisToDateTimeWithCurrentTime() { long millis = System.currentTimeMillis(); - String expected = DateTimeFormatter.ISO_LOCAL_DATE_TIME - .withZone(ZoneId.of("UTC")) - .format(Instant.ofEpochMilli(millis)); + String expected = DateTimeFormatter.ISO_LOCAL_DATE_TIME.withZone(ZoneId.of("UTC")).format(Instant.ofEpochMilli(millis)); String actual = DateUtils.convertMillisToDateTime(millis); assertEquals(expected, actual); } From 741ed12c9139cb304cd811f7cae70a85be91802c Mon Sep 17 00:00:00 2001 From: Joshua Adams Date: Mon, 3 Nov 2025 10:55:40 +0000 Subject: [PATCH 3/8] Update unit tests --- .../org/elasticsearch/common/date/DateUtilsTests.java | 8 ++------ .../snapshots/SnapshotShutdownProgressTrackerTests.java | 8 +++++++- 2 files changed, 9 insertions(+), 7 deletions(-) diff --git a/server/src/test/java/org/elasticsearch/common/date/DateUtilsTests.java b/server/src/test/java/org/elasticsearch/common/date/DateUtilsTests.java index 86546e00d4aa3..0e8ca0f33afda 100644 --- a/server/src/test/java/org/elasticsearch/common/date/DateUtilsTests.java +++ b/server/src/test/java/org/elasticsearch/common/date/DateUtilsTests.java @@ -19,9 +19,7 @@ public class DateUtilsTests extends ESTestCase { public void testConvertMillisToDateTime() { long millis = randomLong(); - String expected = DateTimeFormatter.ISO_LOCAL_DATE_TIME - .withZone(ZoneId.of("UTC")) - .format(Instant.ofEpochMilli(millis)); + String expected = DateTimeFormatter.ISO_LOCAL_DATE_TIME.withZone(ZoneId.of("UTC")).format(Instant.ofEpochMilli(millis)); String actual = DateUtils.convertMillisToDateTime(millis); assertEquals(expected, actual); } @@ -42,9 +40,7 @@ public void testConvertMillisToDateTimeWithEpochNegativeOne() { public void testConvertMillisToDateTimeWithCurrentTime() { long millis = System.currentTimeMillis(); - String expected = DateTimeFormatter.ISO_LOCAL_DATE_TIME - .withZone(ZoneId.of("UTC")) - .format(Instant.ofEpochMilli(millis)); + String expected = DateTimeFormatter.ISO_LOCAL_DATE_TIME.withZone(ZoneId.of("UTC")).format(Instant.ofEpochMilli(millis)); String actual = DateUtils.convertMillisToDateTime(millis); assertEquals(expected, actual); } diff --git a/server/src/test/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTrackerTests.java b/server/src/test/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTrackerTests.java index 8adcb3eb9d5f4..96de3189072e9 100644 --- a/server/src/test/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTrackerTests.java +++ b/server/src/test/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTrackerTests.java @@ -13,6 +13,7 @@ import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; import org.elasticsearch.cluster.coordination.Coordinator; +import org.elasticsearch.common.date.DateUtils; import org.elasticsearch.common.settings.ClusterSettings; import org.elasticsearch.common.settings.Setting; import org.elasticsearch.common.settings.Settings; @@ -271,12 +272,17 @@ public void testTrackerPauseTimestamp() { ); try (var mockLog = MockLog.capture(Coordinator.class, SnapshotShutdownProgressTracker.class)) { + long timeInMillis = testThreadPool.relativeTimeInMillis(); mockLog.addExpectation( new MockLog.SeenEventExpectation( "pausing timestamp should be set", SnapshotShutdownProgressTracker.class.getName(), Level.INFO, - "*Finished signalling shard snapshots to pause at [" + testThreadPool.relativeTimeInMillis() + " millis]*" + "*Finished signalling shard snapshots to pause at [" + + DateUtils.convertMillisToDateTime(timeInMillis) + + "] [" + + timeInMillis + + " millis]*" ) ); From 2cc1aa5b02dee48adbce20de8be9b9210ae20674 Mon Sep 17 00:00:00 2001 From: Joshua Adams Date: Fri, 7 Nov 2025 12:26:54 +0000 Subject: [PATCH 4/8] Remove DateUtils and use TimeValue --- .../elasticsearch/common/date/DateUtils.java | 30 ---------- .../blobstore/BlobStoreRepository.java | 11 ++-- .../SnapshotShutdownProgressTracker.java | 5 +- .../common/date/DateUtilsTests.java | 55 ------------------- .../SnapshotShutdownProgressTrackerTests.java | 7 +-- 5 files changed, 7 insertions(+), 101 deletions(-) delete mode 100644 server/src/main/java/org/elasticsearch/common/date/DateUtils.java delete mode 100644 server/src/test/java/org/elasticsearch/common/date/DateUtilsTests.java diff --git a/server/src/main/java/org/elasticsearch/common/date/DateUtils.java b/server/src/main/java/org/elasticsearch/common/date/DateUtils.java deleted file mode 100644 index f6317be46ed79..0000000000000 --- a/server/src/main/java/org/elasticsearch/common/date/DateUtils.java +++ /dev/null @@ -1,30 +0,0 @@ -/* - * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one - * or more contributor license agreements. Licensed under the "Elastic License - * 2.0", the "GNU Affero General Public License v3.0 only", and the "Server Side - * Public License v 1"; you may not use this file except in compliance with, at - * your election, the "Elastic License 2.0", the "GNU Affero General Public - * License v3.0 only", or the "Server Side Public License, v 1". - */ - -package org.elasticsearch.common.date; - -import java.time.Instant; -import java.time.ZoneId; -import java.time.format.DateTimeFormatter; - -/** - * Utils class containing methods that convert between different java date formats - */ -public class DateUtils { - - /** - * Converts milliseconds to a human-readable date time format - * @param millis The epoch in milliseconds - * @return A human-readable string containing the date time - */ - public static String convertMillisToDateTime(long millis) { - DateTimeFormatter formatter = DateTimeFormatter.ISO_LOCAL_DATE_TIME.withZone(ZoneId.of("UTC")); - return formatter.format(Instant.ofEpochMilli(millis)); - } -} diff --git a/server/src/main/java/org/elasticsearch/repositories/blobstore/BlobStoreRepository.java b/server/src/main/java/org/elasticsearch/repositories/blobstore/BlobStoreRepository.java index 82b87746aa7b6..69055cbd8dceb 100644 --- a/server/src/main/java/org/elasticsearch/repositories/blobstore/BlobStoreRepository.java +++ b/server/src/main/java/org/elasticsearch/repositories/blobstore/BlobStoreRepository.java @@ -64,7 +64,6 @@ import org.elasticsearch.common.component.AbstractLifecycleComponent; import org.elasticsearch.common.compress.DeflateCompressor; import org.elasticsearch.common.compress.NotXContentException; -import org.elasticsearch.common.date.DateUtils; import org.elasticsearch.common.io.Streams; import org.elasticsearch.common.io.stream.BytesStreamOutput; import org.elasticsearch.common.io.stream.InputStreamStreamInput; @@ -95,6 +94,7 @@ import org.elasticsearch.core.RefCounted; import org.elasticsearch.core.Releasable; import org.elasticsearch.core.SuppressForbidden; +import org.elasticsearch.core.TimeValue; import org.elasticsearch.core.Tuple; import org.elasticsearch.index.IndexVersion; import org.elasticsearch.index.shard.ShardId; @@ -4221,18 +4221,15 @@ private void checkAborted() { logger.trace("[{}] Writing [{}] to [{}]", metadata.name(), partName, shardContainer.path()); final long startMillis = threadPool.rawRelativeTimeInMillis(); shardContainer.writeBlob(OperationPurpose.SNAPSHOT_DATA, partName, inputStream, partBytes, false); - final long endMillis = threadPool.rawRelativeTimeInMillis(); - final long uploadTimeInMillis = endMillis - startMillis; + final long uploadTimeInMillis = threadPool.rawRelativeTimeInMillis() - startMillis; blobStoreSnapshotMetrics.incrementCountersForPartUpload(partBytes, uploadTimeInMillis); logger.trace( - "[{}] Writing [{}] of size [{}b] to [{}]. Started at [{}], ended at [{}] and took [{}ms]", + "[{}] Writing [{}] of size [{}b] to [{}] took [{}ms]", metadata.name(), partName, partBytes, shardContainer.path(), - DateUtils.convertMillisToDateTime(startMillis), - DateUtils.convertMillisToDateTime(endMillis), - uploadTimeInMillis + new TimeValue(uploadTimeInMillis) ); } blobStoreSnapshotMetrics.incrementNumberOfBlobsUploaded(); diff --git a/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java b/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java index 1119aa626ff77..27069077493f1 100644 --- a/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java +++ b/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java @@ -13,7 +13,6 @@ import org.apache.logging.log4j.Logger; import org.elasticsearch.action.ResultDeduplicator; import org.elasticsearch.common.Strings; -import org.elasticsearch.common.date.DateUtils; import org.elasticsearch.common.settings.ClusterSettings; import org.elasticsearch.common.settings.Setting; import org.elasticsearch.common.util.concurrent.ConcurrentCollections; @@ -144,9 +143,9 @@ private void logProgressReport() { Shard snapshot completion stats since shutdown began: Done [{}]; Failed [{}]; Aborted [{}]; Paused [{}]\ """, getLocalNodeId.get(), - DateUtils.convertMillisToDateTime(shutdownStartMillis), + new TimeValue(shutdownStartMillis), shutdownStartMillis, - DateUtils.convertMillisToDateTime(shutdownFinishedSignallingPausingMillis), + new TimeValue(shutdownFinishedSignallingPausingMillis), shutdownFinishedSignallingPausingMillis, numberOfShardSnapshotsInProgressOnDataNode.get(), shardSnapshotRequests.size(), diff --git a/server/src/test/java/org/elasticsearch/common/date/DateUtilsTests.java b/server/src/test/java/org/elasticsearch/common/date/DateUtilsTests.java deleted file mode 100644 index 0e8ca0f33afda..0000000000000 --- a/server/src/test/java/org/elasticsearch/common/date/DateUtilsTests.java +++ /dev/null @@ -1,55 +0,0 @@ -/* - * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one - * or more contributor license agreements. Licensed under the "Elastic License - * 2.0", the "GNU Affero General Public License v3.0 only", and the "Server Side - * Public License v 1"; you may not use this file except in compliance with, at - * your election, the "Elastic License 2.0", the "GNU Affero General Public - * License v3.0 only", or the "Server Side Public License, v 1". - */ - -package org.elasticsearch.common.date; - -import org.elasticsearch.test.ESTestCase; - -import java.time.Instant; -import java.time.ZoneId; -import java.time.format.DateTimeFormatter; - -public class DateUtilsTests extends ESTestCase { - - public void testConvertMillisToDateTime() { - long millis = randomLong(); - String expected = DateTimeFormatter.ISO_LOCAL_DATE_TIME.withZone(ZoneId.of("UTC")).format(Instant.ofEpochMilli(millis)); - String actual = DateUtils.convertMillisToDateTime(millis); - assertEquals(expected, actual); - } - - public void testConvertMillisToDateTimeWithEpochZero() { - long millis = 0L; - String expected = "1970-01-01T00:00:00"; - String actual = DateUtils.convertMillisToDateTime(millis); - assertEquals(expected, actual); - } - - public void testConvertMillisToDateTimeWithEpochNegativeOne() { - long millis = -1L; // Just before epoch - String expected = "1969-12-31T23:59:59.999"; - String actual = DateUtils.convertMillisToDateTime(millis); - assertEquals(expected, actual); - } - - public void testConvertMillisToDateTimeWithCurrentTime() { - long millis = System.currentTimeMillis(); - String expected = DateTimeFormatter.ISO_LOCAL_DATE_TIME.withZone(ZoneId.of("UTC")).format(Instant.ofEpochMilli(millis)); - String actual = DateUtils.convertMillisToDateTime(millis); - assertEquals(expected, actual); - } - - public void testConvertMillisToDateTimeConsistency() { - // The method should be consistent for the same input - long millis = randomLong(); - String first = DateUtils.convertMillisToDateTime(millis); - String second = DateUtils.convertMillisToDateTime(millis); - assertEquals(first, second); - } -} diff --git a/server/src/test/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTrackerTests.java b/server/src/test/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTrackerTests.java index 96de3189072e9..1585f66dced2d 100644 --- a/server/src/test/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTrackerTests.java +++ b/server/src/test/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTrackerTests.java @@ -13,7 +13,6 @@ import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; import org.elasticsearch.cluster.coordination.Coordinator; -import org.elasticsearch.common.date.DateUtils; import org.elasticsearch.common.settings.ClusterSettings; import org.elasticsearch.common.settings.Setting; import org.elasticsearch.common.settings.Settings; @@ -278,11 +277,7 @@ public void testTrackerPauseTimestamp() { "pausing timestamp should be set", SnapshotShutdownProgressTracker.class.getName(), Level.INFO, - "*Finished signalling shard snapshots to pause at [" - + DateUtils.convertMillisToDateTime(timeInMillis) - + "] [" - + timeInMillis - + " millis]*" + "*Finished signalling shard snapshots to pause at [" + new TimeValue(timeInMillis) + "] [" + timeInMillis + " millis]*" ) ); From ced5d1e42e4d1bc73c379cd658e90446fe7864e7 Mon Sep 17 00:00:00 2001 From: Joshua Adams Date: Fri, 7 Nov 2025 13:24:35 +0000 Subject: [PATCH 5/8] Use custom DATE_TIME_FORMATTER --- .../blobstore/BlobStoreRepository.java | 5 +++-- .../SnapshotShutdownProgressTracker.java | 17 +++++++++++------ 2 files changed, 14 insertions(+), 8 deletions(-) diff --git a/server/src/main/java/org/elasticsearch/repositories/blobstore/BlobStoreRepository.java b/server/src/main/java/org/elasticsearch/repositories/blobstore/BlobStoreRepository.java index 69055cbd8dceb..d5ffa95bf87b8 100644 --- a/server/src/main/java/org/elasticsearch/repositories/blobstore/BlobStoreRepository.java +++ b/server/src/main/java/org/elasticsearch/repositories/blobstore/BlobStoreRepository.java @@ -4224,12 +4224,13 @@ private void checkAborted() { final long uploadTimeInMillis = threadPool.rawRelativeTimeInMillis() - startMillis; blobStoreSnapshotMetrics.incrementCountersForPartUpload(partBytes, uploadTimeInMillis); logger.trace( - "[{}] Writing [{}] of size [{}b] to [{}] took [{}ms]", + "[{}] Writing [{}] of size [{}b] to [{}] took [{}/{}ms]", metadata.name(), partName, partBytes, shardContainer.path(), - new TimeValue(uploadTimeInMillis) + new TimeValue(uploadTimeInMillis), + uploadTimeInMillis ); } blobStoreSnapshotMetrics.incrementNumberOfBlobsUploaded(); diff --git a/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java b/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java index 27069077493f1..cc0a33d866948 100644 --- a/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java +++ b/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java @@ -15,6 +15,9 @@ import org.elasticsearch.common.Strings; import org.elasticsearch.common.settings.ClusterSettings; import org.elasticsearch.common.settings.Setting; +import org.elasticsearch.common.time.DateFormatter; +import org.elasticsearch.common.time.DateFormatters; +import org.elasticsearch.common.time.DateUtils; import org.elasticsearch.common.util.concurrent.ConcurrentCollections; import org.elasticsearch.core.TimeValue; import org.elasticsearch.index.shard.ShardId; @@ -22,6 +25,7 @@ import org.elasticsearch.threadpool.Scheduler; import org.elasticsearch.threadpool.ThreadPool; +import java.time.ZoneOffset; import java.util.Map; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicLong; @@ -44,6 +48,7 @@ public class SnapshotShutdownProgressTracker { ); private static final Logger logger = LogManager.getLogger(SnapshotShutdownProgressTracker.class); + private static final DateFormatter DATE_TIME_FORMATTER = DateFormatter.forPattern("strict_date_optional_time"); private final Supplier getLocalNodeId; private final Consumer logIndexShardSnapshotStatuses; @@ -136,17 +141,17 @@ private void logProgressReport() { logger.info( """ Current active shard snapshot stats on data node [{}]. \ - Node shutdown cluster state update received at [{}] [{} millis]. \ - Finished signalling shard snapshots to pause at [{}] [{} millis]. \ + Node shutdown cluster state update received at [{}]. \ + Finished signalling shard snapshots to pause at [{}]. \ + Time between the node shutdown cluster state update and signalling shard snapshots to pause is [{} millis]\ Number shard snapshots running [{}]. \ Number shard snapshots waiting for master node reply to status update request [{}] \ Shard snapshot completion stats since shutdown began: Done [{}]; Failed [{}]; Aborted [{}]; Paused [{}]\ """, getLocalNodeId.get(), - new TimeValue(shutdownStartMillis), - shutdownStartMillis, - new TimeValue(shutdownFinishedSignallingPausingMillis), - shutdownFinishedSignallingPausingMillis, + DATE_TIME_FORMATTER.formatMillis(shutdownStartMillis), + DATE_TIME_FORMATTER.formatMillis(shutdownFinishedSignallingPausingMillis), + shutdownFinishedSignallingPausingMillis - shutdownStartMillis, numberOfShardSnapshotsInProgressOnDataNode.get(), shardSnapshotRequests.size(), doneCount.get(), From 9e4ba817d35b89f9ec0fc58fa21afa727bbb196c Mon Sep 17 00:00:00 2001 From: elasticsearchmachine Date: Fri, 7 Nov 2025 13:32:01 +0000 Subject: [PATCH 6/8] [CI] Auto commit changes from spotless --- .../snapshots/SnapshotShutdownProgressTracker.java | 3 --- 1 file changed, 3 deletions(-) diff --git a/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java b/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java index cc0a33d866948..c829a4b25114a 100644 --- a/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java +++ b/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java @@ -16,8 +16,6 @@ import org.elasticsearch.common.settings.ClusterSettings; import org.elasticsearch.common.settings.Setting; import org.elasticsearch.common.time.DateFormatter; -import org.elasticsearch.common.time.DateFormatters; -import org.elasticsearch.common.time.DateUtils; import org.elasticsearch.common.util.concurrent.ConcurrentCollections; import org.elasticsearch.core.TimeValue; import org.elasticsearch.index.shard.ShardId; @@ -25,7 +23,6 @@ import org.elasticsearch.threadpool.Scheduler; import org.elasticsearch.threadpool.ThreadPool; -import java.time.ZoneOffset; import java.util.Map; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicLong; From 961e9e934c1a0c4e4505de766e98a500ee9861cb Mon Sep 17 00:00:00 2001 From: Joshua Adams Date: Fri, 7 Nov 2025 13:33:15 +0000 Subject: [PATCH 7/8] Spotless apply --- .../snapshots/SnapshotShutdownProgressTracker.java | 3 --- .../snapshots/SnapshotShutdownProgressTrackerTests.java | 5 ++++- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java b/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java index cc0a33d866948..c829a4b25114a 100644 --- a/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java +++ b/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java @@ -16,8 +16,6 @@ import org.elasticsearch.common.settings.ClusterSettings; import org.elasticsearch.common.settings.Setting; import org.elasticsearch.common.time.DateFormatter; -import org.elasticsearch.common.time.DateFormatters; -import org.elasticsearch.common.time.DateUtils; import org.elasticsearch.common.util.concurrent.ConcurrentCollections; import org.elasticsearch.core.TimeValue; import org.elasticsearch.index.shard.ShardId; @@ -25,7 +23,6 @@ import org.elasticsearch.threadpool.Scheduler; import org.elasticsearch.threadpool.ThreadPool; -import java.time.ZoneOffset; import java.util.Map; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicLong; diff --git a/server/src/test/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTrackerTests.java b/server/src/test/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTrackerTests.java index 1585f66dced2d..042db6b004c6a 100644 --- a/server/src/test/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTrackerTests.java +++ b/server/src/test/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTrackerTests.java @@ -16,6 +16,7 @@ import org.elasticsearch.common.settings.ClusterSettings; import org.elasticsearch.common.settings.Setting; import org.elasticsearch.common.settings.Settings; +import org.elasticsearch.common.time.DateFormatter; import org.elasticsearch.common.unit.ByteSizeValue; import org.elasticsearch.common.util.concurrent.DeterministicTaskQueue; import org.elasticsearch.core.TimeValue; @@ -277,7 +278,9 @@ public void testTrackerPauseTimestamp() { "pausing timestamp should be set", SnapshotShutdownProgressTracker.class.getName(), Level.INFO, - "*Finished signalling shard snapshots to pause at [" + new TimeValue(timeInMillis) + "] [" + timeInMillis + " millis]*" + "*Finished signalling shard snapshots to pause at [" + + DateFormatter.forPattern("strict_date_optional_time").formatMillis(timeInMillis) + + "]*" ) ); From 1e9a0ab13535180f97500d8a82ebf810160a2a56 Mon Sep 17 00:00:00 2001 From: Joshua Adams Date: Tue, 11 Nov 2025 14:01:41 +0000 Subject: [PATCH 8/8] Add UTC to log message --- .../snapshots/SnapshotShutdownProgressTracker.java | 6 +++--- .../snapshots/SnapshotShutdownProgressTrackerTests.java | 2 +- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java b/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java index c829a4b25114a..53eb8f5fcd91b 100644 --- a/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java +++ b/server/src/main/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTracker.java @@ -138,9 +138,9 @@ private void logProgressReport() { logger.info( """ Current active shard snapshot stats on data node [{}]. \ - Node shutdown cluster state update received at [{}]. \ - Finished signalling shard snapshots to pause at [{}]. \ - Time between the node shutdown cluster state update and signalling shard snapshots to pause is [{} millis]\ + Node shutdown cluster state update received at [{} UTC]. \ + Finished signalling shard snapshots to pause at [{} UTC]. \ + Time between the node shutdown cluster state update and signalling shard snapshots to pause is [{} millis]. \ Number shard snapshots running [{}]. \ Number shard snapshots waiting for master node reply to status update request [{}] \ Shard snapshot completion stats since shutdown began: Done [{}]; Failed [{}]; Aborted [{}]; Paused [{}]\ diff --git a/server/src/test/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTrackerTests.java b/server/src/test/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTrackerTests.java index 042db6b004c6a..fbaf3105d1824 100644 --- a/server/src/test/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTrackerTests.java +++ b/server/src/test/java/org/elasticsearch/snapshots/SnapshotShutdownProgressTrackerTests.java @@ -280,7 +280,7 @@ public void testTrackerPauseTimestamp() { Level.INFO, "*Finished signalling shard snapshots to pause at [" + DateFormatter.forPattern("strict_date_optional_time").formatMillis(timeInMillis) - + "]*" + + " UTC]*" ) );