From 825529a0e152942e86e151123946fe24e78eba36 Mon Sep 17 00:00:00 2001 From: Abdul Muneer Kolarkunnu Date: Fri, 5 Jul 2024 17:33:13 +0530 Subject: [PATCH] [Logging Improvement] Using lambda invocations instead of checking debug/trace isEnabled explicitly Converted debug/trace/warn/info checks to lambda based logging APIs. Resolves #8646 Signed-off-by: Abdul Muneer Kolarkunnu --- .../AbstractAsyncBulkByScrollAction.java | 14 +- .../transport/netty4/Netty4Transport.java | 22 ++- .../netty4/ssl/SecureNetty4Transport.java | 16 +- .../ec2/AwsEc2SeedHostsProvider.java | 18 +- .../cloud/gce/GceInstancesServiceImpl.java | 2 +- .../discovery/gce/GceSeedHostsProvider.java | 6 +- .../health/TransportClusterHealthAction.java | 4 +- ...TransportFieldCapabilitiesIndexAction.java | 12 +- .../search/AbstractSearchAsyncAction.java | 58 +++---- .../search/SearchScrollAsyncAction.java | 4 +- .../broadcast/TransportBroadcastAction.java | 42 +++-- .../node/TransportBroadcastByNodeAction.java | 42 ++--- .../support/nodes/TransportNodesAction.java | 4 +- .../replication/ReplicationOperation.java | 19 ++- .../TransportReplicationAction.java | 54 +++--- .../shard/TransportSingleShardAction.java | 22 +-- .../support/tasks/TransportTasksAction.java | 4 +- .../bootstrap/JNAKernel32Library.java | 5 +- .../org/opensearch/bootstrap/JNANatives.java | 4 +- .../bootstrap/SystemCallFilter.java | 10 +- .../cluster/InternalClusterInfoService.java | 52 +++--- .../action/shard/ShardStateAction.java | 8 +- .../allocator/LocalShardsBalancer.java | 78 ++++----- .../allocator/RemoteShardsBalancer.java | 104 +++++------ .../decider/AllocationDeciders.java | 58 +++---- .../decider/DiskThresholdDecider.java | 161 +++++++----------- .../SnapshotInProgressAllocationDecider.java | 12 +- .../java/org/opensearch/common/Rounding.java | 10 +- .../breaker/ChildMemoryCircuitBreaker.java | 25 ++- .../opensearch/common/settings/Setting.java | 15 +- .../util/concurrent/AbstractAsyncTask.java | 4 +- ...eResizingOpenSearchThreadPoolExecutor.java | 37 ++-- .../org/opensearch/env/NodeEnvironment.java | 4 +- .../gateway/PrimaryShardAllocator.java | 12 +- .../gateway/ReplicaShardAllocator.java | 23 +-- .../http/AbstractHttpServerTransport.java | 4 +- .../java/org/opensearch/http/HttpTracer.java | 4 +- .../identity/tokens/RestTokenExtractor.java | 8 +- .../org/opensearch/index/IndexSettings.java | 5 +- .../org/opensearch/index/IndexWarmer.java | 24 +-- .../index/cache/bitset/BitsetFilterCache.java | 16 +- .../OpenSearchConcurrentMergeScheduler.java | 22 ++- .../ordinals/GlobalOrdinalsBuilder.java | 14 +- .../reindex/ClientScrollableHitSource.java | 10 +- .../opensearch/index/shard/IndexShard.java | 108 +++++------- .../opensearch/index/shard/StoreRecovery.java | 11 +- .../indices/IndexingMemoryController.java | 43 ++--- .../indices/IndicesRequestCache.java | 29 ++-- .../opensearch/indices/IndicesService.java | 26 ++- .../indices/analysis/HunspellService.java | 4 +- .../cluster/IndicesClusterStateService.java | 18 +- .../recovery/PeerRecoveryTargetService.java | 71 +++----- .../recovery/RecoverySourceHandler.java | 14 +- .../org/opensearch/monitor/os/OsProbe.java | 8 +- .../main/java/org/opensearch/node/Node.java | 16 +- .../opensearch/plugins/PluginsService.java | 4 +- .../blobstore/FileRestoreContext.java | 26 +-- .../org/opensearch/script/ScriptCache.java | 20 +-- .../org/opensearch/script/ScriptService.java | 9 +- .../opensearch/search/fetch/FetchPhase.java | 4 +- .../opensearch/search/query/QueryPhase.java | 4 +- .../snapshots/SnapshotShardsService.java | 17 +- .../org/opensearch/tasks/TaskManager.java | 4 +- .../org/opensearch/threadpool/ThreadPool.java | 4 +- .../opensearch/transport/TcpTransport.java | 10 +- .../opensearch/transport/TransportLogger.java | 32 ++-- .../transport/TransportService.java | 36 ++-- .../test/OpenSearchIntegTestCase.java | 11 +- .../test/engine/MockEngineSupport.java | 10 +- .../test/store/MockFSDirectoryFactory.java | 4 +- 70 files changed, 690 insertions(+), 925 deletions(-) diff --git a/modules/reindex/src/main/java/org/opensearch/index/reindex/AbstractAsyncBulkByScrollAction.java b/modules/reindex/src/main/java/org/opensearch/index/reindex/AbstractAsyncBulkByScrollAction.java index 6ed486fbdb33b..2ff5ead274a83 100644 --- a/modules/reindex/src/main/java/org/opensearch/index/reindex/AbstractAsyncBulkByScrollAction.java +++ b/modules/reindex/src/main/java/org/opensearch/index/reindex/AbstractAsyncBulkByScrollAction.java @@ -403,14 +403,12 @@ void prepareBulkRequest(long thisBatchStartTimeNS, ScrollableHitSource.AsyncResp * Send a bulk request, handling retries. */ void sendBulkRequest(BulkRequest request, Runnable onSuccess) { - if (logger.isDebugEnabled()) { - logger.debug( - "[{}]: sending [{}] entry, [{}] bulk request", - task.getId(), - request.requests().size(), - new ByteSizeValue(request.estimatedSizeInBytes()) - ); - } + logger.debug( + "[{}]: sending [{}] entry, [{}] bulk request", + () -> task.getId(), + () -> request.requests().size(), + () -> new ByteSizeValue(request.estimatedSizeInBytes()) + ); if (task.isCancelled()) { logger.debug("[{}]: finishing early because the task was cancelled", task.getId()); finishHim(null); diff --git a/modules/transport-netty4/src/main/java/org/opensearch/transport/netty4/Netty4Transport.java b/modules/transport-netty4/src/main/java/org/opensearch/transport/netty4/Netty4Transport.java index e76a227630dc1..91c0a48c4d6d6 100644 --- a/modules/transport-netty4/src/main/java/org/opensearch/transport/netty4/Netty4Transport.java +++ b/modules/transport-netty4/src/main/java/org/opensearch/transport/netty4/Netty4Transport.java @@ -228,18 +228,16 @@ private Bootstrap createClientBootstrap(SharedGroupFactory.SharedGroup sharedGro private void createServerBootstrap(ProfileSettings profileSettings, SharedGroupFactory.SharedGroup sharedGroup) { String name = profileSettings.profileName; - if (logger.isDebugEnabled()) { - logger.debug( - "using profile[{}], worker_count[{}], port[{}], bind_host[{}], publish_host[{}], receive_predictor[{}->{}]", - name, - sharedGroupFactory.getTransportWorkerCount(), - profileSettings.portOrRange, - profileSettings.bindHosts, - profileSettings.publishHosts, - receivePredictorMin, - receivePredictorMax - ); - } + logger.debug( + "using profile[{}], worker_count[{}], port[{}], bind_host[{}], publish_host[{}], receive_predictor[{}->{}]", + () -> name, + () -> sharedGroupFactory.getTransportWorkerCount(), + () -> profileSettings.portOrRange, + () -> profileSettings.bindHosts, + () -> profileSettings.publishHosts, + () -> receivePredictorMin, + () -> receivePredictorMax + ); final ServerBootstrap serverBootstrap = new ServerBootstrap(); diff --git a/modules/transport-netty4/src/main/java/org/opensearch/transport/netty4/ssl/SecureNetty4Transport.java b/modules/transport-netty4/src/main/java/org/opensearch/transport/netty4/ssl/SecureNetty4Transport.java index 977121346dcc3..f8db1b94871c5 100644 --- a/modules/transport-netty4/src/main/java/org/opensearch/transport/netty4/ssl/SecureNetty4Transport.java +++ b/modules/transport-netty4/src/main/java/org/opensearch/transport/netty4/ssl/SecureNetty4Transport.java @@ -215,15 +215,13 @@ public void connect(ChannelHandlerContext ctx, SocketAddress remoteAddress, Sock ? inetSocketAddress.getHostName() : inetSocketAddress.getHostString(); - if (log.isDebugEnabled()) { - log.debug( - "Hostname of peer is {} ({}/{}) with hostnameVerificationResolveHostName: {}", - hostname, - inetSocketAddress.getHostName(), - inetSocketAddress.getHostString(), - hostnameVerificationResovleHostName - ); - } + log.debug( + "Hostname of peer is {} ({}/{}) with hostnameVerificationResolveHostName: {}", + () -> hostname, + () -> inetSocketAddress.getHostName(), + () -> inetSocketAddress.getHostString(), + () -> hostnameVerificationResovleHostName + ); sslEngine = secureTransportSettingsProvider.buildSecureClientTransportEngine( settings, diff --git a/plugins/discovery-ec2/src/main/java/org/opensearch/discovery/ec2/AwsEc2SeedHostsProvider.java b/plugins/discovery-ec2/src/main/java/org/opensearch/discovery/ec2/AwsEc2SeedHostsProvider.java index fb46b82065fd1..070424de41fbd 100644 --- a/plugins/discovery-ec2/src/main/java/org/opensearch/discovery/ec2/AwsEc2SeedHostsProvider.java +++ b/plugins/discovery-ec2/src/main/java/org/opensearch/discovery/ec2/AwsEc2SeedHostsProvider.java @@ -107,16 +107,14 @@ class AwsEc2SeedHostsProvider implements SeedHostsProvider { instanceStates.add("running"); instanceStates.add("pending"); - if (logger.isDebugEnabled()) { - logger.debug( - "using host_type [{}], tags [{}], groups [{}] with any_group [{}], availability_zones [{}]", - hostType, - tags, - groups, - bindAnyGroup, - availabilityZones - ); - } + logger.debug( + "using host_type [{}], tags [{}], groups [{}] with any_group [{}], availability_zones [{}]", + () -> hostType, + () -> tags, + () -> groups, + () -> bindAnyGroup, + () -> availabilityZones + ); } @Override diff --git a/plugins/discovery-gce/src/main/java/org/opensearch/cloud/gce/GceInstancesServiceImpl.java b/plugins/discovery-gce/src/main/java/org/opensearch/cloud/gce/GceInstancesServiceImpl.java index 46cc1c8eab537..45461e6e0d5cd 100644 --- a/plugins/discovery-gce/src/main/java/org/opensearch/cloud/gce/GceInstancesServiceImpl.java +++ b/plugins/discovery-gce/src/main/java/org/opensearch/cloud/gce/GceInstancesServiceImpl.java @@ -203,7 +203,7 @@ protected synchronized HttpTransport getGceHttpTransport() throws GeneralSecurit public synchronized Compute client() { if (refreshInterval != null && refreshInterval.millis() != 0) { if (client != null && (refreshInterval.millis() < 0 || (System.currentTimeMillis() - lastRefresh) < refreshInterval.millis())) { - if (logger.isTraceEnabled()) logger.trace("using cache to retrieve client"); + logger.trace(() -> "using cache to retrieve client"); return client; } lastRefresh = System.currentTimeMillis(); diff --git a/plugins/discovery-gce/src/main/java/org/opensearch/discovery/gce/GceSeedHostsProvider.java b/plugins/discovery-gce/src/main/java/org/opensearch/discovery/gce/GceSeedHostsProvider.java index 5958c07e244ad..ec96cf1fd4542 100644 --- a/plugins/discovery-gce/src/main/java/org/opensearch/discovery/gce/GceSeedHostsProvider.java +++ b/plugins/discovery-gce/src/main/java/org/opensearch/discovery/gce/GceSeedHostsProvider.java @@ -107,9 +107,7 @@ public GceSeedHostsProvider( this.zones = gceInstancesService.zones(); this.tags = TAGS_SETTING.get(settings); - if (logger.isDebugEnabled()) { - logger.debug("using tags {}", this.tags); - } + logger.debug("using tags {}", () -> this.tags); } /** @@ -133,7 +131,7 @@ public List getSeedAddresses(HostsResolver hostsResolver) { if (refreshInterval.millis() != 0) { if (cachedDynamicHosts != null && (refreshInterval.millis() < 0 || (System.currentTimeMillis() - lastRefresh) < refreshInterval.millis())) { - if (logger.isTraceEnabled()) logger.trace("using cache to retrieve node list"); + logger.trace(() -> "using cache to retrieve node list"); return cachedDynamicHosts; } lastRefresh = System.currentTimeMillis(); diff --git a/server/src/main/java/org/opensearch/action/admin/cluster/health/TransportClusterHealthAction.java b/server/src/main/java/org/opensearch/action/admin/cluster/health/TransportClusterHealthAction.java index 1cc357a4c20f4..e91a182633f00 100644 --- a/server/src/main/java/org/opensearch/action/admin/cluster/health/TransportClusterHealthAction.java +++ b/server/src/main/java/org/opensearch/action/admin/cluster/health/TransportClusterHealthAction.java @@ -486,9 +486,7 @@ private ClusterHealthResponse clusterHealth( int numberOfInFlightFetch, TimeValue pendingTaskTimeInQueue ) { - if (logger.isTraceEnabled()) { - logger.trace("Calculating health based on state version [{}]", clusterState.version()); - } + logger.trace("Calculating health based on state version [{}]", () -> clusterState.version()); String[] concreteIndices; if (request.level().equals(ClusterHealthRequest.Level.AWARENESS_ATTRIBUTES)) { diff --git a/server/src/main/java/org/opensearch/action/fieldcaps/TransportFieldCapabilitiesIndexAction.java b/server/src/main/java/org/opensearch/action/fieldcaps/TransportFieldCapabilitiesIndexAction.java index 10bf4975311d6..727d8febf6ac2 100644 --- a/server/src/main/java/org/opensearch/action/fieldcaps/TransportFieldCapabilitiesIndexAction.java +++ b/server/src/main/java/org/opensearch/action/fieldcaps/TransportFieldCapabilitiesIndexAction.java @@ -232,9 +232,7 @@ private AsyncShardsAction(FieldCapabilitiesIndexRequest request, ActionListener< this.listener = listener; ClusterState clusterState = clusterService.state(); - if (logger.isTraceEnabled()) { - logger.trace("executing [{}] based on cluster state version [{}]", request, clusterState.version()); - } + logger.trace("executing [{}] based on cluster state version [{}]", () -> request, () -> clusterState.version()); nodes = clusterState.nodes(); ClusterBlockException blockException = checkGlobalBlock(clusterState); if (blockException != null) { @@ -306,9 +304,7 @@ private void tryNext(@Nullable final Exception lastFailure, boolean canMatchShar onFailure(shardRouting, new NoShardAvailableActionException(shardRouting.shardId())); } else { request.shardId(shardRouting.shardId()); - if (logger.isTraceEnabled()) { - logger.trace("sending request [{}] on node [{}]", request, node); - } + logger.trace("sending request [{}] on node [{}]", () -> request, () -> node); transportService.sendRequest( node, ACTION_SHARD_NAME, @@ -354,9 +350,7 @@ private class ShardTransportHandler implements TransportRequestHandler request); ActionListener listener = new ChannelActionListener<>(channel, ACTION_SHARD_NAME, request); executor.execute(ActionRunnable.supply(listener, () -> shardOperation(request))); } diff --git a/server/src/main/java/org/opensearch/action/search/AbstractSearchAsyncAction.java b/server/src/main/java/org/opensearch/action/search/AbstractSearchAsyncAction.java index f0fc05c595d6f..72bda90648a57 100644 --- a/server/src/main/java/org/opensearch/action/search/AbstractSearchAsyncAction.java +++ b/server/src/main/java/org/opensearch/action/search/AbstractSearchAsyncAction.java @@ -402,48 +402,36 @@ public final void executeNextPhase(SearchPhase currentPhase, SearchPhase nextPha // successful retries can reset the failures to null ShardOperationFailedException[] shardSearchFailures = buildShardFailures(); if (shardSearchFailures.length > 0) { - if (logger.isDebugEnabled()) { - int numShardFailures = shardSearchFailures.length; - shardSearchFailures = ExceptionsHelper.groupBy(shardSearchFailures); - Throwable cause = OpenSearchException.guessRootCauses(shardSearchFailures[0].getCause())[0]; - logger.debug( - () -> new ParameterizedMessage("{} shards failed for phase: [{}]", numShardFailures, getName()), - cause - ); - } + logger.debug( + () -> new ParameterizedMessage("{} shards failed for phase: [{}]", shardSearchFailures.length, getName()), + OpenSearchException.guessRootCauses(ExceptionsHelper.groupBy(shardSearchFailures)[0].getCause())[0] + ); onPhaseFailure(currentPhase, "Partial shards failure", null); return; } else { int discrepancy = getNumShards() - successfulOps.get(); assert discrepancy > 0 : "discrepancy: " + discrepancy; - if (logger.isDebugEnabled()) { - logger.debug( - "Partial shards failure (unavailable: {}, successful: {}, skipped: {}, num-shards: {}, phase: {})", - discrepancy, - successfulOps.get(), - skippedOps.get(), - getNumShards(), - currentPhase.getName() - ); - } + logger.debug( + "Partial shards failure (unavailable: {}, successful: {}, skipped: {}, num-shards: {}, phase: {})", + () -> discrepancy, + () -> successfulOps.get(), + () -> skippedOps.get(), + () -> getNumShards(), + () -> currentPhase.getName() + ); if (!request.indicesOptions().ignoreUnavailable()) { onPhaseFailure(currentPhase, "Partial shards failure (" + discrepancy + " shards unavailable)", null); return; } } } - if (logger.isTraceEnabled()) { - final String resultsFrom = results.getSuccessfulResults() - .map(r -> r.getSearchShardTarget().toString()) - .collect(Collectors.joining(",")); - logger.trace( - "[{}] Moving to next phase: [{}], based on results from: {} (cluster state version: {})", - currentPhase.getName(), - nextPhase.getName(), - resultsFrom, - clusterState.version() - ); - } + logger.trace( + "[{}] Moving to next phase: [{}], based on results from: {} (cluster state version: {})", + () -> currentPhase.getName(), + () -> nextPhase.getName(), + () -> results.getSuccessfulResults().map(r -> r.getSearchShardTarget().toString()).collect(Collectors.joining(",")), + () -> clusterState.version() + ); onPhaseEnd(searchRequestContext); executePhase(nextPhase); } @@ -480,9 +468,7 @@ private void executePhase(SearchPhase phase) { onPhaseStart(phase); phase.recordAndRun(); } catch (Exception e) { - if (logger.isDebugEnabled()) { - logger.debug(new ParameterizedMessage("Failed to execute [{}] while moving to [{}] phase", request, phase.getName()), e); - } + logger.debug(() -> new ParameterizedMessage("Failed to execute [{}] while moving to [{}] phase", request, phase.getName()), e); if (currentPhaseHasLifecycle == false) { phaseSpan.setError(e); @@ -621,9 +607,7 @@ protected void onShardResult(Result result, SearchShardIterator shardIt) { assert result.getShardIndex() != -1 : "shard index is not set"; assert result.getSearchShardTarget() != null : "search shard target must not be null"; hasShardResponse.set(true); - if (logger.isTraceEnabled()) { - logger.trace("got first-phase result from {}", result != null ? result.getSearchShardTarget() : null); - } + logger.trace("got first-phase result from {}", () -> result != null ? result.getSearchShardTarget() : null); this.setPhaseResourceUsages(); results.consumeResult(result, () -> onShardResultConsumed(result, shardIt)); } diff --git a/server/src/main/java/org/opensearch/action/search/SearchScrollAsyncAction.java b/server/src/main/java/org/opensearch/action/search/SearchScrollAsyncAction.java index 7329a03f7e281..13ff097a595b0 100644 --- a/server/src/main/java/org/opensearch/action/search/SearchScrollAsyncAction.java +++ b/server/src/main/java/org/opensearch/action/search/SearchScrollAsyncAction.java @@ -317,9 +317,7 @@ protected void onShardFailure( @Nullable SearchShardTarget searchShardTarget, Supplier nextPhaseSupplier ) { - if (logger.isDebugEnabled()) { - logger.debug(new ParameterizedMessage("[{}] Failed to execute {} phase", searchId, phaseName), failure); - } + logger.debug(() -> new ParameterizedMessage("[{}] Failed to execute {} phase", searchId, phaseName), failure); addShardFailure(new ShardSearchFailure(failure, searchShardTarget)); int successfulOperations = successfulOps.decrementAndGet(); assert successfulOperations >= 0 : "successfulOperations must be >= 0 but was: " + successfulOperations; diff --git a/server/src/main/java/org/opensearch/action/support/broadcast/TransportBroadcastAction.java b/server/src/main/java/org/opensearch/action/support/broadcast/TransportBroadcastAction.java index 8bf8555194976..33c419bda6a10 100644 --- a/server/src/main/java/org/opensearch/action/support/broadcast/TransportBroadcastAction.java +++ b/server/src/main/java/org/opensearch/action/support/broadcast/TransportBroadcastAction.java @@ -256,33 +256,29 @@ void onOperation(@Nullable ShardRouting shard, final ShardIterator shardIt, int if (nextShard != null) { if (e != null) { - if (logger.isTraceEnabled()) { - if (!TransportActions.isShardNotAvailableException(e)) { - logger.trace( - new ParameterizedMessage( - "{}: failed to execute [{}]", - shard != null ? shard.shortSummary() : shardIt.shardId(), - request - ), - e - ); - } + if (!TransportActions.isShardNotAvailableException(e)) { + logger.trace( + () -> new ParameterizedMessage( + "{}: failed to execute [{}]", + shard != null ? shard.shortSummary() : shardIt.shardId(), + request + ), + e + ); } } performOperation(shardIt, nextShard, shardIndex); } else { - if (logger.isDebugEnabled()) { - if (e != null) { - if (!TransportActions.isShardNotAvailableException(e)) { - logger.debug( - new ParameterizedMessage( - "{}: failed to execute [{}]", - shard != null ? shard.shortSummary() : shardIt.shardId(), - request - ), - e - ); - } + if (e != null) { + if (!TransportActions.isShardNotAvailableException(e)) { + logger.debug( + () -> new ParameterizedMessage( + "{}: failed to execute [{}]", + shard != null ? shard.shortSummary() : shardIt.shardId(), + request + ), + e + ); } } if (expectedOps == counterOps.incrementAndGet()) { diff --git a/server/src/main/java/org/opensearch/action/support/broadcast/node/TransportBroadcastByNodeAction.java b/server/src/main/java/org/opensearch/action/support/broadcast/node/TransportBroadcastByNodeAction.java index c08cfb7af0e3d..ba7169b85d055 100644 --- a/server/src/main/java/org/opensearch/action/support/broadcast/node/TransportBroadcastByNodeAction.java +++ b/server/src/main/java/org/opensearch/action/support/broadcast/node/TransportBroadcastByNodeAction.java @@ -308,9 +308,7 @@ protected AsyncAction(Task task, Request request, ActionListener liste throw requestBlockException; } - if (logger.isTraceEnabled()) { - logger.trace("resolving shards for [{}] based on cluster state version [{}]", actionName, clusterState.version()); - } + logger.trace("resolving shards for [{}] based on cluster state version [{}]", () -> actionName, () -> clusterState.version()); ShardsIterator shardIt = shards(clusterState, request, concreteIndices); nodeIds = new HashMap<>(); @@ -400,9 +398,7 @@ public String executor() { } protected void onNodeResponse(DiscoveryNode node, int nodeIndex, NodeResponse response) { - if (logger.isTraceEnabled()) { - logger.trace("received response for [{}] from node [{}]", actionName, node.getId()); - } + logger.trace("received response for [{}] from node [{}]", () -> actionName, () -> node.getId()); // this is defensive to protect against the possibility of double invocation // the current implementation of TransportService#sendRequest guards against this @@ -416,8 +412,8 @@ protected void onNodeResponse(DiscoveryNode node, int nodeIndex, NodeResponse re protected void onNodeFailure(DiscoveryNode node, int nodeIndex, Throwable t) { String nodeId = node.getId(); - if (logger.isDebugEnabled() && !(t instanceof NodeShouldNotConnectException)) { - logger.debug(new ParameterizedMessage("failed to execute [{}] on node [{}]", actionName, nodeId), t); + if (!(t instanceof NodeShouldNotConnectException)) { + logger.debug(() -> new ParameterizedMessage("failed to execute [{}] on node [{}]", actionName, nodeId), t); } // this is defensive to protect against the possibility of double invocation @@ -458,9 +454,7 @@ class BroadcastByNodeTransportRequestHandler implements TransportRequestHandler< public void messageReceived(final NodeRequest request, TransportChannel channel, Task task) throws Exception { List shards = request.getShards(); final int totalShards = shards.size(); - if (logger.isTraceEnabled()) { - logger.trace("[{}] executing operation on [{}] shards", actionName, totalShards); - } + logger.trace("[{}] executing operation on [{}] shards", () -> actionName, () -> totalShards); final Object[] shardResultOrExceptions = new Object[totalShards]; int shardIndex = -1; @@ -489,14 +483,10 @@ private void onShardOperation( final ShardRouting shardRouting ) { try { - if (logger.isTraceEnabled()) { - logger.trace("[{}] executing operation for shard [{}]", actionName, shardRouting.shortSummary()); - } + logger.trace("[{}] executing operation for shard [{}]", () -> actionName, () -> shardRouting.shortSummary()); ShardOperationResult result = shardOperation(request.indicesLevelRequest, shardRouting); shardResults[shardIndex] = result; - if (logger.isTraceEnabled()) { - logger.trace("[{}] completed operation for shard [{}]", actionName, shardRouting.shortSummary()); - } + logger.trace("[{}] completed operation for shard [{}]", () -> actionName, () -> shardRouting.shortSummary()); } catch (Exception e) { BroadcastShardOperationFailedException failure = new BroadcastShardOperationFailedException( shardRouting.shardId(), @@ -517,16 +507,14 @@ private void onShardOperation( ); } } else { - if (logger.isDebugEnabled()) { - logger.debug( - new ParameterizedMessage( - "[{}] failed to execute operation for shard [{}]", - actionName, - shardRouting.shortSummary() - ), - e - ); - } + logger.debug( + () -> new ParameterizedMessage( + "[{}] failed to execute operation for shard [{}]", + actionName, + shardRouting.shortSummary() + ), + e + ); } } } diff --git a/server/src/main/java/org/opensearch/action/support/nodes/TransportNodesAction.java b/server/src/main/java/org/opensearch/action/support/nodes/TransportNodesAction.java index 9a1a28dd70636..d0fe57da51fed 100644 --- a/server/src/main/java/org/opensearch/action/support/nodes/TransportNodesAction.java +++ b/server/src/main/java/org/opensearch/action/support/nodes/TransportNodesAction.java @@ -302,8 +302,8 @@ private void onOperation(int idx, NodeResponse nodeResponse) { } private void onFailure(int idx, String nodeId, Throwable t) { - if (logger.isDebugEnabled() && !(t instanceof NodeShouldNotConnectException)) { - logger.debug(new ParameterizedMessage("failed to execute on node [{}]", nodeId), t); + if (!(t instanceof NodeShouldNotConnectException)) { + logger.debug(() -> new ParameterizedMessage("failed to execute on node [{}]", nodeId), t); } responses.set(idx, new FailedNodeException(nodeId, "Failed node [" + nodeId + "]", t)); if (counter.incrementAndGet() == responses.length()) { diff --git a/server/src/main/java/org/opensearch/action/support/replication/ReplicationOperation.java b/server/src/main/java/org/opensearch/action/support/replication/ReplicationOperation.java index 9f69d41d83f5b..cd125120a0132 100644 --- a/server/src/main/java/org/opensearch/action/support/replication/ReplicationOperation.java +++ b/server/src/main/java/org/opensearch/action/support/replication/ReplicationOperation.java @@ -162,9 +162,12 @@ private void handlePrimaryResult(final PrimaryResultT primaryResult) { this.primaryResult = primaryResult; final ReplicaRequest replicaRequest = primaryResult.replicaRequest(); if (replicaRequest != null) { - if (logger.isTraceEnabled()) { - logger.trace("[{}] op [{}] completed on primary for request [{}]", primary.routingEntry().shardId(), opType, request); - } + logger.trace( + "[{}] op [{}] completed on primary for request [{}]", + () -> primary.routingEntry().shardId(), + () -> opType, + () -> request + ); // we have to get the replication group after successfully indexing into the primary in order to honour recovery semantics. // we have to make sure that every operation indexed into the primary after recovery start will also be replicated // to the recovery target. If we used an old replication group, we may miss a recovery that has started since then. @@ -253,9 +256,13 @@ private void performOnReplica( final ReplicaRequest replicaRequest = replicationProxyRequest.getReplicaRequest(); final PendingReplicationActions pendingReplicationActions = replicationProxyRequest.getPendingReplicationActions(); - if (logger.isTraceEnabled()) { - logger.trace("[{}] sending op [{}] to replica {} for request [{}]", shard.shardId(), opType, shard, replicaRequest); - } + logger.trace( + "[{}] sending op [{}] to replica {} for request [{}]", + () -> shard.shardId(), + () -> opType, + () -> shard, + () -> replicaRequest + ); totalShards.incrementAndGet(); pendingActions.incrementAndGet(); final ActionListener replicationListener = new ActionListener() { diff --git a/server/src/main/java/org/opensearch/action/support/replication/TransportReplicationAction.java b/server/src/main/java/org/opensearch/action/support/replication/TransportReplicationAction.java index 49a96603f6802..61d3be022dfed 100644 --- a/server/src/main/java/org/opensearch/action/support/replication/TransportReplicationAction.java +++ b/server/src/main/java/org/opensearch/action/support/replication/TransportReplicationAction.java @@ -837,14 +837,12 @@ public void onResponse(Releasable releasable) { replica.getLastSyncedGlobalCheckpoint() ); releasable.close(); // release shard operation lock before responding to caller - if (logger.isTraceEnabled()) { - logger.trace( - "action [{}] completed on shard [{}] for request [{}]", - transportReplicaAction, - replicaRequest.getRequest().shardId(), - replicaRequest.getRequest() - ); - } + logger.trace( + "action [{}] completed on shard [{}] for request [{}]", + () -> transportReplicaAction, + () -> replicaRequest.getRequest().shardId(), + () -> replicaRequest.getRequest() + ); setPhase(task, "finished"); onCompletionListener.onResponse(response); }, e -> { @@ -1064,16 +1062,14 @@ protected void doRun() { private void performLocalAction(ClusterState state, ShardRouting primary, DiscoveryNode node, IndexMetadata indexMetadata) { setPhase(task, "waiting_on_primary"); - if (logger.isTraceEnabled()) { - logger.trace( - "send action [{}] to local primary [{}] for request [{}] with cluster state version [{}] to [{}] ", - transportPrimaryAction, - request.shardId(), - request, - state.version(), - primary.currentNodeId() - ); - } + logger.trace( + "send action [{}] to local primary [{}] for request [{}] with cluster state version [{}] to [{}] ", + () -> transportPrimaryAction, + () -> request.shardId(), + () -> request, + () -> state.version(), + () -> primary.currentNodeId() + ); performAction( node, transportPrimaryAction, @@ -1113,16 +1109,14 @@ private void performRemoteAction(ClusterState state, ShardRouting primary, Disco // target is not aware that it is the active primary shard already. request.routedBasedOnClusterVersion(state.version()); } - if (logger.isTraceEnabled()) { - logger.trace( - "send action [{}] on primary [{}] for request [{}] with cluster state version [{}] to [{}]", - actionName, - request.shardId(), - request, - state.version(), - primary.currentNodeId() - ); - } + logger.trace( + "send action [{}] on primary [{}] for request [{}] with cluster state version [{}] to [{}]", + () -> actionName, + () -> request.shardId(), + () -> request, + () -> state.version(), + () -> primary.currentNodeId() + ); setPhase(task, "rerouted"); performAction(node, actionName, false, request); } @@ -1236,9 +1230,7 @@ void finishWithUnexpectedFailure(Exception failure) { void finishOnSuccess(Response response) { if (finished.compareAndSet(false, true)) { setPhase(task, "finished"); - if (logger.isTraceEnabled()) { - logger.trace("operation succeeded. action [{}],request [{}]", actionName, request); - } + logger.trace("operation succeeded. action [{}],request [{}]", () -> actionName, () -> request); listener.onResponse(response); } else { assert false : "finishOnSuccess called but operation is already finished"; diff --git a/server/src/main/java/org/opensearch/action/support/single/shard/TransportSingleShardAction.java b/server/src/main/java/org/opensearch/action/support/single/shard/TransportSingleShardAction.java index df91559a2f8cb..7d876d51ff34c 100644 --- a/server/src/main/java/org/opensearch/action/support/single/shard/TransportSingleShardAction.java +++ b/server/src/main/java/org/opensearch/action/support/single/shard/TransportSingleShardAction.java @@ -171,9 +171,7 @@ private AsyncSingleAction(Request request, ActionListener listener) { this.listener = listener; ClusterState clusterState = clusterService.state(); - if (logger.isTraceEnabled()) { - logger.trace("executing [{}] based on cluster state version [{}]", request, clusterState.version()); - } + logger.trace("executing [{}] based on cluster state version [{}]", () -> request, () -> clusterState.version()); nodes = clusterState.nodes(); ClusterBlockException blockException = checkGlobalBlock(clusterState); if (blockException != null) { @@ -267,14 +265,12 @@ private void perform(@Nullable final Exception currentFailure) { onFailure(shardRouting, new NoShardAvailableActionException(shardRouting.shardId())); } else { internalRequest.request().internalShardId = shardRouting.shardId(); - if (logger.isTraceEnabled()) { - logger.trace( - "sending request [{}] to shard [{}] on node [{}]", - internalRequest.request(), - internalRequest.request().internalShardId, - node - ); - } + logger.trace( + "sending request [{}] to shard [{}] on node [{}]", + () -> internalRequest.request(), + () -> internalRequest.request().internalShardId, + () -> node + ); final Writeable.Reader reader = getResponseReader(); ShardRouting finalShardRouting = shardRouting; transportService.sendRequest( @@ -331,9 +327,7 @@ private class ShardTransportHandler implements TransportRequestHandler @Override public void messageReceived(final Request request, final TransportChannel channel, Task task) throws Exception { - if (logger.isTraceEnabled()) { - logger.trace("executing [{}] on shard [{}]", request, request.internalShardId); - } + logger.trace("executing [{}] on shard [{}]", () -> request, () -> request.internalShardId); asyncShardOperation(request, request.internalShardId, new ChannelActionListener<>(channel, transportShardAction, request)); } } diff --git a/server/src/main/java/org/opensearch/action/support/tasks/TransportTasksAction.java b/server/src/main/java/org/opensearch/action/support/tasks/TransportTasksAction.java index f33d7161660a3..7ed8b65dde47d 100644 --- a/server/src/main/java/org/opensearch/action/support/tasks/TransportTasksAction.java +++ b/server/src/main/java/org/opensearch/action/support/tasks/TransportTasksAction.java @@ -334,8 +334,8 @@ private void onOperation(int idx, NodeTasksResponse nodeResponse) { } private void onFailure(int idx, String nodeId, Throwable t) { - if (logger.isDebugEnabled() && !(t instanceof NodeShouldNotConnectException)) { - logger.debug(new ParameterizedMessage("failed to execute on node [{}]", nodeId), t); + if (!(t instanceof NodeShouldNotConnectException)) { + logger.debug(() -> new ParameterizedMessage("failed to execute on node [{}]", nodeId), t); } responses.set(idx, new FailedNodeException(nodeId, "Failed node [" + nodeId + "]", t)); diff --git a/server/src/main/java/org/opensearch/bootstrap/JNAKernel32Library.java b/server/src/main/java/org/opensearch/bootstrap/JNAKernel32Library.java index 91da34fb7216d..519aad7290be6 100644 --- a/server/src/main/java/org/opensearch/bootstrap/JNAKernel32Library.java +++ b/server/src/main/java/org/opensearch/bootstrap/JNAKernel32Library.java @@ -131,10 +131,7 @@ class NativeHandlerCallback implements StdCallLibrary.StdCallCallback { public boolean callback(long dwCtrlType) { int event = (int) dwCtrlType; - if (logger.isDebugEnabled()) { - logger.debug("console control handler receives event [{}@{}]", event, dwCtrlType); - - } + logger.debug("console control handler receives event [{}@{}]", () -> event, () -> dwCtrlType); return handler.handle(event); } } diff --git a/server/src/main/java/org/opensearch/bootstrap/JNANatives.java b/server/src/main/java/org/opensearch/bootstrap/JNANatives.java index 033596033b0fd..baac0acb36bb8 100644 --- a/server/src/main/java/org/opensearch/bootstrap/JNANatives.java +++ b/server/src/main/java/org/opensearch/bootstrap/JNANatives.java @@ -286,9 +286,7 @@ static void tryInstallSystemCallFilter(Path tmpFile) { } catch (Exception e) { // this is likely to happen unless the kernel is newish, its a best effort at the moment // so we log stacktrace at debug for now... - if (logger.isDebugEnabled()) { - logger.debug("unable to install syscall filter", e); - } + logger.debug(() -> "unable to install syscall filter", e); logger.warn("unable to install syscall filter: ", e); } } diff --git a/server/src/main/java/org/opensearch/bootstrap/SystemCallFilter.java b/server/src/main/java/org/opensearch/bootstrap/SystemCallFilter.java index 6347c37a7c7a5..5bd7c49cb8bd5 100644 --- a/server/src/main/java/org/opensearch/bootstrap/SystemCallFilter.java +++ b/server/src/main/java/org/opensearch/bootstrap/SystemCallFilter.java @@ -433,12 +433,10 @@ private static int linuxImpl() { if (linux_syscall(arch.seccomp, SECCOMP_SET_MODE_FILTER, SECCOMP_FILTER_FLAG_TSYNC, new NativeLong(pointer)) != 0) { method = 0; int errno1 = Native.getLastError(); - if (logger.isDebugEnabled()) { - logger.debug( - "seccomp(SECCOMP_SET_MODE_FILTER): {}, falling back to prctl(PR_SET_SECCOMP)...", - JNACLibrary.strerror(errno1) - ); - } + logger.debug( + "seccomp(SECCOMP_SET_MODE_FILTER): {}, falling back to prctl(PR_SET_SECCOMP)...", + () -> JNACLibrary.strerror(errno1) + ); if (linux_prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, pointer, 0, 0) != 0) { int errno2 = Native.getLastError(); throw new UnsupportedOperationException( diff --git a/server/src/main/java/org/opensearch/cluster/InternalClusterInfoService.java b/server/src/main/java/org/opensearch/cluster/InternalClusterInfoService.java index e381b8f244bf3..c0219a8ef4b96 100644 --- a/server/src/main/java/org/opensearch/cluster/InternalClusterInfoService.java +++ b/server/src/main/java/org/opensearch/cluster/InternalClusterInfoService.java @@ -285,9 +285,7 @@ public void onFailure(Exception e) { logger.error("NodeStatsAction timed out for ClusterInfoUpdateJob", e); } else { if (e instanceof ClusterBlockException) { - if (logger.isTraceEnabled()) { - logger.trace("Failed to execute NodeStatsAction for ClusterInfoUpdateJob", e); - } + logger.trace(() -> "Failed to execute NodeStatsAction for ClusterInfoUpdateJob", e); } else { logger.warn("Failed to execute NodeStatsAction for ClusterInfoUpdateJob", e); } @@ -319,9 +317,7 @@ public void onFailure(Exception e) { logger.error("IndicesStatsAction timed out for ClusterInfoUpdateJob", e); } else { if (e instanceof ClusterBlockException) { - if (logger.isTraceEnabled()) { - logger.trace("Failed to execute IndicesStatsAction for ClusterInfoUpdateJob", e); - } + logger.trace(() -> "Failed to execute IndicesStatsAction for ClusterInfoUpdateJob", e); } else { logger.warn("Failed to execute IndicesStatsAction for ClusterInfoUpdateJob", e); } @@ -422,25 +418,23 @@ static void fillDiskUsagePerNode( } String nodeId = nodeStats.getNode().getId(); String nodeName = nodeStats.getNode().getName(); - if (logger.isTraceEnabled()) { + final FsInfo.Path finalMostAvailablePath = mostAvailablePath; + final FsInfo.Path finalLeastAvailablePath = leastAvailablePath; + logger.trace( + "node: [{}], most available: total disk: {}," + + " available disk: {} / least available: total disk: {}, available disk: {}", + () -> nodeId, + () -> finalMostAvailablePath.getTotal(), + () -> finalMostAvailablePath.getAvailable(), + () -> finalLeastAvailablePath.getTotal(), + () -> finalLeastAvailablePath.getAvailable() + ); + if (leastAvailablePath.getTotal().getBytes() < 0) { logger.trace( - "node: [{}], most available: total disk: {}," - + " available disk: {} / least available: total disk: {}, available disk: {}", - nodeId, - mostAvailablePath.getTotal(), - mostAvailablePath.getAvailable(), - leastAvailablePath.getTotal(), - leastAvailablePath.getAvailable() + "node: [{}] least available path has less than 0 total bytes of disk [{}], skipping", + () -> nodeId, + () -> finalLeastAvailablePath.getTotal().getBytes() ); - } - if (leastAvailablePath.getTotal().getBytes() < 0) { - if (logger.isTraceEnabled()) { - logger.trace( - "node: [{}] least available path has less than 0 total bytes of disk [{}], skipping", - nodeId, - leastAvailablePath.getTotal().getBytes() - ); - } } else { newLeastAvailableUsages.put( nodeId, @@ -454,13 +448,11 @@ static void fillDiskUsagePerNode( ); } if (mostAvailablePath.getTotal().getBytes() < 0) { - if (logger.isTraceEnabled()) { - logger.trace( - "node: [{}] most available path has less than 0 total bytes of disk [{}], skipping", - nodeId, - mostAvailablePath.getTotal().getBytes() - ); - } + logger.trace( + "node: [{}] most available path has less than 0 total bytes of disk [{}], skipping", + () -> nodeId, + () -> finalMostAvailablePath.getTotal().getBytes() + ); } else { newMostAvailableUsages.put( nodeId, diff --git a/server/src/main/java/org/opensearch/cluster/action/shard/ShardStateAction.java b/server/src/main/java/org/opensearch/cluster/action/shard/ShardStateAction.java index cb5749a91d448..225ce1448f272 100644 --- a/server/src/main/java/org/opensearch/cluster/action/shard/ShardStateAction.java +++ b/server/src/main/java/org/opensearch/cluster/action/shard/ShardStateAction.java @@ -309,9 +309,11 @@ protected void waitForNewClusterManagerAndRetry( observer.waitForNextChange(new ClusterStateObserver.Listener() { @Override public void onNewClusterState(ClusterState state) { - if (logger.isTraceEnabled()) { - logger.trace("new cluster state [{}] after waiting for cluster-manager election for shard entry [{}]", state, request); - } + logger.trace( + "new cluster state [{}] after waiting for cluster-manager election for shard entry [{}]", + () -> state, + () -> request + ); sendShardAction(actionName, state, request, listener); } diff --git a/server/src/main/java/org/opensearch/cluster/routing/allocation/allocator/LocalShardsBalancer.java b/server/src/main/java/org/opensearch/cluster/routing/allocation/allocator/LocalShardsBalancer.java index 6978c988fd648..543ebc9725aa6 100644 --- a/server/src/main/java/org/opensearch/cluster/routing/allocation/allocator/LocalShardsBalancer.java +++ b/server/src/main/java/org/opensearch/cluster/routing/allocation/allocator/LocalShardsBalancer.java @@ -164,9 +164,7 @@ private static boolean lessThan(float delta, float threshold) { */ @Override void balance() { - if (logger.isTraceEnabled()) { - logger.trace("Start balancing cluster"); - } + logger.trace(() -> "Start balancing cluster"); if (allocation.hasPendingAsyncFetch()) { /* * see https://github.com/elastic/elasticsearch/issues/14387 @@ -367,6 +365,8 @@ private void balanceByWeights() { final BalancedShardsAllocator.ModelNode maxNode = modelNodes[highIdx]; advance_range: if (maxNode.numShards(index) > 0) { final float delta = absDelta(weights[lowIdx], weights[highIdx]); + final int finalHighIdx = highIdx; + final int finalLowIdx = lowIdx; if (lessThan(delta, threshold)) { if (lowIdx > 0 && highIdx - 1 > 0 // is there a chance for a higher delta? @@ -384,29 +384,26 @@ private void balanceByWeights() { */ break advance_range; } - if (logger.isTraceEnabled()) { - logger.trace( - "Stop balancing index [{}] min_node [{}] weight: [{}]" + " max_node [{}] weight: [{}] delta: [{}]", - index, - maxNode.getNodeId(), - weights[highIdx], - minNode.getNodeId(), - weights[lowIdx], - delta - ); - } - break; - } - if (logger.isTraceEnabled()) { + logger.trace( - "Balancing from node [{}] weight: [{}] to node [{}] weight: [{}] delta: [{}]", - maxNode.getNodeId(), - weights[highIdx], - minNode.getNodeId(), - weights[lowIdx], - delta + "Stop balancing index [{}] min_node [{}] weight: [{}]" + " max_node [{}] weight: [{}] delta: [{}]", + () -> index, + () -> maxNode.getNodeId(), + () -> weights[finalHighIdx], + () -> minNode.getNodeId(), + () -> weights[finalLowIdx], + () -> delta ); + break; } + logger.trace( + "Balancing from node [{}] weight: [{}] to node [{}] weight: [{}] delta: [{}]", + () -> maxNode.getNodeId(), + () -> weights[finalHighIdx], + () -> minNode.getNodeId(), + () -> weights[finalLowIdx], + () -> delta + ); if (delta <= 1.0f) { /* * prevent relocations that only swap the weights of the two nodes. a relocation must bring us closer to the @@ -586,7 +583,7 @@ void moveShards() { // is not being throttled. Decision canMoveAwayDecision = allocation.deciders().canMoveAway(shardRouting, allocation); if (canMoveAwayDecision.type() != Decision.Type.YES) { - if (logger.isDebugEnabled()) logger.debug("Cannot move away shard [{}] Skipping this shard", shardRouting); + logger.debug("Cannot move away shard [{}] Skipping this shard", () -> shardRouting); if (shardRouting.primary() && canMoveAwayDecision.type() == Decision.Type.THROTTLE) { primariesThrottled = true; } @@ -605,9 +602,7 @@ void moveShards() { allocation.changes() ); targetNode.addShard(relocatingShards.v2()); - if (logger.isTraceEnabled()) { - logger.trace("Moved shard [{}] to node [{}]", shardRouting, targetNode.getRoutingNode()); - } + logger.trace("Moved shard [{}] to node [{}]", () -> shardRouting, () -> targetNode.getRoutingNode()); // Verifying if this node can be considered ineligible for further iterations if (targetNode != null) { @@ -724,9 +719,7 @@ private Map buildModelFromAssigned() /* we skip relocating shards here since we expect an initializing shard with the same id coming in */ if (RoutingPool.LOCAL_ONLY.equals(RoutingPool.getShardPool(shard, allocation)) && shard.state() != RELOCATING) { node.addShard(shard); - if (logger.isTraceEnabled()) { - logger.trace("Assigned shard [{}] to node [{}]", shard, node.getNodeId()); - } + logger.trace("Assigned shard [{}] to node [{}]", () -> shard, () -> node.getNodeId()); } } } @@ -741,9 +734,7 @@ private Map buildModelFromAssigned() void allocateUnassigned() { RoutingNodes.UnassignedShards unassigned = routingNodes.unassigned(); assert !nodes.isEmpty(); - if (logger.isTraceEnabled()) { - logger.trace("Start allocating unassigned shards"); - } + logger.trace(() -> "Start allocating unassigned shards"); if (unassigned.isEmpty()) { return; } @@ -799,11 +790,10 @@ void allocateUnassigned() { ? allocationDecision.getTargetNode().getId() : null; final BalancedShardsAllocator.ModelNode minNode = assignedNodeId != null ? nodes.get(assignedNodeId) : null; + final ShardRouting finalShard = shard; if (allocationDecision.getAllocationDecision() == AllocationDecision.YES) { - if (logger.isTraceEnabled()) { - logger.trace("Assigned shard [{}] to [{}]", shard, minNode.getNodeId()); - } + logger.trace("Assigned shard [{}] to [{}]", () -> finalShard, () -> minNode.getNodeId()); final long shardSize = DiskThresholdDecider.getExpectedShardSize( shard, @@ -824,13 +814,11 @@ void allocateUnassigned() { } } else { // did *not* receive a YES decision - if (logger.isTraceEnabled()) { - logger.trace( - "No eligible node found to assign shard [{}] allocation_status [{}]", - shard, - allocationDecision.getAllocationStatus() - ); - } + logger.trace( + "No eligible node found to assign shard [{}] allocation_status [{}]", + () -> finalShard, + () -> allocationDecision.getAllocationStatus() + ); if (minNode != null) { // throttle decision scenario @@ -845,9 +833,7 @@ void allocateUnassigned() { ); minNode.addShard(shard.initialize(minNode.getNodeId(), null, shardSize)); } else { - if (logger.isTraceEnabled()) { - logger.trace("No Node found to assign shard [{}]", shard); - } + logger.trace("No Node found to assign shard [{}]", () -> finalShard); } unassigned.ignoreShard(shard, allocationDecision.getAllocationStatus(), allocation.changes()); diff --git a/server/src/main/java/org/opensearch/cluster/routing/allocation/allocator/RemoteShardsBalancer.java b/server/src/main/java/org/opensearch/cluster/routing/allocation/allocator/RemoteShardsBalancer.java index a05938c176678..dd35e0a057a39 100644 --- a/server/src/main/java/org/opensearch/cluster/routing/allocation/allocator/RemoteShardsBalancer.java +++ b/server/src/main/java/org/opensearch/cluster/routing/allocation/allocator/RemoteShardsBalancer.java @@ -185,14 +185,12 @@ private void tryShardMovementToEligibleNode(Queue eligibleNodes, Sh final Decision currentShardDecision = allocation.deciders().canAllocate(shard, targetNode, allocation); if (currentShardDecision.type() == Decision.Type.YES) { - if (logger.isDebugEnabled()) { - logger.debug( - "Moving shard: {} from node: [{}] to node: [{}]", - shardShortSummary(shard), - shard.currentNodeId(), - targetNode.nodeId() - ); - } + logger.debug( + "Moving shard: {} from node: [{}] to node: [{}]", + () -> shardShortSummary(shard), + () -> shard.currentNodeId(), + () -> targetNode.nodeId() + ); routingNodes.relocateShard( shard, targetNode.nodeId(), @@ -202,14 +200,12 @@ private void tryShardMovementToEligibleNode(Queue eligibleNodes, Sh eligibleNodes.offer(targetNode); return; } else { - if (logger.isTraceEnabled()) { - logger.trace( - "Cannot move shard: {} to node: [{}]. Decisions: [{}]", - shardShortSummary(shard), - targetNode.nodeId(), - currentShardDecision.getDecisions() - ); - } + logger.trace( + "Cannot move shard: {} to node: [{}]. Decisions: [{}]", + () -> shardShortSummary(shard), + () -> targetNode.nodeId(), + () -> currentShardDecision.getDecisions() + ); final Decision nodeLevelDecision = allocation.deciders().canAllocateAnyShardToNode(targetNode, allocation); if (nodeLevelDecision.type() == Decision.Type.YES) { @@ -397,22 +393,18 @@ private void allocateUnassignedShards( while (shardsToAllocate.isEmpty() == false && nodeQueue.isEmpty() == false) { ShardRouting shard = shardsToAllocate.poll(); if (shard.assignedToNode()) { - if (logger.isDebugEnabled()) { - logger.debug("Shard: {} already assigned to node: [{}]", shardShortSummary(shard), shard.currentNodeId()); - } + logger.debug("Shard: {} already assigned to node: [{}]", () -> shardShortSummary(shard), () -> shard.currentNodeId()); continue; } Decision shardLevelDecision = allocation.deciders().canAllocate(shard, allocation); if (shardLevelDecision.type() == Decision.Type.NO) { - if (logger.isDebugEnabled()) { - logger.debug( - "Ignoring shard: [{}] as is cannot be allocated to any node. Shard level decisions: [{}][{}].", - shardShortSummary(shard), - shardLevelDecision.getDecisions(), - shardLevelDecision.getExplanation() - ); - } + logger.debug( + "Ignoring shard: [{}] as is cannot be allocated to any node. Shard level decisions: [{}][{}].", + () -> shardShortSummary(shard), + () -> shardLevelDecision.getDecisions(), + () -> shardLevelDecision.getExplanation() + ); routingNodes.unassigned().ignoreShard(shard, UnassignedInfo.AllocationStatus.DECIDERS_NO, allocation.changes()); continue; } @@ -436,9 +428,7 @@ private void tryAllocateUnassignedShard(Queue nodeQueue, ShardRouti --numNodesToCheck; Decision allocateDecision = allocation.deciders().canAllocate(shard, node, allocation); if (allocateDecision.type() == Decision.Type.YES) { - if (logger.isTraceEnabled()) { - logger.trace("Assigned shard [{}] to [{}]", shardShortSummary(shard), node.nodeId()); - } + logger.trace("Assigned shard [{}] to [{}]", () -> shardShortSummary(shard), () -> node.nodeId()); final long shardSize = DiskThresholdDecider.getExpectedShardSize( shard, ShardRouting.UNAVAILABLE_EXPECTED_SHARD_SIZE, @@ -452,39 +442,33 @@ private void tryAllocateUnassignedShard(Queue nodeQueue, ShardRouti allocated = true; break; } else { - if (logger.isTraceEnabled()) { - logger.trace( - "Cannot allocate shard: {} on node [{}]. Decisions: [{}]", - shardShortSummary(shard), - node.nodeId(), - allocateDecision.getDecisions() - ); - } + logger.trace( + "Cannot allocate shard: {} on node [{}]. Decisions: [{}]", + () -> shardShortSummary(shard), + () -> node.nodeId(), + () -> allocateDecision.getDecisions() + ); throttled = throttled || allocateDecision.type() == Decision.Type.THROTTLE; Decision nodeLevelDecision = allocation.deciders().canAllocateAnyShardToNode(node, allocation); if (nodeLevelDecision.type() == Decision.Type.YES) { - if (logger.isTraceEnabled()) { - logger.trace( - "Node: [{}] can still accept shards, retaining it in queue - [{}]", - node.nodeId(), - nodeLevelDecision.getDecisions() - ); - } + logger.trace( + "Node: [{}] can still accept shards, retaining it in queue - [{}]", + () -> node.nodeId(), + () -> nodeLevelDecision.getDecisions() + ); nodeQueue.offer(node); } else { if (nodeLevelDecision.type() == Decision.Type.THROTTLE) { anyNodesThrottled = true; } - if (logger.isTraceEnabled()) { - logger.trace( - "Cannot allocate any shard to node: [{}]. Removing from queue. Node level decisions: [{}],[{}]", - node.nodeId(), - nodeLevelDecision.getDecisions(), - nodeLevelDecision.getExplanation() - ); - } + logger.trace( + "Cannot allocate any shard to node: [{}]. Removing from queue. Node level decisions: [{}],[{}]", + () -> node.nodeId(), + () -> nodeLevelDecision.getDecisions(), + () -> nodeLevelDecision.getExplanation() + ); } // Break out if all nodes in the queue have been checked for this shard @@ -553,14 +537,12 @@ private void tryRebalanceNode( targetNodes.offer(targetNode); nodesCheckedForRelocation.add(targetNode.nodeId()); } else { - if (logger.isTraceEnabled()) { - logger.trace( - "Cannot allocate any shard to node: [{}]. Removing from queue. Node level decisions: [{}],[{}]", - targetNode.nodeId(), - nodeDecision.getDecisions(), - nodeDecision.toString() - ); - } + logger.trace( + "Cannot allocate any shard to node: [{}]. Removing from queue. Node level decisions: [{}],[{}]", + () -> targetNode.nodeId(), + () -> nodeDecision.getDecisions(), + () -> nodeDecision.toString() + ); } } diff --git a/server/src/main/java/org/opensearch/cluster/routing/allocation/decider/AllocationDeciders.java b/server/src/main/java/org/opensearch/cluster/routing/allocation/decider/AllocationDeciders.java index 1263efd19ac46..d4c324cf73627 100644 --- a/server/src/main/java/org/opensearch/cluster/routing/allocation/decider/AllocationDeciders.java +++ b/server/src/main/java/org/opensearch/cluster/routing/allocation/decider/AllocationDeciders.java @@ -90,14 +90,12 @@ public Decision canAllocate(ShardRouting shardRouting, RoutingNode node, Routing Decision decision = allocationDecider.canAllocate(shardRouting, node, allocation); // short track if a NO is returned. if (decision == Decision.NO) { - if (logger.isTraceEnabled()) { - logger.trace( - "Can not allocate [{}] on node [{}] due to [{}]", - shardRouting, - node.node(), - allocationDecider.getClass().getSimpleName() - ); - } + logger.trace( + "Can not allocate [{}] on node [{}] due to [{}]", + () -> shardRouting, + () -> node.node(), + () -> allocationDecider.getClass().getSimpleName() + ); // short circuit only if debugging is not enabled if (allocation.debugDecision() == false) { return decision; @@ -114,9 +112,7 @@ public Decision canAllocate(ShardRouting shardRouting, RoutingNode node, Routing @Override public Decision canRemain(ShardRouting shardRouting, RoutingNode node, RoutingAllocation allocation) { if (allocation.shouldIgnoreShardForNode(shardRouting.shardId(), node.nodeId())) { - if (logger.isTraceEnabled()) { - logger.trace("Shard [{}] should be ignored for node [{}]", shardRouting, node.nodeId()); - } + logger.trace("Shard [{}] should be ignored for node [{}]", () -> shardRouting, () -> node.nodeId()); return Decision.NO; } Decision.Multi ret = new Decision.Multi(); @@ -124,14 +120,12 @@ public Decision canRemain(ShardRouting shardRouting, RoutingNode node, RoutingAl Decision decision = allocationDecider.canRemain(shardRouting, node, allocation); // short track if a NO is returned. if (decision == Decision.NO) { - if (logger.isTraceEnabled()) { - logger.trace( - "Shard [{}] can not remain on node [{}] due to [{}]", - shardRouting, - node.nodeId(), - allocationDecider.getClass().getSimpleName() - ); - } + logger.trace( + "Shard [{}] can not remain on node [{}] due to [{}]", + () -> shardRouting, + () -> node.nodeId(), + () -> allocationDecider.getClass().getSimpleName() + ); if (allocation.debugDecision() == false) { return decision; } else { @@ -232,14 +226,12 @@ public Decision canForceAllocatePrimary(ShardRouting shardRouting, RoutingNode n Decision decision = decider.canForceAllocatePrimary(shardRouting, node, allocation); // short track if a NO is returned. if (decision == Decision.NO) { - if (logger.isTraceEnabled()) { - logger.trace( - "Shard [{}] can not be forcefully allocated to node [{}] due to [{}].", - shardRouting.shardId(), - node.nodeId(), - decider.getClass().getSimpleName() - ); - } + logger.trace( + "Shard [{}] can not be forcefully allocated to node [{}] due to [{}].", + () -> shardRouting.shardId(), + () -> node.nodeId(), + () -> decider.getClass().getSimpleName() + ); if (allocation.debugDecision() == false) { return decision; } else { @@ -258,9 +250,11 @@ public Decision canAllocateAnyShardToNode(RoutingNode node, RoutingAllocation al for (AllocationDecider decider : allocations) { Decision decision = decider.canAllocateAnyShardToNode(node, allocation); if (decision.type().canPreemptivelyReturn()) { - if (logger.isTraceEnabled()) { - logger.trace("Shard can not be allocated on node [{}] due to [{}]", node.nodeId(), decider.getClass().getSimpleName()); - } + logger.trace( + "Shard can not be allocated on node [{}] due to [{}]", + () -> node.nodeId(), + () -> decider.getClass().getSimpleName() + ); if (allocation.debugDecision() == false) { return decision; } else { @@ -280,9 +274,7 @@ public Decision canMoveAway(ShardRouting shardRouting, RoutingAllocation allocat Decision decision = decider.canMoveAway(shardRouting, allocation); // short track if a NO is returned. if (decision.type().canPreemptivelyReturn()) { - if (logger.isTraceEnabled()) { - logger.trace("Shard [{}] can not be moved away due to [{}]", shardRouting, decider.getClass().getSimpleName()); - } + logger.trace("Shard [{}] can not be moved away due to [{}]", () -> shardRouting, () -> decider.getClass().getSimpleName()); if (allocation.debugDecision() == false) { return decision; } else { diff --git a/server/src/main/java/org/opensearch/cluster/routing/allocation/decider/DiskThresholdDecider.java b/server/src/main/java/org/opensearch/cluster/routing/allocation/decider/DiskThresholdDecider.java index efa5115939d3c..65f8390990de0 100644 --- a/server/src/main/java/org/opensearch/cluster/routing/allocation/decider/DiskThresholdDecider.java +++ b/server/src/main/java/org/opensearch/cluster/routing/allocation/decider/DiskThresholdDecider.java @@ -264,9 +264,7 @@ public Decision canAllocate(ShardRouting shardRouting, RoutingNode node, Routing } ByteSizeValue freeBytesValue = new ByteSizeValue(freeBytes); - if (logger.isTraceEnabled()) { - logger.trace("node [{}] has {}% used disk", node.nodeId(), usedDiskPercentage); - } + logger.trace("node [{}] has {}% used disk", () -> node.nodeId(), () -> usedDiskPercentage); // flag that determines whether the low threshold checks below can be skipped. We use this for a primary shard that is freshly // allocated and empty. @@ -277,14 +275,12 @@ public Decision canAllocate(ShardRouting shardRouting, RoutingNode node, Routing // checks for exact byte comparisons if (freeBytes < diskThresholdSettings.getFreeBytesThresholdLow().getBytes()) { if (skipLowThresholdChecks == false) { - if (logger.isDebugEnabled()) { - logger.debug( - "less than the required {} free bytes threshold ({} free) on node {}, preventing allocation", - diskThresholdSettings.getFreeBytesThresholdLow(), - freeBytesValue, - node.nodeId() - ); - } + logger.debug( + "less than the required {} free bytes threshold ({} free) on node {}, preventing allocation", + () -> diskThresholdSettings.getFreeBytesThresholdLow(), + () -> freeBytesValue, + () -> node.nodeId() + ); return allocation.decision( Decision.NO, NAME, @@ -298,15 +294,13 @@ public Decision canAllocate(ShardRouting shardRouting, RoutingNode node, Routing } else if (freeBytes > diskThresholdSettings.getFreeBytesThresholdHigh().getBytes()) { // Allow the shard to be allocated because it is primary that // has never been allocated if it's under the high watermark - if (logger.isDebugEnabled()) { - logger.debug( - "less than the required {} free bytes threshold ({} free) on node {}, " - + "but allowing allocation because primary has never been allocated", - diskThresholdSettings.getFreeBytesThresholdLow(), - freeBytesValue, - node.nodeId() - ); - } + logger.debug( + "less than the required {} free bytes threshold ({} free) on node {}, " + + "but allowing allocation because primary has never been allocated", + () -> diskThresholdSettings.getFreeBytesThresholdLow(), + () -> freeBytesValue, + () -> node.nodeId() + ); return allocation.decision( Decision.YES, NAME, @@ -316,15 +310,13 @@ public Decision canAllocate(ShardRouting shardRouting, RoutingNode node, Routing } else { // Even though the primary has never been allocated, the node is // above the high watermark, so don't allow allocating the shard - if (logger.isDebugEnabled()) { - logger.debug( - "less than the required {} free bytes threshold ({} free) on node {}, " - + "preventing allocation even though primary has never been allocated", - diskThresholdSettings.getFreeBytesThresholdHigh(), - freeBytesValue, - node.nodeId() - ); - } + logger.debug( + "less than the required {} free bytes threshold ({} free) on node {}, " + + "preventing allocation even though primary has never been allocated", + () -> diskThresholdSettings.getFreeBytesThresholdHigh(), + () -> freeBytesValue, + () -> node.nodeId() + ); return allocation.decision( Decision.NO, NAME, @@ -342,14 +334,12 @@ public Decision canAllocate(ShardRouting shardRouting, RoutingNode node, Routing if (freeDiskPercentage < diskThresholdSettings.getFreeDiskThresholdLow()) { // If the shard is a replica or is a non-empty primary, check the low threshold if (skipLowThresholdChecks == false) { - if (logger.isDebugEnabled()) { - logger.debug( - "more than the allowed {} used disk threshold ({} used) on node [{}], preventing allocation", - Strings.format1Decimals(usedDiskThresholdLow, "%"), - Strings.format1Decimals(usedDiskPercentage, "%"), - node.nodeId() - ); - } + logger.debug( + "more than the allowed {} used disk threshold ({} used) on node [{}], preventing allocation", + () -> Strings.format1Decimals(usedDiskThresholdLow, "%"), + () -> Strings.format1Decimals(usedDiskPercentage, "%"), + () -> node.nodeId() + ); return allocation.decision( Decision.NO, NAME, @@ -363,15 +353,13 @@ public Decision canAllocate(ShardRouting shardRouting, RoutingNode node, Routing } else if (freeDiskPercentage > diskThresholdSettings.getFreeDiskThresholdHigh()) { // Allow the shard to be allocated because it is primary that // has never been allocated if it's under the high watermark - if (logger.isDebugEnabled()) { - logger.debug( - "more than the allowed {} used disk threshold ({} used) on node [{}], " - + "but allowing allocation because primary has never been allocated", - Strings.format1Decimals(usedDiskThresholdLow, "%"), - Strings.format1Decimals(usedDiskPercentage, "%"), - node.nodeId() - ); - } + logger.debug( + "more than the allowed {} used disk threshold ({} used) on node [{}], " + + "but allowing allocation because primary has never been allocated", + () -> Strings.format1Decimals(usedDiskThresholdLow, "%"), + () -> Strings.format1Decimals(usedDiskPercentage, "%"), + () -> node.nodeId() + ); return allocation.decision( Decision.YES, NAME, @@ -381,15 +369,13 @@ public Decision canAllocate(ShardRouting shardRouting, RoutingNode node, Routing } else { // Even though the primary has never been allocated, the node is // above the high watermark, so don't allow allocating the shard - if (logger.isDebugEnabled()) { - logger.debug( - "less than the required {} free bytes threshold ({} bytes free) on node {}, " - + "preventing allocation even though primary has never been allocated", - Strings.format1Decimals(diskThresholdSettings.getFreeDiskThresholdHigh(), "%"), - Strings.format1Decimals(freeDiskPercentage, "%"), - node.nodeId() - ); - } + logger.debug( + "less than the required {} free bytes threshold ({} bytes free) on node {}, " + + "preventing allocation even though primary has never been allocated", + () -> Strings.format1Decimals(diskThresholdSettings.getFreeDiskThresholdHigh(), "%"), + () -> Strings.format1Decimals(freeDiskPercentage, "%"), + () -> node.nodeId() + ); return allocation.decision( Decision.NO, NAME, @@ -497,9 +483,7 @@ public Decision canRemain(ShardRouting shardRouting, RoutingNode node, RoutingAl // If this node is already above the high threshold, the shard cannot remain (get it off!) final double freeDiskPercentage = usage.getFreeDiskAsPercentage(); final long freeBytes = usage.getFreeBytes(); - if (logger.isTraceEnabled()) { - logger.trace("node [{}] has {}% free disk ({} bytes)", node.nodeId(), freeDiskPercentage, freeBytes); - } + logger.trace("node [{}] has {}% free disk ({} bytes)", () -> node.nodeId(), () -> freeDiskPercentage, () -> freeBytes); if (dataPath == null || usage.getPath().equals(dataPath) == false) { return allocation.decision(Decision.YES, NAME, "this shard is not allocated on the most utilized disk and can remain"); } @@ -529,14 +513,12 @@ public Decision canRemain(ShardRouting shardRouting, RoutingNode node, RoutingAl ); } if (freeBytes < diskThresholdSettings.getFreeBytesThresholdHigh().getBytes()) { - if (logger.isDebugEnabled()) { - logger.debug( - "less than the required {} free bytes threshold ({} bytes free) on node {}, shard cannot remain", - diskThresholdSettings.getFreeBytesThresholdHigh(), - freeBytes, - node.nodeId() - ); - } + logger.debug( + "less than the required {} free bytes threshold ({} bytes free) on node {}, shard cannot remain", + () -> diskThresholdSettings.getFreeBytesThresholdHigh(), + () -> freeBytes, + () -> node.nodeId() + ); return allocation.decision( Decision.NO, NAME, @@ -549,14 +531,12 @@ public Decision canRemain(ShardRouting shardRouting, RoutingNode node, RoutingAl ); } if (freeDiskPercentage < diskThresholdSettings.getFreeDiskThresholdHigh()) { - if (logger.isDebugEnabled()) { - logger.debug( - "less than the required {}% free disk threshold ({}% free) on node {}, shard cannot remain", - diskThresholdSettings.getFreeDiskThresholdHigh(), - freeDiskPercentage, - node.nodeId() - ); - } + logger.debug( + "less than the required {}% free disk threshold ({}% free) on node {}, shard cannot remain", + () -> diskThresholdSettings.getFreeDiskThresholdHigh(), + () -> freeDiskPercentage, + () -> node.nodeId() + ); return allocation.decision( Decision.NO, NAME, @@ -588,15 +568,14 @@ private DiskUsageWithRelocations getDiskUsage( // If there is no usage, and we have other nodes in the cluster, // use the average usage for all nodes as the usage for this node usage = averageUsage(node, usages); - if (logger.isDebugEnabled()) { - logger.debug( - "unable to determine disk usage for {}, defaulting to average across nodes [{} total] [{} free] [{}% free]", - node.nodeId(), - usage.getTotalBytes(), - usage.getFreeBytes(), - usage.getFreeDiskAsPercentage() - ); - } + final DiskUsage averageUsage = usage; + logger.debug( + "unable to determine disk usage for {}, defaulting to average across nodes [{} total] [{} free] [{}% free]", + () -> node.nodeId(), + () -> averageUsage.getTotalBytes(), + () -> averageUsage.getFreeBytes(), + () -> averageUsage.getFreeDiskAsPercentage() + ); } final DiskUsageWithRelocations diskUsageWithRelocations = new DiskUsageWithRelocations( @@ -612,9 +591,7 @@ private DiskUsageWithRelocations getDiskUsage( ) : 0 ); - if (logger.isTraceEnabled()) { - logger.trace("getDiskUsage(subtractLeavingShards={}) returning {}", subtractLeavingShards, diskUsageWithRelocations); - } + logger.trace("getDiskUsage(subtractLeavingShards={}) returning {}", () -> subtractLeavingShards, () -> diskUsageWithRelocations); return diskUsageWithRelocations; } @@ -666,26 +643,20 @@ private Decision earlyTerminate(RoutingAllocation allocation, final Map "only a single data node is present, allowing allocation"); return allocation.decision(Decision.YES, NAME, "there is only a single data node present"); } // Fail open there is no info available final ClusterInfo clusterInfo = allocation.clusterInfo(); if (clusterInfo == null) { - if (logger.isTraceEnabled()) { - logger.trace("cluster info unavailable for disk threshold decider, allowing allocation."); - } + logger.trace(() -> "cluster info unavailable for disk threshold decider, allowing allocation."); return allocation.decision(Decision.YES, NAME, "the cluster info is unavailable"); } // Fail open if there are no disk usages available if (usages.isEmpty()) { - if (logger.isTraceEnabled()) { - logger.trace("unable to determine disk usages for disk-aware allocation, allowing allocation"); - } + logger.trace(() -> "unable to determine disk usages for disk-aware allocation, allowing allocation"); return allocation.decision(Decision.YES, NAME, "disk usages are unavailable"); } return null; diff --git a/server/src/main/java/org/opensearch/cluster/routing/allocation/decider/SnapshotInProgressAllocationDecider.java b/server/src/main/java/org/opensearch/cluster/routing/allocation/decider/SnapshotInProgressAllocationDecider.java index c55365c43d23a..0df1ae441c3ce 100644 --- a/server/src/main/java/org/opensearch/cluster/routing/allocation/decider/SnapshotInProgressAllocationDecider.java +++ b/server/src/main/java/org/opensearch/cluster/routing/allocation/decider/SnapshotInProgressAllocationDecider.java @@ -86,13 +86,11 @@ private Decision canMove(ShardRouting shardRouting, RoutingAllocation allocation && !shardSnapshotStatus.state().completed() && shardSnapshotStatus.nodeId() != null && shardSnapshotStatus.nodeId().equals(shardRouting.currentNodeId())) { - if (logger.isTraceEnabled()) { - logger.trace( - "Preventing snapshotted shard [{}] from being moved away from node [{}]", - shardRouting.shardId(), - shardSnapshotStatus.nodeId() - ); - } + logger.trace( + "Preventing snapshotted shard [{}] from being moved away from node [{}]", + () -> shardRouting.shardId(), + () -> shardSnapshotStatus.nodeId() + ); return allocation.decision( Decision.THROTTLE, NAME, diff --git a/server/src/main/java/org/opensearch/common/Rounding.java b/server/src/main/java/org/opensearch/common/Rounding.java index 6f5f1e4328758..89188ba3d2791 100644 --- a/server/src/main/java/org/opensearch/common/Rounding.java +++ b/server/src/main/java/org/opensearch/common/Rounding.java @@ -1234,8 +1234,14 @@ public long nextRoundingValue(long utcMillis) { } assert highEnough && (false == tooHigh); assert roundedRoundedDown == prevRound; - if (iterations > 3 && logger.isDebugEnabled()) { - logger.debug("Iterated {} time for {} using {}", iterations, utcMillis, TimeIntervalRounding.this.toString()); + if (iterations > 3) { + final int currentIterations = iterations; + logger.debug( + "Iterated {} time for {} using {}", + () -> currentIterations, + () -> utcMillis, + () -> TimeIntervalRounding.this.toString() + ); } return rounded; } diff --git a/server/src/main/java/org/opensearch/common/breaker/ChildMemoryCircuitBreaker.java b/server/src/main/java/org/opensearch/common/breaker/ChildMemoryCircuitBreaker.java index c9b498c3ec6fa..f4f6b6d3b164f 100644 --- a/server/src/main/java/org/opensearch/common/breaker/ChildMemoryCircuitBreaker.java +++ b/server/src/main/java/org/opensearch/common/breaker/ChildMemoryCircuitBreaker.java @@ -170,19 +170,18 @@ private long limit(long bytes, String label, double overheadConstant, long memor currentUsed = this.used.get(); newUsed = currentUsed + bytes; long newUsedWithOverhead = (long) (newUsed * overheadConstant); - if (logger.isTraceEnabled()) { - logger.trace( - "[{}] Adding [{}][{}] to used bytes [new used: [{}], limit: {} [{}], estimate: {} [{}]]", - this.name, - new ByteSizeValue(bytes), - label, - new ByteSizeValue(newUsed), - memoryBytesLimit, - new ByteSizeValue(memoryBytesLimit), - newUsedWithOverhead, - new ByteSizeValue(newUsedWithOverhead) - ); - } + final long finalNewUsed = newUsed; + logger.trace( + "[{}] Adding [{}][{}] to used bytes [new used: [{}], limit: {} [{}], estimate: {} [{}]]", + () -> this.name, + () -> new ByteSizeValue(bytes), + () -> label, + () -> new ByteSizeValue(finalNewUsed), + () -> memoryBytesLimit, + () -> new ByteSizeValue(memoryBytesLimit), + () -> newUsedWithOverhead, + () -> new ByteSizeValue(newUsedWithOverhead) + ); if (memoryBytesLimit > 0 && newUsedWithOverhead > memoryBytesLimit) { logger.warn( "[{}] New used memory {} [{}] for data of [{}] would be larger than configured breaker: {} [{}], breaking", diff --git a/server/src/main/java/org/opensearch/common/settings/Setting.java b/server/src/main/java/org/opensearch/common/settings/Setting.java index fea4c165809ba..d734413aae114 100644 --- a/server/src/main/java/org/opensearch/common/settings/Setting.java +++ b/server/src/main/java/org/opensearch/common/settings/Setting.java @@ -2435,12 +2435,15 @@ public void diff(Settings.Builder builder, Settings source, Settings defaultSett } static void logSettingUpdate(Setting setting, Settings current, Settings previous, Logger logger) { - if (logger.isInfoEnabled()) { - if (setting.isFiltered()) { - logger.info("updating [{}]", setting.key); - } else { - logger.info("updating [{}] from [{}] to [{}]", setting.key, setting.getRaw(previous), setting.getRaw(current)); - } + if (setting.isFiltered()) { + logger.info("updating [{}]", () -> setting.key); + } else { + logger.info( + "updating [{}] from [{}] to [{}]", + () -> setting.key, + () -> setting.getRaw(previous), + () -> setting.getRaw(current) + ); } } diff --git a/server/src/main/java/org/opensearch/common/util/concurrent/AbstractAsyncTask.java b/server/src/main/java/org/opensearch/common/util/concurrent/AbstractAsyncTask.java index 7c599476e263d..ec7450b1294cf 100644 --- a/server/src/main/java/org/opensearch/common/util/concurrent/AbstractAsyncTask.java +++ b/server/src/main/java/org/opensearch/common/util/concurrent/AbstractAsyncTask.java @@ -103,9 +103,7 @@ public synchronized void rescheduleIfNecessary() { cancellable.cancel(); } if (interval.millis() > 0 && mustReschedule()) { - if (logger.isTraceEnabled()) { - logger.trace("scheduling {} every {}", toString(), interval); - } + logger.trace("scheduling {} every {}", () -> toString(), () -> interval); cancellable = threadPool.schedule(this, interval, getThreadPool()); isScheduledOrRunning = true; } else { diff --git a/server/src/main/java/org/opensearch/common/util/concurrent/QueueResizingOpenSearchThreadPoolExecutor.java b/server/src/main/java/org/opensearch/common/util/concurrent/QueueResizingOpenSearchThreadPoolExecutor.java index 0c0b437e4f390..b0fdb0f5c405a 100644 --- a/server/src/main/java/org/opensearch/common/util/concurrent/QueueResizingOpenSearchThreadPoolExecutor.java +++ b/server/src/main/java/org/opensearch/common/util/concurrent/QueueResizingOpenSearchThreadPoolExecutor.java @@ -210,33 +210,30 @@ protected void afterExecute(Runnable r, Throwable t) { final int desiredQueueSize = calculateL(lambda, targetedResponseTimeNanos); final int oldCapacity = workQueue.capacity(); - if (logger.isDebugEnabled()) { - final long avgTaskTime = totalNanos / tasksPerFrame; - logger.debug( - "[{}]: there were [{}] tasks in [{}], avg task time [{}], EWMA task execution [{}], " - + "[{} tasks/s], optimal queue is [{}], current capacity [{}]", - getName(), - tasksPerFrame, - TimeValue.timeValueNanos(totalRuntime), - TimeValue.timeValueNanos(avgTaskTime), - TimeValue.timeValueNanos((long) executionEWMA.getAverage()), - String.format(Locale.ROOT, "%.2f", lambda * TimeValue.timeValueSeconds(1).nanos()), - desiredQueueSize, - oldCapacity - ); - } + logger.debug( + "[{}]: there were [{}] tasks in [{}], avg task time [{}], EWMA task execution [{}], " + + "[{} tasks/s], optimal queue is [{}], current capacity [{}]", + () -> getName(), + () -> tasksPerFrame, + () -> TimeValue.timeValueNanos(totalRuntime), + () -> TimeValue.timeValueNanos(totalNanos / tasksPerFrame), + () -> TimeValue.timeValueNanos((long) executionEWMA.getAverage()), + () -> String.format(Locale.ROOT, "%.2f", lambda * TimeValue.timeValueSeconds(1).nanos()), + () -> desiredQueueSize, + () -> oldCapacity + ); // Adjust the queue size towards the desired capacity using an adjust of // QUEUE_ADJUSTMENT_AMOUNT (either up or down), keeping in mind the min and max // values the queue size can have. final int newCapacity = workQueue.adjustCapacity(desiredQueueSize, QUEUE_ADJUSTMENT_AMOUNT, minQueueSize, maxQueueSize); - if (oldCapacity != newCapacity && logger.isDebugEnabled()) { + if (oldCapacity != newCapacity) { logger.debug( "adjusted [{}] queue size by [{}], old capacity: [{}], new capacity: [{}]", - getName(), - newCapacity > oldCapacity ? QUEUE_ADJUSTMENT_AMOUNT : -QUEUE_ADJUSTMENT_AMOUNT, - oldCapacity, - newCapacity + () -> getName(), + () -> newCapacity > oldCapacity ? QUEUE_ADJUSTMENT_AMOUNT : -QUEUE_ADJUSTMENT_AMOUNT, + () -> oldCapacity, + () -> newCapacity ); } } catch (ArithmeticException e) { diff --git a/server/src/main/java/org/opensearch/env/NodeEnvironment.java b/server/src/main/java/org/opensearch/env/NodeEnvironment.java index 2748938d8b761..8b39ef45f06a2 100644 --- a/server/src/main/java/org/opensearch/env/NodeEnvironment.java +++ b/server/src/main/java/org/opensearch/env/NodeEnvironment.java @@ -365,9 +365,7 @@ public NodeEnvironment(Settings settings, Environment environment, IndexStoreLis this.nodeLockId = nodeLock.nodeId; - if (logger.isDebugEnabled()) { - logger.debug("using node location [{}], local_lock_id [{}]", nodePaths, nodeLockId); - } + logger.debug("using node location [{}], local_lock_id [{}]", () -> nodePaths, () -> nodeLockId); maybeLogPathDetails(); maybeLogHeapDetails(); diff --git a/server/src/main/java/org/opensearch/gateway/PrimaryShardAllocator.java b/server/src/main/java/org/opensearch/gateway/PrimaryShardAllocator.java index f41545cbdf9bf..918b2235e2992 100644 --- a/server/src/main/java/org/opensearch/gateway/PrimaryShardAllocator.java +++ b/server/src/main/java/org/opensearch/gateway/PrimaryShardAllocator.java @@ -433,13 +433,11 @@ protected static NodeShardsResult buildNodeShardsResult( nodeShardStates.sort(createActiveShardComparator(matchAnyShard, inSyncAllocationIds)); - if (logger.isTraceEnabled()) { - logger.trace( - "{} candidates for allocation: {}", - shard, - nodeShardStates.stream().map(s -> s.getNode().getName()).collect(Collectors.joining(", ")) - ); - } + logger.trace( + "{} candidates for allocation: {}", + () -> shard, + () -> nodeShardStates.stream().map(s -> s.getNode().getName()).collect(Collectors.joining(", ")) + ); return new NodeShardsResult(nodeShardStates, numberOfAllocationsFound); } diff --git a/server/src/main/java/org/opensearch/gateway/ReplicaShardAllocator.java b/server/src/main/java/org/opensearch/gateway/ReplicaShardAllocator.java index d9474b32bdbf6..1de412625ed8e 100644 --- a/server/src/main/java/org/opensearch/gateway/ReplicaShardAllocator.java +++ b/server/src/main/java/org/opensearch/gateway/ReplicaShardAllocator.java @@ -447,23 +447,24 @@ private MatchingNodes findMatchingNodes( matchingNode = computeMatchingNode(primaryNode, primaryStore, discoNode, storeFilesMetadata); } matchingNodes.put(discoNode, matchingNode); - if (logger.isTraceEnabled()) { - if (matchingNode.isNoopRecovery) { - logger.trace("{}: node [{}] can perform a noop recovery", shard, discoNode.getName()); - } else if (matchingNode.retainingSeqNo >= 0) { + if (matchingNode.isNoopRecovery) { + logger.trace("{}: node [{}] can perform a noop recovery", () -> shard, () -> discoNode.getName()); + } else { + final MatchingNode finalMatchingNode = matchingNode; + if (matchingNode.retainingSeqNo >= 0) { logger.trace( "{}: node [{}] can perform operation-based recovery with retaining sequence number [{}]", - shard, - discoNode.getName(), - matchingNode.retainingSeqNo + () -> shard, + () -> discoNode.getName(), + () -> finalMatchingNode.retainingSeqNo ); } else { logger.trace( "{}: node [{}] has [{}/{}] bytes of re-usable data", - shard, - discoNode.getName(), - new ByteSizeValue(matchingNode.matchingBytes), - matchingNode.matchingBytes + () -> shard, + () -> discoNode.getName(), + () -> new ByteSizeValue(finalMatchingNode.matchingBytes), + () -> finalMatchingNode.matchingBytes ); } } diff --git a/server/src/main/java/org/opensearch/http/AbstractHttpServerTransport.java b/server/src/main/java/org/opensearch/http/AbstractHttpServerTransport.java index 991fbf12072be..ece9eb5782f8b 100644 --- a/server/src/main/java/org/opensearch/http/AbstractHttpServerTransport.java +++ b/server/src/main/java/org/opensearch/http/AbstractHttpServerTransport.java @@ -218,9 +218,7 @@ private TransportAddress bindAddress(final InetAddress hostAddress) { throw new BindHttpException("Failed to bind to " + NetworkAddress.format(hostAddress, port), lastException.get()); } - if (logger.isDebugEnabled()) { - logger.debug("Bound http to address {{}}", NetworkAddress.format(boundSocket.get())); - } + logger.debug("Bound http to address {{}}", () -> NetworkAddress.format(boundSocket.get())); return new TransportAddress(boundSocket.get()); } diff --git a/server/src/main/java/org/opensearch/http/HttpTracer.java b/server/src/main/java/org/opensearch/http/HttpTracer.java index de1da4a20e294..c2c7cb4a50ff1 100644 --- a/server/src/main/java/org/opensearch/http/HttpTracer.java +++ b/server/src/main/java/org/opensearch/http/HttpTracer.java @@ -79,9 +79,9 @@ class HttpTracer { */ @Nullable HttpTracer maybeTraceRequest(RestRequest restRequest, @Nullable Exception e) { - if (logger.isTraceEnabled() && TransportService.shouldTraceAction(restRequest.uri(), tracerLogInclude, tracerLogExclude)) { + if (TransportService.shouldTraceAction(restRequest.uri(), tracerLogInclude, tracerLogExclude)) { logger.trace( - new ParameterizedMessage( + () -> new ParameterizedMessage( "[{}][{}][{}][{}] received request from [{}]", restRequest.getRequestId(), restRequest.header(Task.X_OPAQUE_ID), diff --git a/server/src/main/java/org/opensearch/identity/tokens/RestTokenExtractor.java b/server/src/main/java/org/opensearch/identity/tokens/RestTokenExtractor.java index 4bd3ebdded588..5638464cedf18 100644 --- a/server/src/main/java/org/opensearch/identity/tokens/RestTokenExtractor.java +++ b/server/src/main/java/org/opensearch/identity/tokens/RestTokenExtractor.java @@ -43,10 +43,10 @@ public static AuthToken extractToken(final RestRequest request) { if (authHeaderValueStr.startsWith(BasicAuthToken.TOKEN_IDENTIFIER)) { return new BasicAuthToken(authHeaderValueStr); } else { - if (logger.isDebugEnabled()) { - String tokenTypeTruncated = Strings.substring(authHeaderValueStr, 0, 5); - logger.debug("An authentication header was detected but the token type was not supported " + tokenTypeTruncated); - } + logger.debug( + "An authentication header was detected but the token type was not supported {}", + () -> Strings.substring(authHeaderValueStr, 0, 5) + ); } } diff --git a/server/src/main/java/org/opensearch/index/IndexSettings.java b/server/src/main/java/org/opensearch/index/IndexSettings.java index 96458ecc49ddc..d3c55b9ae3a59 100644 --- a/server/src/main/java/org/opensearch/index/IndexSettings.java +++ b/server/src/main/java/org/opensearch/index/IndexSettings.java @@ -1691,9 +1691,8 @@ public MergePolicy getMergePolicy(boolean isTimeSeriesIndex) { } assert mergePolicyProvider != null : "should not happen as validation for invalid merge policy values " + "are part of setting definition"; - if (logger.isTraceEnabled()) { - logger.trace("Index: " + this.index.getName() + ", Merge policy used: " + mergePolicyProvider); - } + final MergePolicyProvider finalMergePolicyProvider = mergePolicyProvider; + logger.trace("Index: {}, Merge policy used: {}", () -> this.index.getName(), () -> finalMergePolicyProvider); return mergePolicyProvider.getMergePolicy(); } diff --git a/server/src/main/java/org/opensearch/index/IndexWarmer.java b/server/src/main/java/org/opensearch/index/IndexWarmer.java index 81063cb9b9c38..10c155c93bc44 100644 --- a/server/src/main/java/org/opensearch/index/IndexWarmer.java +++ b/server/src/main/java/org/opensearch/index/IndexWarmer.java @@ -82,9 +82,7 @@ void warm(OpenSearchDirectoryReader reader, IndexShard shard, IndexSettings sett if (settings.isWarmerEnabled() == false) { return; } - if (logger.isTraceEnabled()) { - logger.trace("{} top warming [{}]", shard.shardId(), reader); - } + logger.trace("{} top warming [{}]", () -> shard.shardId(), () -> reader); shard.warmerService().onPreWarm(); long time = System.nanoTime(); final List terminationHandles = new ArrayList<>(); @@ -104,9 +102,7 @@ void warm(OpenSearchDirectoryReader reader, IndexShard shard, IndexSettings sett } long took = System.nanoTime() - time; shard.warmerService().onPostWarm(took); - if (shard.warmerService().logger().isTraceEnabled()) { - shard.warmerService().logger().trace("top warming took [{}]", new TimeValue(took, TimeUnit.NANOSECONDS)); - } + shard.warmerService().logger().trace("top warming took [{}]", () -> new TimeValue(took, TimeUnit.NANOSECONDS)); } /** @@ -178,15 +174,13 @@ public TerminationHandle warmReader(final IndexShard indexShard, final OpenSearc global.load(reader.leaves().get(0)); } - if (indexShard.warmerService().logger().isTraceEnabled()) { - indexShard.warmerService() - .logger() - .trace( - "warmed global ordinals for [{}], took [{}]", - fieldType.name(), - TimeValue.timeValueNanos(System.nanoTime() - start) - ); - } + indexShard.warmerService() + .logger() + .trace( + "warmed global ordinals for [{}], took [{}]", + () -> fieldType.name(), + () -> TimeValue.timeValueNanos(System.nanoTime() - start) + ); } catch (Exception e) { indexShard.warmerService() .logger() diff --git a/server/src/main/java/org/opensearch/index/cache/bitset/BitsetFilterCache.java b/server/src/main/java/org/opensearch/index/cache/bitset/BitsetFilterCache.java index 88d20bca7b6d4..9d8f74a081f61 100644 --- a/server/src/main/java/org/opensearch/index/cache/bitset/BitsetFilterCache.java +++ b/server/src/main/java/org/opensearch/index/cache/bitset/BitsetFilterCache.java @@ -294,15 +294,13 @@ public IndexWarmer.TerminationHandle warmReader(final IndexShard indexShard, fin try { final long start = System.nanoTime(); getAndLoadIfNotPresent(filterToWarm, ctx); - if (indexShard.warmerService().logger().isTraceEnabled()) { - indexShard.warmerService() - .logger() - .trace( - "warmed bitset for [{}], took [{}]", - filterToWarm, - TimeValue.timeValueNanos(System.nanoTime() - start) - ); - } + indexShard.warmerService() + .logger() + .trace( + "warmed bitset for [{}], took [{}]", + () -> filterToWarm, + () -> TimeValue.timeValueNanos(System.nanoTime() - start) + ); } catch (Exception e) { indexShard.warmerService() .logger() diff --git a/server/src/main/java/org/opensearch/index/engine/OpenSearchConcurrentMergeScheduler.java b/server/src/main/java/org/opensearch/index/engine/OpenSearchConcurrentMergeScheduler.java index c57c0090c180b..c4b1a17c80a95 100644 --- a/server/src/main/java/org/opensearch/index/engine/OpenSearchConcurrentMergeScheduler.java +++ b/server/src/main/java/org/opensearch/index/engine/OpenSearchConcurrentMergeScheduler.java @@ -105,16 +105,14 @@ protected void doMerge(MergeSource mergeSource, MergePolicy.OneMerge merge) thro OnGoingMerge onGoingMerge = new OnGoingMerge(merge); onGoingMerges.add(onGoingMerge); - if (logger.isTraceEnabled()) { - logger.trace( - "merge [{}] starting..., merging [{}] segments, [{}] docs, [{}] size, into [{}] estimated_size", - OneMergeHelper.getSegmentName(merge), - merge.segments.size(), - totalNumDocs, - new ByteSizeValue(totalSizeInBytes), - new ByteSizeValue(merge.estimatedMergeBytes) - ); - } + logger.trace( + "merge [{}] starting..., merging [{}] segments, [{}] docs, [{}] size, into [{}] estimated_size", + () -> OneMergeHelper.getSegmentName(merge), + () -> merge.segments.size(), + () -> totalNumDocs, + () -> new ByteSizeValue(totalSizeInBytes), + () -> new ByteSizeValue(merge.estimatedMergeBytes) + ); try { beforeMerge(onGoingMerge); super.doMerge(mergeSource, merge); @@ -159,8 +157,8 @@ protected void doMerge(MergeSource mergeSource, MergePolicy.OneMerge merge) thro if (tookMS > 20000) { // if more than 20 seconds, DEBUG log it logger.debug("{}", message); - } else if (logger.isTraceEnabled()) { - logger.trace("{}", message); + } else { + logger.trace("{}", () -> message); } } } diff --git a/server/src/main/java/org/opensearch/index/fielddata/ordinals/GlobalOrdinalsBuilder.java b/server/src/main/java/org/opensearch/index/fielddata/ordinals/GlobalOrdinalsBuilder.java index 06219b69266b5..18232cb011a9c 100644 --- a/server/src/main/java/org/opensearch/index/fielddata/ordinals/GlobalOrdinalsBuilder.java +++ b/server/src/main/java/org/opensearch/index/fielddata/ordinals/GlobalOrdinalsBuilder.java @@ -84,14 +84,12 @@ public static IndexOrdinalsFieldData build( final long memorySizeInBytes = ordinalMap.ramBytesUsed(); breakerService.getBreaker(CircuitBreaker.FIELDDATA).addWithoutBreaking(memorySizeInBytes); - if (logger.isDebugEnabled()) { - logger.debug( - "global-ordinals [{}][{}] took [{}]", - indexFieldData.getFieldName(), - ordinalMap.getValueCount(), - new TimeValue(System.nanoTime() - startTimeNS, TimeUnit.NANOSECONDS) - ); - } + logger.debug( + "global-ordinals [{}][{}] took [{}]", + () -> indexFieldData.getFieldName(), + () -> ordinalMap.getValueCount(), + () -> new TimeValue(System.nanoTime() - startTimeNS, TimeUnit.NANOSECONDS) + ); return new GlobalOrdinalsIndexFieldData( indexFieldData.getFieldName(), indexFieldData.getValuesSourceType(), diff --git a/server/src/main/java/org/opensearch/index/reindex/ClientScrollableHitSource.java b/server/src/main/java/org/opensearch/index/reindex/ClientScrollableHitSource.java index 55d018af46970..58ee0d92685bf 100644 --- a/server/src/main/java/org/opensearch/index/reindex/ClientScrollableHitSource.java +++ b/server/src/main/java/org/opensearch/index/reindex/ClientScrollableHitSource.java @@ -91,12 +91,10 @@ public ClientScrollableHitSource( @Override public void doStart(RejectAwareActionListener searchListener) { - if (logger.isDebugEnabled()) { - logger.debug( - "executing initial scroll against {}", - isEmpty(firstSearchRequest.indices()) ? "all indices" : firstSearchRequest.indices() - ); - } + logger.debug( + "executing initial scroll against {}", + () -> isEmpty(firstSearchRequest.indices()) ? "all indices" : firstSearchRequest.indices() + ); client.search(firstSearchRequest, wrapListener(searchListener)); } diff --git a/server/src/main/java/org/opensearch/index/shard/IndexShard.java b/server/src/main/java/org/opensearch/index/shard/IndexShard.java index 82b68b32f3bf8..3efb0094af9e3 100644 --- a/server/src/main/java/org/opensearch/index/shard/IndexShard.java +++ b/server/src/main/java/org/opensearch/index/shard/IndexShard.java @@ -1192,50 +1192,45 @@ private Engine.IndexResult index(Engine engine, Engine.Index index) throws IOExc active.set(true); final Engine.IndexResult result; index = indexingOperationListeners.preIndex(shardId, index); + final Engine.Index finalIndex = index; try { - if (logger.isTraceEnabled()) { - // don't use index.source().utf8ToString() here source might not be valid UTF-8 - logger.trace( - "index [{}] seq# [{}] allocation-id [{}] primaryTerm [{}] operationPrimaryTerm [{}] origin [{}]", - index.id(), - index.seqNo(), - routingEntry().allocationId(), - index.primaryTerm(), - getOperationPrimaryTerm(), - index.origin() - ); - } + // don't use index.source().utf8ToString() here source might not be valid UTF-8 + logger.trace( + "index [{}] seq# [{}] allocation-id [{}] primaryTerm [{}] operationPrimaryTerm [{}] origin [{}]", + () -> finalIndex.id(), + () -> finalIndex.seqNo(), + () -> routingEntry().allocationId(), + () -> finalIndex.primaryTerm(), + () -> getOperationPrimaryTerm(), + () -> finalIndex.origin() + ); result = engine.index(index); - if (logger.isTraceEnabled()) { - logger.trace( - "index-done [{}] seq# [{}] allocation-id [{}] primaryTerm [{}] operationPrimaryTerm [{}] origin [{}] " - + "result-seq# [{}] result-term [{}] failure [{}]", - index.id(), - index.seqNo(), + logger.trace( + "index-done [{}] seq# [{}] allocation-id [{}] primaryTerm [{}] operationPrimaryTerm [{}] origin [{}] " + + "result-seq# [{}] result-term [{}] failure [{}]", + () -> finalIndex.id(), + () -> finalIndex.seqNo(), + () -> routingEntry().allocationId(), + () -> finalIndex.primaryTerm(), + () -> getOperationPrimaryTerm(), + () -> finalIndex.origin(), + () -> result.getSeqNo(), + () -> result.getTerm(), + () -> result.getFailure() + ); + } catch (Exception e) { + logger.trace( + () -> new ParameterizedMessage( + "index-fail [{}] seq# [{}] allocation-id [{}] primaryTerm [{}] operationPrimaryTerm [{}] origin [{}]", + finalIndex.id(), + finalIndex.seqNo(), routingEntry().allocationId(), - index.primaryTerm(), + finalIndex.primaryTerm(), getOperationPrimaryTerm(), - index.origin(), - result.getSeqNo(), - result.getTerm(), - result.getFailure() - ); - } - } catch (Exception e) { - if (logger.isTraceEnabled()) { - logger.trace( - new ParameterizedMessage( - "index-fail [{}] seq# [{}] allocation-id [{}] primaryTerm [{}] operationPrimaryTerm [{}] origin [{}]", - index.id(), - index.seqNo(), - routingEntry().allocationId(), - index.primaryTerm(), - getOperationPrimaryTerm(), - index.origin() - ), - e - ); - } + finalIndex.origin() + ), + e + ); indexingOperationListeners.postIndex(shardId, index, e); throw e; } @@ -1262,9 +1257,7 @@ private Engine.NoOpResult markSeqNoAsNoop(Engine engine, long seqNo, long opPrim private Engine.NoOpResult noOp(Engine engine, Engine.NoOp noOp) throws IOException { active.set(true); - if (logger.isTraceEnabled()) { - logger.trace("noop (seq# [{}])", noOp.seqNo()); - } + logger.trace("noop (seq# [{}])", () -> noOp.seqNo()); return engine.noOp(noOp); } @@ -1367,9 +1360,8 @@ private Engine.DeleteResult delete(Engine engine, Engine.Delete delete) throws I final Engine.DeleteResult result; delete = indexingOperationListeners.preDelete(shardId, delete); try { - if (logger.isTraceEnabled()) { - logger.trace("delete [{}] (seq no [{}])", delete.uid().text(), delete.seqNo()); - } + final Engine.Delete finalDelete = delete; + logger.trace("delete [{}] (seq no [{}])", () -> finalDelete.uid().text(), () -> finalDelete.seqNo()); result = engine.delete(delete); } catch (Exception e) { indexingOperationListeners.postDelete(shardId, delete, e); @@ -1393,9 +1385,7 @@ public Engine.GetResult get(Engine.Get get) { */ public void refresh(String source) { verifyNotClosed(); - if (logger.isTraceEnabled()) { - logger.trace("refresh with source [{}]", source); - } + logger.trace("refresh with source [{}]", () -> source); getEngine().refresh(source); } @@ -1572,9 +1562,7 @@ public void rollTranslogGeneration() throws IOException { public void forceMerge(ForceMergeRequest forceMerge) throws IOException { verifyActive(); - if (logger.isTraceEnabled()) { - logger.trace("force merge with {}", forceMerge); - } + logger.trace("force merge with {}", () -> forceMerge); Engine engine = getEngine(); engine.forceMerge( forceMerge.flush(), @@ -1591,9 +1579,7 @@ public void forceMerge(ForceMergeRequest forceMerge) throws IOException { */ public org.apache.lucene.util.Version upgrade(UpgradeRequest upgrade) throws IOException { verifyActive(); - if (logger.isTraceEnabled()) { - logger.trace("upgrade with {}", upgrade); - } + logger.trace("upgrade with {}", () -> upgrade); org.apache.lucene.util.Version previousVersion = minimumCompatibleVersion(); // we just want to upgrade the segments, not actually forge merge to a single segment final Engine engine = getEngine(); @@ -1606,9 +1592,7 @@ public org.apache.lucene.util.Version upgrade(UpgradeRequest upgrade) throws IOE null ); org.apache.lucene.util.Version version = minimumCompatibleVersion(); - if (logger.isTraceEnabled()) { - logger.trace("upgraded segments for {} from version {} to version {}", shardId, previousVersion, version); - } + logger.trace("upgraded segments for {} from version {} to version {}", () -> shardId, () -> previousVersion, () -> version); return version; } @@ -3676,9 +3660,7 @@ private void doCheckIndex() throws IOException { } } - if (logger.isDebugEnabled()) { - logger.debug("check index [success]\n{}", os.bytes().utf8ToString()); - } + logger.debug("check index [success]\n{}", () -> os.bytes().utf8ToString()); } recoveryState.getVerifyIndex().checkIndexTime(Math.max(0, TimeValue.nsecToMSec(System.nanoTime() - timeNS))); @@ -4627,9 +4609,7 @@ && isSearchIdle() setRefreshPending(engine); return false; } else { - if (logger.isTraceEnabled()) { - logger.trace("refresh with source [schedule]"); - } + logger.trace(() -> "refresh with source [schedule]"); return getEngine().maybeRefresh("schedule"); } } diff --git a/server/src/main/java/org/opensearch/index/shard/StoreRecovery.java b/server/src/main/java/org/opensearch/index/shard/StoreRecovery.java index 8d689e8769728..04cf27e585aa4 100644 --- a/server/src/main/java/org/opensearch/index/shard/StoreRecovery.java +++ b/server/src/main/java/org/opensearch/index/shard/StoreRecovery.java @@ -500,8 +500,11 @@ private ActionListener recoveryListener(IndexShard indexShard, ActionLi timeValueMillis(recoveryState.getTimer().time()), sb ); - } else if (logger.isDebugEnabled()) { - logger.debug("recovery completed from [shard_store], took [{}]", timeValueMillis(recoveryState.getTimer().time())); + } else { + logger.debug( + "recovery completed from [shard_store], took [{}]", + () -> timeValueMillis(recoveryState.getTimer().time()) + ); } } listener.onResponse(res); @@ -698,9 +701,7 @@ private void restore( listener.onFailure(new IndexShardRestoreFailedException(shardId, "empty restore source")); return; } - if (logger.isTraceEnabled()) { - logger.trace("[{}] restoring shard [{}]", restoreSource.snapshot(), shardId); - } + logger.trace("[{}] restoring shard [{}]", () -> restoreSource.snapshot(), () -> shardId); final ActionListener restoreListener = ActionListener.wrap(v -> { final Store store = indexShard.store(); if (indexShard.indexSettings.isRemoteTranslogStoreEnabled() == false) { diff --git a/server/src/main/java/org/opensearch/indices/IndexingMemoryController.java b/server/src/main/java/org/opensearch/indices/IndexingMemoryController.java index 93b75218fd1c6..e194b85c11cb6 100644 --- a/server/src/main/java/org/opensearch/indices/IndexingMemoryController.java +++ b/server/src/main/java/org/opensearch/indices/IndexingMemoryController.java @@ -360,15 +360,15 @@ private void runUnlocked() { totalBytesUsed += shardBytesUsed; } - if (logger.isTraceEnabled()) { - logger.trace( - "total indexing heap bytes used [{}] vs {} [{}], currently writing bytes [{}]", - new ByteSizeValue(totalBytesUsed), - INDEX_BUFFER_SIZE_SETTING.getKey(), - indexingBuffer, - new ByteSizeValue(totalBytesWriting) - ); - } + final long finalTotalBytesUsed = totalBytesUsed; + final long finalTotalBytesWriting = totalBytesWriting; + logger.trace( + "total indexing heap bytes used [{}] vs {} [{}], currently writing bytes [{}]", + () -> new ByteSizeValue(finalTotalBytesUsed), + () -> INDEX_BUFFER_SIZE_SETTING.getKey(), + () -> indexingBuffer, + () -> new ByteSizeValue(finalTotalBytesWriting) + ); // If we are using more than 50% of our budget across both indexing buffer and bytes we are still moving to disk, then we now // throttle the top shards to send back-pressure to ongoing indexing: @@ -395,17 +395,20 @@ private void runUnlocked() { } if (shardBytesUsed > 0) { - if (logger.isTraceEnabled()) { - if (shardWritingBytes != 0) { - logger.trace( - "shard [{}] is using [{}] heap, writing [{}] heap", - shard.shardId(), - shardBytesUsed, - shardWritingBytes - ); - } else { - logger.trace("shard [{}] is using [{}] heap, not writing any bytes", shard.shardId(), shardBytesUsed); - } + final long finalShardBytesUsed = shardBytesUsed; + if (shardWritingBytes != 0) { + logger.trace( + "shard [{}] is using [{}] heap, writing [{}] heap", + () -> shard.shardId(), + () -> finalShardBytesUsed, + () -> shardWritingBytes + ); + } else { + logger.trace( + "shard [{}] is using [{}] heap, not writing any bytes", + () -> shard.shardId(), + () -> finalShardBytesUsed + ); } queue.add(new ShardAndBytesUsed(shardBytesUsed, shard)); } diff --git a/server/src/main/java/org/opensearch/indices/IndicesRequestCache.java b/server/src/main/java/org/opensearch/indices/IndicesRequestCache.java index 93946fa11de13..55a0db394ad59 100644 --- a/server/src/main/java/org/opensearch/indices/IndicesRequestCache.java +++ b/server/src/main/java/org/opensearch/indices/IndicesRequestCache.java @@ -524,13 +524,11 @@ class IndicesRequestCacheCleanupManager implements Closeable { void updateStalenessThreshold(double stalenessThreshold) { double oldStalenessThreshold = this.stalenessThreshold; this.stalenessThreshold = stalenessThreshold; - if (logger.isDebugEnabled()) { - logger.debug( - "Staleness threshold for indices request cache changed to {} from {}", - this.stalenessThreshold, - oldStalenessThreshold - ); - } + logger.debug( + "Staleness threshold for indices request cache changed to {} from {}", + () -> this.stalenessThreshold, + () -> oldStalenessThreshold + ); } /** @@ -713,9 +711,7 @@ private void forceCleanCache() { * @param stalenessThreshold The staleness threshold as a double. */ private synchronized void cleanCache(double stalenessThreshold) { - if (logger.isDebugEnabled()) { - logger.debug("Cleaning Indices Request Cache with threshold : " + stalenessThreshold); - } + logger.debug("Cleaning Indices Request Cache with threshold : {}", () -> stalenessThreshold); if (canSkipCacheCleanup(stalenessThreshold)) { return; } @@ -799,14 +795,11 @@ private synchronized boolean canSkipCacheCleanup(double cleanThresholdPercent) { } double staleKeysInCachePercentage = staleKeysInCachePercentage(); if (staleKeysInCachePercentage < cleanThresholdPercent) { - if (logger.isDebugEnabled()) { - logger.debug( - "Skipping Indices Request cache cleanup since the percentage of stale keys : " - + staleKeysInCachePercentage - + " is less than the threshold : " - + stalenessThreshold - ); - } + logger.debug( + "Skipping Indices Request cache cleanup since the percentage of stale keys : {} is less than the threshold : {}", + () -> staleKeysInCachePercentage, + () -> stalenessThreshold + ); return true; } return false; diff --git a/server/src/main/java/org/opensearch/indices/IndicesService.java b/server/src/main/java/org/opensearch/indices/IndicesService.java index 902ca95643625..095aa4d509e80 100644 --- a/server/src/main/java/org/opensearch/indices/IndicesService.java +++ b/server/src/main/java/org/opensearch/indices/IndicesService.java @@ -1683,20 +1683,16 @@ private static final class CacheCleaner implements Runnable, Releasable { @Override public void run() { long startTimeNS = System.nanoTime(); - if (logger.isTraceEnabled()) { - logger.trace("running periodic field data cache cleanup"); - } + logger.trace(() -> "running periodic field data cache cleanup"); try { this.cache.getCache().refresh(); } catch (Exception e) { logger.warn("Exception during periodic field data cache cleanup:", e); } - if (logger.isTraceEnabled()) { - logger.trace( - "periodic field data cache cleanup finished in {} milliseconds", - TimeValue.nsecToMSec(System.nanoTime() - startTimeNS) - ); - } + logger.trace( + "periodic field data cache cleanup finished in {} milliseconds", + () -> (TimeValue.nsecToMSec(System.nanoTime() - startTimeNS)) + ); // Reschedule itself to run again if not closed if (closed.get() == false) { threadPool.scheduleUnlessShuttingDown(interval, ThreadPool.Names.SAME, this); @@ -1794,13 +1790,11 @@ public void loadIntoContext(ShardSearchRequest request, SearchContext context, Q // running a search that times out concurrently will likely timeout again if it's run while we have this `stale` result in the // cache. One other option is to not cache requests with a timeout at all... indicesRequestCache.invalidate(new IndexShardCacheEntity(context.indexShard()), directoryReader, request.cacheKey()); - if (logger.isTraceEnabled()) { - logger.trace( - "Query timed out, invalidating cache entry for request on shard [{}]:\n {}", - request.shardId(), - request.source() - ); - } + logger.trace( + "Query timed out, invalidating cache entry for request on shard [{}]:\n {}", + () -> request.shardId(), + () -> request.source() + ); } } diff --git a/server/src/main/java/org/opensearch/indices/analysis/HunspellService.java b/server/src/main/java/org/opensearch/indices/analysis/HunspellService.java index 027cd502da1fb..5e390861a1580 100644 --- a/server/src/main/java/org/opensearch/indices/analysis/HunspellService.java +++ b/server/src/main/java/org/opensearch/indices/analysis/HunspellService.java @@ -188,9 +188,7 @@ private void scanAndLoadDictionaries() throws IOException { * @throws Exception when loading fails (due to IO errors or malformed dictionary files) */ private Dictionary loadDictionary(String locale, Settings nodeSettings, Environment env) throws Exception { - if (logger.isDebugEnabled()) { - logger.debug("Loading hunspell dictionary [{}]...", locale); - } + logger.debug("Loading hunspell dictionary [{}]...", () -> locale); Path dicDir = hunspellDir.resolve(locale); if (FileSystemUtils.isAccessibleDirectory(dicDir, logger) == false) { throw new OpenSearchException(String.format(Locale.ROOT, "Could not find hunspell dictionary [%s]", locale)); diff --git a/server/src/main/java/org/opensearch/indices/cluster/IndicesClusterStateService.java b/server/src/main/java/org/opensearch/indices/cluster/IndicesClusterStateService.java index 2c3ffcdd9e0ba..fb00e9bd8f6bf 100644 --- a/server/src/main/java/org/opensearch/indices/cluster/IndicesClusterStateService.java +++ b/server/src/main/java/org/opensearch/indices/cluster/IndicesClusterStateService.java @@ -342,9 +342,7 @@ private void deleteIndices(final ClusterChangedEvent event) { assert localNodeId != null; for (Index index : event.indicesDeleted()) { - if (logger.isDebugEnabled()) { - logger.debug("[{}] cleaning index, no longer part of the metadata", index); - } + logger.debug("[{}] cleaning index, no longer part of the metadata", () -> index); AllocatedIndex indexService = indicesService.indexService(index); final IndexSettings indexSettings; if (indexService != null) { @@ -728,14 +726,12 @@ private void updateShard( // the cluster-manager thinks we are initializing, but we are already started or on POST_RECOVERY and waiting // for cluster-manager to confirm a shard started message (either cluster-manager failover, or a cluster event before // we managed to tell the cluster-manager we started), mark us as started - if (logger.isTraceEnabled()) { - logger.trace( - "{} cluster-manager marked shard as initializing, but shard has state [{}], resending shard started to {}", - shardRouting.shardId(), - state, - nodes.getClusterManagerNode() - ); - } + logger.trace( + "{} cluster-manager marked shard as initializing, but shard has state [{}], resending shard started to {}", + () -> shardRouting.shardId(), + () -> state, + () -> nodes.getClusterManagerNode() + ); if (nodes.getClusterManagerNode() != null) { shardStateAction.shardStarted( shardRouting, diff --git a/server/src/main/java/org/opensearch/indices/recovery/PeerRecoveryTargetService.java b/server/src/main/java/org/opensearch/indices/recovery/PeerRecoveryTargetService.java index 6279a8ec3646c..43408fa09778f 100644 --- a/server/src/main/java/org/opensearch/indices/recovery/PeerRecoveryTargetService.java +++ b/server/src/main/java/org/opensearch/indices/recovery/PeerRecoveryTargetService.java @@ -643,41 +643,24 @@ public void handleResponse(RecoveryResponse recoveryResponse) { // do this through ongoing recoveries to remove it from the collection onGoingRecoveries.markAsDone(recoveryId); if (logger.isTraceEnabled()) { - StringBuilder sb = new StringBuilder(); - sb.append('[') - .append(request.shardId().getIndex().getName()) - .append(']') - .append('[') - .append(request.shardId().id()) - .append("] "); - sb.append("recovery completed from ").append(request.sourceNode()).append(", took[").append(recoveryTime).append("]\n"); - sb.append(" phase1: recovered_files [") - .append(recoveryResponse.phase1FileNames.size()) - .append("]") - .append(" with total_size of [") - .append(new ByteSizeValue(recoveryResponse.phase1TotalSize)) - .append("]") - .append(", took [") - .append(timeValueMillis(recoveryResponse.phase1Time)) - .append("], throttling_wait [") - .append(timeValueMillis(recoveryResponse.phase1ThrottlingWaitTime)) - .append(']') - .append("\n"); - sb.append(" : reusing_files [") - .append(recoveryResponse.phase1ExistingFileNames.size()) - .append("] with total_size of [") - .append(new ByteSizeValue(recoveryResponse.phase1ExistingTotalSize)) - .append("]\n"); - sb.append(" phase2: start took [").append(timeValueMillis(recoveryResponse.startTime)).append("]\n"); - sb.append(" : recovered [") - .append(recoveryResponse.phase2Operations) - .append("]") - .append(" transaction log operations") - .append(", took [") - .append(timeValueMillis(recoveryResponse.phase2Time)) - .append("]") - .append("\n"); - logger.trace("{}", sb); + logger.trace( + "[{}][{}] recovery completed from {}, took[{}]\n phase1: recovered_files [{}] with total_size of [{}]" + + ", took [{}], throttling_wait [{}]\n : reusing_files [{}] with total_size of [{}]\n phase2: start took [{}]\n" + + " : recovered [{}] transaction log operations, took [{}]\n", + () -> request.shardId().getIndex().getName(), + () -> request.shardId().id(), + () -> request.sourceNode(), + () -> recoveryTime, + () -> recoveryResponse.phase1FileNames.size(), + () -> new ByteSizeValue(recoveryResponse.phase1TotalSize), + () -> timeValueMillis(recoveryResponse.phase1Time), + () -> timeValueMillis(recoveryResponse.phase1ThrottlingWaitTime), + () -> recoveryResponse.phase1ExistingFileNames.size(), + () -> new ByteSizeValue(recoveryResponse.phase1ExistingTotalSize), + () -> timeValueMillis(recoveryResponse.startTime), + () -> recoveryResponse.phase2Operations, + () -> timeValueMillis(recoveryResponse.phase2Time) + ); } else { logger.debug("{} recovery done from [{}], took [{}]", request.shardId(), request.sourceNode(), recoveryTime); } @@ -689,16 +672,14 @@ public void handleException(TransportException e) { } private void onException(Exception e) { - if (logger.isTraceEnabled()) { - logger.trace( - () -> new ParameterizedMessage( - "[{}][{}] Got exception on recovery", - request.shardId().getIndex().getName(), - request.shardId().id() - ), - e - ); - } + logger.trace( + () -> new ParameterizedMessage( + "[{}][{}] Got exception on recovery", + request.shardId().getIndex().getName(), + request.shardId().id() + ), + e + ); Throwable cause = ExceptionsHelper.unwrapCause(e); if (cause instanceof CancellableThreads.ExecutionCancelledException) { // this can also come from the source wrapped in a RemoteTransportException diff --git a/server/src/main/java/org/opensearch/indices/recovery/RecoverySourceHandler.java b/server/src/main/java/org/opensearch/indices/recovery/RecoverySourceHandler.java index abf9b1aaeb2cc..c6e7c82d1229f 100644 --- a/server/src/main/java/org/opensearch/indices/recovery/RecoverySourceHandler.java +++ b/server/src/main/java/org/opensearch/indices/recovery/RecoverySourceHandler.java @@ -402,14 +402,12 @@ void phase1( phase1ExistingFileNames.add(md.name()); phase1ExistingFileSizes.add(md.length()); existingTotalSizeInBytes += md.length(); - if (logger.isTraceEnabled()) { - logger.trace( - "recovery [phase1]: not recovering [{}], exist in local store and has checksum [{}]," + " size [{}]", - md.name(), - md.checksum(), - md.length() - ); - } + logger.trace( + "recovery [phase1]: not recovering [{}], exist in local store and has checksum [{}]," + " size [{}]", + () -> md.name(), + () -> md.checksum(), + () -> md.length() + ); totalSizeInBytes += md.length(); } List phase1Files = new ArrayList<>(diff.different.size() + diff.missing.size()); diff --git a/server/src/main/java/org/opensearch/monitor/os/OsProbe.java b/server/src/main/java/org/opensearch/monitor/os/OsProbe.java index a0a14372aa31a..7813c40dbbeb5 100644 --- a/server/src/main/java/org/opensearch/monitor/os/OsProbe.java +++ b/server/src/main/java/org/opensearch/monitor/os/OsProbe.java @@ -202,9 +202,7 @@ final double[] getSystemLoadAverage() { final String[] fields = procLoadAvg.split("\\s+"); return new double[] { Double.parseDouble(fields[0]), Double.parseDouble(fields[1]), Double.parseDouble(fields[2]) }; } catch (final IOException e) { - if (logger.isDebugEnabled()) { - logger.debug("error reading /proc/loadavg", e); - } + logger.debug(() -> "error reading /proc/loadavg", e); return null; } } else { @@ -216,9 +214,7 @@ final double[] getSystemLoadAverage() { final double oneMinuteLoadAverage = (double) getSystemLoadAverage.invoke(osMxBean); return new double[] { oneMinuteLoadAverage >= 0 ? oneMinuteLoadAverage : -1, -1, -1 }; } catch (IllegalAccessException | InvocationTargetException e) { - if (logger.isDebugEnabled()) { - logger.debug("error reading one minute load average from operating system", e); - } + logger.debug(() -> "error reading one minute load average from operating system", e); return null; } } diff --git a/server/src/main/java/org/opensearch/node/Node.java b/server/src/main/java/org/opensearch/node/Node.java index 85ef547e27787..db656208761ae 100644 --- a/server/src/main/java/org/opensearch/node/Node.java +++ b/server/src/main/java/org/opensearch/node/Node.java @@ -487,15 +487,13 @@ protected Node( ); } - if (logger.isDebugEnabled()) { - logger.debug( - "using config [{}], data [{}], logs [{}], plugins [{}]", - initialEnvironment.configDir(), - Arrays.toString(initialEnvironment.dataFiles()), - initialEnvironment.logsDir(), - initialEnvironment.pluginsDir() - ); - } + logger.debug( + "using config [{}], data [{}], logs [{}], plugins [{}]", + () -> initialEnvironment.configDir(), + () -> Arrays.toString(initialEnvironment.dataFiles()), + () -> initialEnvironment.logsDir(), + () -> initialEnvironment.pluginsDir() + ); this.pluginsService = new PluginsService( tmpSettings, diff --git a/server/src/main/java/org/opensearch/plugins/PluginsService.java b/server/src/main/java/org/opensearch/plugins/PluginsService.java index f08c9c738f1b4..e388e344c769e 100644 --- a/server/src/main/java/org/opensearch/plugins/PluginsService.java +++ b/server/src/main/java/org/opensearch/plugins/PluginsService.java @@ -153,9 +153,7 @@ public PluginsService( Collections.emptyList(), false ); - if (logger.isTraceEnabled()) { - logger.trace("plugin loaded from classpath [{}]", pluginInfo); - } + logger.trace("plugin loaded from classpath [{}]", () -> pluginInfo); pluginsLoaded.add(new Tuple<>(pluginInfo, plugin)); pluginsList.add(pluginInfo); pluginsNames.add(pluginInfo.getName()); diff --git a/server/src/main/java/org/opensearch/repositories/blobstore/FileRestoreContext.java b/server/src/main/java/org/opensearch/repositories/blobstore/FileRestoreContext.java index 7e6e3a0ad3b79..9b429a3a1893a 100644 --- a/server/src/main/java/org/opensearch/repositories/blobstore/FileRestoreContext.java +++ b/server/src/main/java/org/opensearch/repositories/blobstore/FileRestoreContext.java @@ -135,24 +135,26 @@ public void restore(SnapshotFiles snapshotFiles, Store store, ActionListener shardId, + () -> snapshotId, + () -> fileInfo.physicalName(), + () -> fileInfo.name() + ); } for (StoreFileMetadata md : concat(diff)) { BlobStoreIndexShardSnapshot.FileInfo fileInfo = fileInfos.get(md.name()); filesToRecover.add(fileInfo); recoveryState.getIndex().addFileDetail(fileInfo.physicalName(), fileInfo.length(), false); - if (logger.isTraceEnabled()) { - logger.trace("[{}] [{}] recovering [{}] from [{}]", shardId, snapshotId, fileInfo.physicalName(), fileInfo.name()); - } + logger.trace( + "[{}] [{}] recovering [{}] from [{}]", + () -> shardId, + () -> snapshotId, + () -> fileInfo.physicalName(), + () -> fileInfo.name() + ); } recoveryState.getIndex().setFileDetailsComplete(); diff --git a/server/src/main/java/org/opensearch/script/ScriptCache.java b/server/src/main/java/org/opensearch/script/ScriptCache.java index fb57e7cdfa5bd..d5f3bd199a90c 100644 --- a/server/src/main/java/org/opensearch/script/ScriptCache.java +++ b/server/src/main/java/org/opensearch/script/ScriptCache.java @@ -111,15 +111,13 @@ FactoryType compile( // If the script type is inline the name will be the same as the code for identification in exceptions // but give the script engine the chance to be better, give it separate name + source code // for the inline case, then its anonymous: null. - if (logger.isTraceEnabled()) { - logger.trace( - "context [{}]: compiling script, type: [{}], lang: [{}], options: [{}]", - context.name, - type, - lang, - options - ); - } + logger.trace( + "context [{}]: compiling script, type: [{}], lang: [{}], options: [{}]", + () -> context.name, + () -> type, + () -> lang, + () -> options + ); // Check whether too many compilations have happened checkCompilationLimit(); Object compiledScript = scriptEngine.compile(id, idOrCode, context, options); @@ -211,9 +209,7 @@ void checkCompilationLimit() { private class ScriptCacheRemovalListener implements RemovalListener { @Override public void onRemoval(RemovalNotification notification) { - if (logger.isDebugEnabled()) { - logger.debug("removed [{}] from cache, reason: [{}]", notification.getValue(), notification.getRemovalReason()); - } + logger.debug("removed [{}] from cache, reason: [{}]", () -> notification.getValue(), () -> notification.getRemovalReason()); scriptMetrics.onCacheEviction(); } } diff --git a/server/src/main/java/org/opensearch/script/ScriptService.java b/server/src/main/java/org/opensearch/script/ScriptService.java index d3c8861dbc5d7..4013cdb6a8b2a 100644 --- a/server/src/main/java/org/opensearch/script/ScriptService.java +++ b/server/src/main/java/org/opensearch/script/ScriptService.java @@ -442,7 +442,7 @@ public FactoryType compile(Script script, ScriptContext options = script.getOptions(); @@ -458,6 +458,8 @@ public FactoryType compile(Script script, ScriptContext FactoryType compile(Script script, ScriptContext lang, () -> type, () -> finalIdOrCode); ScriptCache scriptCache = cacheHolder.get().get(context.name); assert scriptCache != null : "script context [" + context.name + "] has no script cache"; diff --git a/server/src/main/java/org/opensearch/search/fetch/FetchPhase.java b/server/src/main/java/org/opensearch/search/fetch/FetchPhase.java index 1698f41caaf2b..1eb91661ba701 100644 --- a/server/src/main/java/org/opensearch/search/fetch/FetchPhase.java +++ b/server/src/main/java/org/opensearch/search/fetch/FetchPhase.java @@ -107,9 +107,7 @@ public FetchPhase(List fetchSubPhases) { } public void execute(SearchContext context) { - if (LOGGER.isTraceEnabled()) { - LOGGER.trace("{}", new SearchContextSourcePrinter(context)); - } + LOGGER.trace("{}", () -> new SearchContextSourcePrinter(context)); if (context.isCancelled()) { throw new TaskCancelledException("cancelled task with reason: " + context.getTask().getReasonCancelled()); diff --git a/server/src/main/java/org/opensearch/search/query/QueryPhase.java b/server/src/main/java/org/opensearch/search/query/QueryPhase.java index 55b7c0bc5178d..9229d3436bdb1 100644 --- a/server/src/main/java/org/opensearch/search/query/QueryPhase.java +++ b/server/src/main/java/org/opensearch/search/query/QueryPhase.java @@ -143,9 +143,7 @@ public void execute(SearchContext searchContext) throws QueryPhaseExecutionExcep return; } - if (LOGGER.isTraceEnabled()) { - LOGGER.trace("{}", new SearchContextSourcePrinter(searchContext)); - } + LOGGER.trace("{}", () -> new SearchContextSourcePrinter(searchContext)); final AggregationProcessor aggregationProcessor = queryPhaseSearcher.aggregationProcessor(searchContext); // Pre-process aggregations as late as possible. In the case of a DFS_Q_T_F diff --git a/server/src/main/java/org/opensearch/snapshots/SnapshotShardsService.java b/server/src/main/java/org/opensearch/snapshots/SnapshotShardsService.java index 8da36bbb8d4bd..59509f08198db 100644 --- a/server/src/main/java/org/opensearch/snapshots/SnapshotShardsService.java +++ b/server/src/main/java/org/opensearch/snapshots/SnapshotShardsService.java @@ -289,16 +289,13 @@ private void startNewShards(SnapshotsInProgress.Entry entry, Map snapshot, + () -> snapshot.getRepository(), + () -> snapshotStatus.asCopy(), + () -> snapshotStatus.generation() + ); notifySuccessfulSnapshotShard(snapshot, shardId, newGeneration); } diff --git a/server/src/main/java/org/opensearch/tasks/TaskManager.java b/server/src/main/java/org/opensearch/tasks/TaskManager.java index a49968ab85e89..6d4b97d1a09e4 100644 --- a/server/src/main/java/org/opensearch/tasks/TaskManager.java +++ b/server/src/main/java/org/opensearch/tasks/TaskManager.java @@ -206,9 +206,7 @@ public Task register(String type, String action, TaskAwareRequest request) { Task task = request.createTask(taskIdGenerator.incrementAndGet(), type, action, request.getParentTask(), headers); Objects.requireNonNull(task); assert task.getParentTaskId().equals(request.getParentTask()) : "Request [ " + request + "] didn't preserve it parentTaskId"; - if (logger.isTraceEnabled()) { - logger.trace("register {} [{}] [{}] [{}]", task.getId(), type, action, task.getDescription()); - } + logger.trace("register {} [{}] [{}] [{}]", () -> task.getId(), () -> type, () -> action, () -> task.getDescription()); if (task.supportsResourceTracking()) { boolean success = task.addResourceTrackingCompletionListener(new NotifyOnceListener<>() { diff --git a/server/src/main/java/org/opensearch/threadpool/ThreadPool.java b/server/src/main/java/org/opensearch/threadpool/ThreadPool.java index 056ef0fac0153..73bc629e0a7c8 100644 --- a/server/src/main/java/org/opensearch/threadpool/ThreadPool.java +++ b/server/src/main/java/org/opensearch/threadpool/ThreadPool.java @@ -503,9 +503,7 @@ public void scheduleUnlessShuttingDown(TimeValue delay, String executor, Runnabl @Override public Cancellable scheduleWithFixedDelay(Runnable command, TimeValue interval, String executor) { return new ReschedulingRunnable(command, interval, executor, this, (e) -> { - if (logger.isDebugEnabled()) { - logger.debug(() -> new ParameterizedMessage("scheduled task [{}] was rejected on thread pool [{}]", command, executor), e); - } + logger.debug(() -> new ParameterizedMessage("scheduled task [{}] was rejected on thread pool [{}]", command, executor), e); }, (e) -> logger.warn( () -> new ParameterizedMessage("failed to run scheduled task [{}] on thread pool [{}]", command, executor), diff --git a/server/src/main/java/org/opensearch/transport/TcpTransport.java b/server/src/main/java/org/opensearch/transport/TcpTransport.java index ffa3168da0b3e..d9a9b68e7c933 100644 --- a/server/src/main/java/org/opensearch/transport/TcpTransport.java +++ b/server/src/main/java/org/opensearch/transport/TcpTransport.java @@ -436,13 +436,13 @@ protected void bindServer(ProfileSettings profileSettings) { } catch (IOException e) { throw new BindTransportException("Failed to resolve host " + profileBindHosts, e); } - if (logger.isDebugEnabled()) { + logger.debug("binding server bootstrap to: {}", () -> { String[] addresses = new String[hostAddresses.length]; for (int i = 0; i < hostAddresses.length; i++) { addresses[i] = NetworkAddress.format(hostAddresses[i]); } - logger.debug("binding server bootstrap to: {}", (Object) addresses); - } + return (Object) addresses; + }); assert hostAddresses.length > 0; @@ -490,9 +490,7 @@ private InetSocketAddress bindToPort(final String name, final InetAddress hostAd } finally { closeLock.writeLock().unlock(); } - if (logger.isDebugEnabled()) { - logger.debug("Bound profile [{}] to address {{}}", name, NetworkAddress.format(boundSocket.get())); - } + logger.debug("Bound profile [{}] to address {{}}", () -> name, () -> NetworkAddress.format(boundSocket.get())); return boundSocket.get(); } diff --git a/server/src/main/java/org/opensearch/transport/TransportLogger.java b/server/src/main/java/org/opensearch/transport/TransportLogger.java index e780f643aafd7..eb7b333927c0b 100644 --- a/server/src/main/java/org/opensearch/transport/TransportLogger.java +++ b/server/src/main/java/org/opensearch/transport/TransportLogger.java @@ -55,41 +55,41 @@ public final class TransportLogger { private static final int HEADER_SIZE = TcpHeader.MARKER_BYTES_SIZE + TcpHeader.MESSAGE_LENGTH_SIZE; static void logInboundMessage(TcpChannel channel, BytesReference message) { - if (logger.isTraceEnabled()) { + logger.trace(() -> { try { - String logMessage = format(channel, message, "READ"); - logger.trace(logMessage); + return format(channel, message, "READ"); } catch (IOException e) { logger.warn("an exception occurred formatting a READ trace message", e); + return ""; } - } + }); } static void logInboundMessage(TcpChannel channel, NativeInboundMessage message) { - if (logger.isTraceEnabled()) { + logger.trace(() -> { try { - String logMessage = format(channel, message, "READ"); - logger.trace(logMessage); + return format(channel, message, "READ"); } catch (IOException e) { logger.warn("an exception occurred formatting a READ trace message", e); + return ""; } - } + }); } static void logOutboundMessage(TcpChannel channel, BytesReference message) { - if (logger.isTraceEnabled()) { + if (message.get(0) != 'E') { + // This is not an OpenSearch transport message. + return; + } + logger.trace(() -> { try { - if (message.get(0) != 'E') { - // This is not an OpenSearch transport message. - return; - } BytesReference withoutHeader = message.slice(HEADER_SIZE, message.length() - HEADER_SIZE); - String logMessage = format(channel, withoutHeader, "WRITE"); - logger.trace(logMessage); + return format(channel, withoutHeader, "WRITE"); } catch (IOException e) { logger.warn("an exception occurred formatting a WRITE trace message", e); + return ""; } - } + }); } private static String format(TcpChannel channel, BytesReference message, String event) throws IOException { diff --git a/server/src/main/java/org/opensearch/transport/TransportService.java b/server/src/main/java/org/opensearch/transport/TransportService.java index d08b28730d417..132dd43397149 100644 --- a/server/src/main/java/org/opensearch/transport/TransportService.java +++ b/server/src/main/java/org/opensearch/transport/TransportService.java @@ -304,10 +304,10 @@ protected void doStart() { transport.setMessageListener(this); connectionManager.addListener(this); transport.start(); - if (transport.boundAddress() != null && logger.isInfoEnabled()) { - logger.info("{}", transport.boundAddress()); + if (transport.boundAddress() != null) { + logger.info("{}", () -> transport.boundAddress()); for (Map.Entry entry : transport.profileBoundAddresses().entrySet()) { - logger.info("profile [{}]: {}", entry.getKey(), entry.getValue()); + logger.info("profile [{}]: {}", () -> entry.getKey(), () -> entry.getValue()); } } localNode = localNodeFactory.apply(transport.boundAddress()); @@ -1240,8 +1240,8 @@ public void onRequestReceived(long requestId, String action) { if (handleIncomingRequests.get() == false) { throw new IllegalStateException("transport not ready yet to handle incoming requests"); } - if (tracerLog.isTraceEnabled() && shouldTraceAction(action)) { - tracerLog.trace("[{}][{}] received request", requestId, action); + if (shouldTraceAction(action)) { + tracerLog.trace("[{}][{}] received request", () -> requestId, () -> action); } messageListener.onRequestReceived(requestId, action); } @@ -1255,8 +1255,8 @@ public void onRequestSent( TransportRequest request, TransportRequestOptions options ) { - if (tracerLog.isTraceEnabled() && shouldTraceAction(action)) { - tracerLog.trace("[{}][{}] sent to [{}] (timeout: [{}])", requestId, action, node, options.timeout()); + if (shouldTraceAction(action)) { + tracerLog.trace("[{}][{}] sent to [{}] (timeout: [{}])", () -> requestId, () -> action, () -> node, () -> options.timeout()); } messageListener.onRequestSent(node, requestId, action, request, options); } @@ -1265,8 +1265,13 @@ public void onRequestSent( public void onResponseReceived(long requestId, Transport.ResponseContext holder) { if (holder == null) { checkForTimeout(requestId); - } else if (tracerLog.isTraceEnabled() && shouldTraceAction(holder.action())) { - tracerLog.trace("[{}][{}] received response from [{}]", requestId, holder.action(), holder.connection().getNode()); + } else if (shouldTraceAction(holder.action())) { + tracerLog.trace( + "[{}][{}] received response from [{}]", + () -> requestId, + () -> holder.action(), + () -> holder.connection().getNode() + ); } messageListener.onResponseReceived(requestId, holder); } @@ -1274,8 +1279,8 @@ public void onResponseReceived(long requestId, Transport.ResponseContext holder) /** called by the {@link Transport} implementation once a response was sent to calling node */ @Override public void onResponseSent(long requestId, String action, TransportResponse response) { - if (tracerLog.isTraceEnabled() && shouldTraceAction(action)) { - tracerLog.trace("[{}][{}] sent response", requestId, action); + if (shouldTraceAction(action)) { + tracerLog.trace("[{}][{}] sent response", () -> requestId, () -> action); } messageListener.onResponseSent(requestId, action, response); } @@ -1283,7 +1288,7 @@ public void onResponseSent(long requestId, String action, TransportResponse resp /** called by the {@link Transport} implementation after an exception was sent as a response to an incoming request */ @Override public void onResponseSent(long requestId, String action, Exception e) { - if (tracerLog.isTraceEnabled() && shouldTraceAction(action)) { + if (shouldTraceAction(action)) { tracerLog.trace(() -> new ParameterizedMessage("[{}][{}] sent error response", requestId, action), e); } messageListener.onResponseSent(requestId, action, e); @@ -1318,14 +1323,11 @@ private void checkForTimeout(long requestId) { sourceNode = null; } // call tracer out of lock - if (tracerLog.isTraceEnabled() == false) { - return; - } if (action == null) { assert sourceNode == null; - tracerLog.trace("[{}] received response but can't resolve it to a request", requestId); + tracerLog.trace("[{}] received response but can't resolve it to a request", () -> requestId); } else if (shouldTraceAction(action)) { - tracerLog.trace("[{}][{}] received response from [{}]", requestId, action, sourceNode); + tracerLog.trace("[{}][{}] received response from [{}]", () -> requestId, () -> action, () -> sourceNode); } } diff --git a/test/framework/src/main/java/org/opensearch/test/OpenSearchIntegTestCase.java b/test/framework/src/main/java/org/opensearch/test/OpenSearchIntegTestCase.java index ca5ddf21710af..33782dbdcc267 100644 --- a/test/framework/src/main/java/org/opensearch/test/OpenSearchIntegTestCase.java +++ b/test/framework/src/main/java/org/opensearch/test/OpenSearchIntegTestCase.java @@ -1022,12 +1022,11 @@ public void waitForDocs(final long numDocs, final BackgroundIndexer indexer) thr } } - if (logger.isDebugEnabled()) { - if (lastKnownCount < numDocs) { - logger.debug("[{}] docs indexed. waiting for [{}]", lastKnownCount, numDocs); - } else { - logger.debug("[{}] docs visible for search (needed [{}])", lastKnownCount, numDocs); - } + final long finalLastKnownCount = lastKnownCount; + if (lastKnownCount < numDocs) { + logger.debug("[{}] docs indexed. waiting for [{}]", () -> finalLastKnownCount, () -> numDocs); + } else { + logger.debug("[{}] docs visible for search (needed [{}])", () -> finalLastKnownCount, () -> numDocs); } assertThat(lastKnownCount, greaterThanOrEqualTo(numDocs)); diff --git a/test/framework/src/main/java/org/opensearch/test/engine/MockEngineSupport.java b/test/framework/src/main/java/org/opensearch/test/engine/MockEngineSupport.java index 86e92a3deef75..f9d6dea41f852 100644 --- a/test/framework/src/main/java/org/opensearch/test/engine/MockEngineSupport.java +++ b/test/framework/src/main/java/org/opensearch/test/engine/MockEngineSupport.java @@ -113,9 +113,13 @@ public MockEngineSupport(EngineConfig config, Class this.getClass().getName(), + () -> shardId, + () -> seed, + () -> wrapReader + ); mockContext = new MockContext(random, wrapReader, wrapper, settings); this.inFlightSearchers = new InFlightSearchers(); LuceneTestCase.closeAfterSuite(inFlightSearchers); // only one suite closeable per Engine diff --git a/test/framework/src/main/java/org/opensearch/test/store/MockFSDirectoryFactory.java b/test/framework/src/main/java/org/opensearch/test/store/MockFSDirectoryFactory.java index 9c42ea2672601..aeb3ef59c7921 100644 --- a/test/framework/src/main/java/org/opensearch/test/store/MockFSDirectoryFactory.java +++ b/test/framework/src/main/java/org/opensearch/test/store/MockFSDirectoryFactory.java @@ -128,9 +128,7 @@ public static void checkIndex(Logger logger, Store store, ShardId shardId) { OpenSearchTestCase.checkIndexFailures.add(failure); throw failure; } else { - if (logger.isDebugEnabled()) { - logger.debug("check index [success]\n{}", os.bytes().utf8ToString()); - } + logger.debug("check index [success]\n{}", () -> os.bytes().utf8ToString()); } } catch (LockObtainFailedException e) { IllegalStateException failure = new IllegalStateException("IndexWriter is still open on shard " + shardId, e);