From 6b17e731fde02de8c793868a949456b632860f2e Mon Sep 17 00:00:00 2001 From: Nhat Nguyen Date: Wed, 29 Apr 2020 09:40:35 -0400 Subject: [PATCH 1/2] Add trace log for task cancellation --- .../cancel/TransportCancelTasksAction.java | 25 ++++++++++++------- .../org/elasticsearch/tasks/TaskManager.java | 6 ++++- .../node/tasks/CancellableTasksIT.java | 4 +++ 3 files changed, 25 insertions(+), 10 deletions(-) diff --git a/server/src/main/java/org/elasticsearch/action/admin/cluster/node/tasks/cancel/TransportCancelTasksAction.java b/server/src/main/java/org/elasticsearch/action/admin/cluster/node/tasks/cancel/TransportCancelTasksAction.java index 61af76cbd0173..d26bafd047854 100644 --- a/server/src/main/java/org/elasticsearch/action/admin/cluster/node/tasks/cancel/TransportCancelTasksAction.java +++ b/server/src/main/java/org/elasticsearch/action/admin/cluster/node/tasks/cancel/TransportCancelTasksAction.java @@ -113,13 +113,19 @@ protected void taskOperation(CancelTasksRequest request, CancellableTask cancell } void cancelTaskAndDescendants(CancellableTask task, String reason, boolean waitForCompletion, ActionListener listener) { + final TaskId taskId = task.taskInfo(clusterService.localNode().getId(), false).getTaskId(); if (task.shouldCancelChildrenOnCancellation()) { + logger.trace("cancelling task [{}] and its descendants", taskId); StepListener completedListener = new StepListener<>(); GroupedActionListener groupedListener = new GroupedActionListener<>(ActionListener.map(completedListener, r -> null), 3); - Collection childrenNodes = - taskManager.startBanOnChildrenNodes(task.getId(), () -> groupedListener.onResponse(null)); - taskManager.cancel(task, reason, () -> groupedListener.onResponse(null)); - + Collection childrenNodes = taskManager.startBanOnChildrenNodes(task.getId(), () -> { + logger.trace("child tasks of parent [{}] are completed", taskId); + groupedListener.onResponse(null); + }); + taskManager.cancel(task, reason, () -> { + logger.trace("task [{}] is cancelled", taskId); + groupedListener.onResponse(null); + }); StepListener banOnNodesListener = new StepListener<>(); setBanOnNodes(reason, waitForCompletion, task, childrenNodes, banOnNodesListener); banOnNodesListener.whenComplete(groupedListener::onResponse, groupedListener::onFailure); @@ -137,7 +143,7 @@ void cancelTaskAndDescendants(CancellableTask task, String reason, boolean waitF banOnNodesListener.whenComplete(r -> listener.onResponse(null), listener::onFailure); } } else { - logger.trace("task {} doesn't have any children that should be cancelled", task.getId()); + logger.trace("task [{}] doesn't have any children that should be cancelled", taskId); if (waitForCompletion) { taskManager.cancel(task, reason, () -> listener.onResponse(null)); } else { @@ -153,23 +159,24 @@ private void setBanOnNodes(String reason, boolean waitForCompletion, Cancellable listener.onResponse(null); return; } - logger.trace("cancelling task {} on child nodes {}", task.getId(), childNodes); + final TaskId taskId = new TaskId(clusterService.localNode().getId(), task.getId()); + logger.trace("cancelling child tasks of [{}] on child nodes {}", taskId, childNodes); GroupedActionListener groupedListener = new GroupedActionListener<>(ActionListener.map(listener, r -> null), childNodes.size()); - final BanParentTaskRequest banRequest = BanParentTaskRequest.createSetBanParentTaskRequest( - new TaskId(clusterService.localNode().getId(), task.getId()), reason, waitForCompletion); + final BanParentTaskRequest banRequest = BanParentTaskRequest.createSetBanParentTaskRequest(taskId, reason, waitForCompletion); for (DiscoveryNode node : childNodes) { transportService.sendRequest(node, BAN_PARENT_ACTION_NAME, banRequest, new EmptyTransportResponseHandler(ThreadPool.Names.SAME) { @Override public void handleResponse(TransportResponse.Empty response) { + logger.warn("sent ban for tasks with the parent [{}] to the node [{}]", taskId, node); groupedListener.onResponse(null); } @Override public void handleException(TransportException exp) { assert ExceptionsHelper.unwrapCause(exp) instanceof ElasticsearchSecurityException == false; - logger.warn("Cannot send ban for tasks with the parent [{}] to the node [{}]", banRequest.parentTaskId, node); + logger.warn("Cannot send ban for tasks with the parent [{}] to the node [{}]", taskId, node); groupedListener.onFailure(exp); } }); diff --git a/server/src/main/java/org/elasticsearch/tasks/TaskManager.java b/server/src/main/java/org/elasticsearch/tasks/TaskManager.java index 17f51816bbb2a..e2df210798f12 100644 --- a/server/src/main/java/org/elasticsearch/tasks/TaskManager.java +++ b/server/src/main/java/org/elasticsearch/tasks/TaskManager.java @@ -234,8 +234,12 @@ public Task unregister(Task task) { public Releasable registerChildNode(long taskId, DiscoveryNode node) { final CancellableTaskHolder holder = cancellableTasks.get(taskId); if (holder != null) { + logger.trace("register child node [{}] task [{}]", node, taskId); holder.registerChildNode(node); - return Releasables.releaseOnce(() -> holder.unregisterChildNode(node)); + return Releasables.releaseOnce(() -> { + logger.trace("unregister child node [{}] task [{}]", node, taskId); + holder.unregisterChildNode(node); + }); } return () -> {}; } diff --git a/server/src/test/java/org/elasticsearch/action/admin/cluster/node/tasks/CancellableTasksIT.java b/server/src/test/java/org/elasticsearch/action/admin/cluster/node/tasks/CancellableTasksIT.java index e6062a113a6cb..946c51d355857 100644 --- a/server/src/test/java/org/elasticsearch/action/admin/cluster/node/tasks/CancellableTasksIT.java +++ b/server/src/test/java/org/elasticsearch/action/admin/cluster/node/tasks/CancellableTasksIT.java @@ -52,6 +52,7 @@ import org.elasticsearch.tasks.TaskInfo; import org.elasticsearch.tasks.TaskManager; import org.elasticsearch.test.ESIntegTestCase; +import org.elasticsearch.test.junit.annotations.TestIssueLogging; import org.elasticsearch.threadpool.ThreadPool; import org.elasticsearch.transport.TransportException; import org.elasticsearch.transport.TransportResponseHandler; @@ -79,6 +80,9 @@ import static org.hamcrest.Matchers.hasSize; import static org.hamcrest.Matchers.instanceOf; +@TestIssueLogging( + value = "org.elasticsearch.action.admin.cluster.node.tasks.cancel:TRACE,org.elasticsearch.tasks:TRACE", + issueUrl = "https://github.com/elastic/elasticsearch/issues/55875") public class CancellableTasksIT extends ESIntegTestCase { static int idGenerator = 0; From 1fb7256e84612d7b4673520f46d4f36928c8bb28 Mon Sep 17 00:00:00 2001 From: Nhat Nguyen Date: Wed, 29 Apr 2020 10:10:49 -0400 Subject: [PATCH 2/2] -> trace --- .../cluster/node/tasks/cancel/TransportCancelTasksAction.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/server/src/main/java/org/elasticsearch/action/admin/cluster/node/tasks/cancel/TransportCancelTasksAction.java b/server/src/main/java/org/elasticsearch/action/admin/cluster/node/tasks/cancel/TransportCancelTasksAction.java index d26bafd047854..c95c4df9b4078 100644 --- a/server/src/main/java/org/elasticsearch/action/admin/cluster/node/tasks/cancel/TransportCancelTasksAction.java +++ b/server/src/main/java/org/elasticsearch/action/admin/cluster/node/tasks/cancel/TransportCancelTasksAction.java @@ -169,7 +169,7 @@ private void setBanOnNodes(String reason, boolean waitForCompletion, Cancellable new EmptyTransportResponseHandler(ThreadPool.Names.SAME) { @Override public void handleResponse(TransportResponse.Empty response) { - logger.warn("sent ban for tasks with the parent [{}] to the node [{}]", taskId, node); + logger.trace("sent ban for tasks with the parent [{}] to the node [{}]", taskId, node); groupedListener.onResponse(null); }