Merge pull request #2660 from janeklb/jlb/log-formatted-duration

chernser · web-flow · commit 5e843af0abcd · 2025-11-21T14:28:20.000-08:00
[client-v2] log duration in ISO-8601
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -1,4 +1,9 @@
-### 0.9.4 
+## 0.9.5
+
+### New Features
+- [client-v2] Log durations in ISO-8601 duration format
+
+## 0.9.4 
 
 ### New Features 
 - [client-v2] Added support for different compression algorithms when HTTP compression is enabled. (https://github.com/ClickHouse/clickhouse-java/pull/2645)
diff --git a/client-v2/src/main/java/com/clickhouse/client/api/Client.java b/client-v2/src/main/java/com/clickhouse/client/api/Client.java
@@ -1132,7 +1132,7 @@ public boolean ping(long timeout) {
                 return true;
             }
         } catch (Exception e) {
-            LOG.debug("Failed to connect to the server (Duration: {})", System.nanoTime() - startTime, e);
+            LOG.debug("Failed to connect to the server (Duration: {})", durationSince(startTime), e);
             return false;
         }
     }
@@ -1277,7 +1277,7 @@ public CompletableFuture<InsertResponse> insert(String tableName, List<?> data,
 
                     // Check response
                     if (httpResponse.getCode() == HttpStatus.SC_SERVICE_UNAVAILABLE) {
-                        LOG.warn("Failed to get response. Server returned {}. Retrying. (Duration: {})", httpResponse.getCode(), System.nanoTime() - startTime);
+                        LOG.warn("Failed to get response. Server returned {}. Retrying. (Duration: {})", httpResponse.getCode(), durationSince(startTime));
                         selectedEndpoint = getNextAliveNode();
                         continue;
                     }
@@ -1292,7 +1292,7 @@ public CompletableFuture<InsertResponse> insert(String tableName, List<?> data,
                     return new InsertResponse(metrics);
                 } catch (Exception e) {
                     lastException = httpClientHelper.wrapException(String.format("Query request failed (Attempt: %s/%s - Duration: %s)",
-                            (i + 1), (maxRetries + 1), System.nanoTime() - startTime), e);
+                            (i + 1), (maxRetries + 1), durationSince(startTime)), e);
                     if (httpClientHelper.shouldRetry(e, requestSettings.getAllSettings())) {
                         LOG.warn("Retrying.", e);
                         selectedEndpoint = getNextAliveNode();
@@ -1301,7 +1301,7 @@ public CompletableFuture<InsertResponse> insert(String tableName, List<?> data,
                     }
                 }
             }
-            throw new ClientException("Insert request failed after attempts: " + (maxRetries + 1) + " - Duration: " + (System.nanoTime() - startTime), lastException);
+            throw new ClientException("Insert request failed after attempts: " + (maxRetries + 1) + " - Duration: " + durationSince(startTime), lastException);
         };
 
         return runAsyncOperation(supplier, requestSettings.getAllSettings());
@@ -1480,7 +1480,7 @@ public CompletableFuture<InsertResponse> insert(String tableName,
 
                     // Check response
                     if (httpResponse.getCode() == HttpStatus.SC_SERVICE_UNAVAILABLE) {
-                        LOG.warn("Failed to get response. Server returned {}. Retrying. (Duration: {})", System.nanoTime() - startTime, httpResponse.getCode());
+                        LOG.warn("Failed to get response. Server returned {}. Retrying. (Duration: {})", httpResponse.getCode(), durationSince(startTime));
                         selectedEndpoint = getNextAliveNode();
                         continue;
                     }
@@ -1494,7 +1494,7 @@ public CompletableFuture<InsertResponse> insert(String tableName,
                     return new InsertResponse(metrics);
                 } catch (Exception e) {
                     lastException = httpClientHelper.wrapException(String.format("Insert failed (Attempt: %s/%s - Duration: %s)",
-                            (i + 1), (retries + 1), System.nanoTime() - startTime), e);
+                            (i + 1), (retries + 1), durationSince(startTime)), e);
                     if (httpClientHelper.shouldRetry(e, requestSettings.getAllSettings())) {
                         LOG.warn("Retrying.", e);
                         selectedEndpoint = getNextAliveNode();
@@ -1511,7 +1511,7 @@ public CompletableFuture<InsertResponse> insert(String tableName,
                     }
                 }
             }
-            LOG.warn("Insert request failed after attempts: " + (retries + 1) + " - Duration: " + (System.nanoTime() - startTime));
+            LOG.warn("Insert request failed after attempts: {} - Duration: {}", retries + 1, durationSince(startTime));
             throw (lastException == null ? new ClientException("Failed to complete insert operation") : lastException);
         };
 
@@ -1603,7 +1603,7 @@ public CompletableFuture<QueryResponse> query(String sqlQuery, Map<String, Objec
 
                         // Check response
                         if (httpResponse.getCode() == HttpStatus.SC_SERVICE_UNAVAILABLE) {
-                            LOG.warn("Failed to get response. Server returned {}. Retrying. (Duration: {})", System.nanoTime() - startTime, httpResponse.getCode());
+                            LOG.warn("Failed to get response. Server returned {}. Retrying. (Duration: {})", httpResponse.getCode(), durationSince(startTime));
                             selectedEndpoint = getNextAliveNode();
                             HttpAPIClientHelper.closeQuietly(httpResponse);
                             continue;
@@ -1628,7 +1628,7 @@ public CompletableFuture<QueryResponse> query(String sqlQuery, Map<String, Objec
                     } catch (Exception e) {
                         HttpAPIClientHelper.closeQuietly(httpResponse);
                         lastException = httpClientHelper.wrapException(String.format("Query request failed (Attempt: %s/%s - Duration: %s)",
-                                (i + 1), (retries + 1), System.nanoTime() - startTime), e);
+                                (i + 1), (retries + 1), durationSince(startTime)), e);
                         if (httpClientHelper.shouldRetry(e, requestSettings.getAllSettings())) {
                             LOG.warn("Retrying.", e);
                             selectedEndpoint = getNextAliveNode();
@@ -1637,7 +1637,7 @@ public CompletableFuture<QueryResponse> query(String sqlQuery, Map<String, Objec
                         }
                     }
                 }
-                LOG.warn("Query request failed after attempts: " + (retries + 1) + " - Duration: " + (System.nanoTime() - startTime));
+                LOG.warn("Query request failed after attempts: {} - Duration: {}", retries + 1, durationSince(startTime));
                 throw (lastException == null ? new ClientException("Failed to complete query") : lastException);
             };
 
@@ -2115,4 +2115,7 @@ private Map<String, Object> buildRequestSettings(Map<String, Object> opSettings)
         return requestSettings;
     }
 
+    private Duration durationSince(long sinceNanos) {
+        return Duration.ofNanos(System.nanoTime() - sinceNanos);
+    }
 }

Original file line number	Diff line number	Diff line change
`@@ -1132,7 +1132,7 @@ public boolean ping(long timeout) {`
`1132`	`1132`	`return true;`
`1133`	`1133`	`}`
`1134`	`1134`	`} catch (Exception e) {`
`1135`		`- LOG.debug("Failed to connect to the server (Duration: {})", System.nanoTime() - startTime, e);`
	`1135`	`+ LOG.debug("Failed to connect to the server (Duration: {})", durationSince(startTime), e);`
`1136`	`1136`	`return false;`
`1137`	`1137`	`}`
`1138`	`1138`	`}`
`@@ -1277,7 +1277,7 @@ public CompletableFuture<InsertResponse> insert(String tableName, List<?> data,`
`1277`	`1277`
`1278`	`1278`	`// Check response`
`1279`	`1279`	`if (httpResponse.getCode() == HttpStatus.SC_SERVICE_UNAVAILABLE) {`
`1280`		`- LOG.warn("Failed to get response. Server returned {}. Retrying. (Duration: {})", httpResponse.getCode(), System.nanoTime() - startTime);`
	`1280`	`+ LOG.warn("Failed to get response. Server returned {}. Retrying. (Duration: {})", httpResponse.getCode(), durationSince(startTime));`
`1281`	`1281`	`selectedEndpoint = getNextAliveNode();`
`1282`	`1282`	`continue;`
`1283`	`1283`	`}`
`@@ -1292,7 +1292,7 @@ public CompletableFuture<InsertResponse> insert(String tableName, List<?> data,`
`1292`	`1292`	`return new InsertResponse(metrics);`
`1293`	`1293`	`} catch (Exception e) {`
`1294`	`1294`	`lastException = httpClientHelper.wrapException(String.format("Query request failed (Attempt: %s/%s - Duration: %s)",`
`1295`		`- (i + 1), (maxRetries + 1), System.nanoTime() - startTime), e);`
	`1295`	`+ (i + 1), (maxRetries + 1), durationSince(startTime)), e);`
`1296`	`1296`	`if (httpClientHelper.shouldRetry(e, requestSettings.getAllSettings())) {`
`1297`	`1297`	`LOG.warn("Retrying.", e);`
`1298`	`1298`	`selectedEndpoint = getNextAliveNode();`
`@@ -1301,7 +1301,7 @@ public CompletableFuture<InsertResponse> insert(String tableName, List<?> data,`
`1301`	`1301`	`}`
`1302`	`1302`	`}`
`1303`	`1303`	`}`
`1304`		`- throw new ClientException("Insert request failed after attempts: " + (maxRetries + 1) + " - Duration: " + (System.nanoTime() - startTime), lastException);`
	`1304`	`+ throw new ClientException("Insert request failed after attempts: " + (maxRetries + 1) + " - Duration: " + durationSince(startTime), lastException);`
`1305`	`1305`	`};`
`1306`	`1306`
`1307`	`1307`	`return runAsyncOperation(supplier, requestSettings.getAllSettings());`
`@@ -1480,7 +1480,7 @@ public CompletableFuture<InsertResponse> insert(String tableName,`
`1480`	`1480`
`1481`	`1481`	`// Check response`
`1482`	`1482`	`if (httpResponse.getCode() == HttpStatus.SC_SERVICE_UNAVAILABLE) {`
`1483`		`- LOG.warn("Failed to get response. Server returned {}. Retrying. (Duration: {})", System.nanoTime() - startTime, httpResponse.getCode());`
	`1483`	`+ LOG.warn("Failed to get response. Server returned {}. Retrying. (Duration: {})", httpResponse.getCode(), durationSince(startTime));`
`1484`	`1484`	`selectedEndpoint = getNextAliveNode();`
`1485`	`1485`	`continue;`
`1486`	`1486`	`}`
`@@ -1494,7 +1494,7 @@ public CompletableFuture<InsertResponse> insert(String tableName,`
`1494`	`1494`	`return new InsertResponse(metrics);`
`1495`	`1495`	`} catch (Exception e) {`
`1496`	`1496`	`lastException = httpClientHelper.wrapException(String.format("Insert failed (Attempt: %s/%s - Duration: %s)",`
`1497`		`- (i + 1), (retries + 1), System.nanoTime() - startTime), e);`
	`1497`	`+ (i + 1), (retries + 1), durationSince(startTime)), e);`
`1498`	`1498`	`if (httpClientHelper.shouldRetry(e, requestSettings.getAllSettings())) {`
`1499`	`1499`	`LOG.warn("Retrying.", e);`
`1500`	`1500`	`selectedEndpoint = getNextAliveNode();`
`@@ -1511,7 +1511,7 @@ public CompletableFuture<InsertResponse> insert(String tableName,`
`1511`	`1511`	`}`
`1512`	`1512`	`}`
`1513`	`1513`	`}`
`1514`		`- LOG.warn("Insert request failed after attempts: " + (retries + 1) + " - Duration: " + (System.nanoTime() - startTime));`
	`1514`	`+ LOG.warn("Insert request failed after attempts: {} - Duration: {}", retries + 1, durationSince(startTime));`
`1515`	`1515`	`throw (lastException == null ? new ClientException("Failed to complete insert operation") : lastException);`
`1516`	`1516`	`};`
`1517`	`1517`
`@@ -1603,7 +1603,7 @@ public CompletableFuture<QueryResponse> query(String sqlQuery, Map<String, Objec`
`1603`	`1603`
`1604`	`1604`	`// Check response`
`1605`	`1605`	`if (httpResponse.getCode() == HttpStatus.SC_SERVICE_UNAVAILABLE) {`
`1606`		`- LOG.warn("Failed to get response. Server returned {}. Retrying. (Duration: {})", System.nanoTime() - startTime, httpResponse.getCode());`
	`1606`	`+ LOG.warn("Failed to get response. Server returned {}. Retrying. (Duration: {})", httpResponse.getCode(), durationSince(startTime));`
`1607`	`1607`	`selectedEndpoint = getNextAliveNode();`
`1608`	`1608`	`HttpAPIClientHelper.closeQuietly(httpResponse);`
`1609`	`1609`	`continue;`
`@@ -1628,7 +1628,7 @@ public CompletableFuture<QueryResponse> query(String sqlQuery, Map<String, Objec`
`1628`	`1628`	`} catch (Exception e) {`
`1629`	`1629`	`HttpAPIClientHelper.closeQuietly(httpResponse);`
`1630`	`1630`	`lastException = httpClientHelper.wrapException(String.format("Query request failed (Attempt: %s/%s - Duration: %s)",`
`1631`		`- (i + 1), (retries + 1), System.nanoTime() - startTime), e);`
	`1631`	`+ (i + 1), (retries + 1), durationSince(startTime)), e);`
`1632`	`1632`	`if (httpClientHelper.shouldRetry(e, requestSettings.getAllSettings())) {`
`1633`	`1633`	`LOG.warn("Retrying.", e);`
`1634`	`1634`	`selectedEndpoint = getNextAliveNode();`
`@@ -1637,7 +1637,7 @@ public CompletableFuture<QueryResponse> query(String sqlQuery, Map<String, Objec`
`1637`	`1637`	`}`
`1638`	`1638`	`}`
`1639`	`1639`	`}`
`1640`		`- LOG.warn("Query request failed after attempts: " + (retries + 1) + " - Duration: " + (System.nanoTime() - startTime));`
	`1640`	`+ LOG.warn("Query request failed after attempts: {} - Duration: {}", retries + 1, durationSince(startTime));`
`1641`	`1641`	`throw (lastException == null ? new ClientException("Failed to complete query") : lastException);`
`1642`	`1642`	`};`
`1643`	`1643`
`@@ -2115,4 +2115,7 @@ private Map<String, Object> buildRequestSettings(Map<String, Object> opSettings)`
`2115`	`2115`	`return requestSettings;`
`2116`	`2116`	`}`
`2117`	`2117`
	`2118`	`+ private Duration durationSince(long sinceNanos) {`
	`2119`	`+ return Duration.ofNanos(System.nanoTime() - sinceNanos);`
	`2120`	`+ }`
`2118`	`2121`	`}`