This is an automated email from the ASF dual-hosted git repository. mblow pushed a commit to branch master in repository https://gitbox.apache.org/repos/asf/asterixdb.git
commit 6449b31b47f52864dfde43388980db2260828441 Author: Ali Alsuliman <[email protected]> AuthorDate: Sun Jun 9 05:29:08 2024 +0300 [NO ISSUE][OTH] Reduce/tune logs - user model changes: no - storage format changes: no - interface changes: no Details: - When logging handleException, log only request uuid and client context id instead of the whole request parameters since it is already logged before in handleRequest. - Make RegisterResultPartitionLocation message TRACE. RegisterResultPartitionLocation is logged per query per partition. ReportResultPartitionWriteCompletion message is already logged and can cover for RegisterResultPartitionLocation. - Remove ResultDirectoryService job notification. This is already covered in JobManager/JobExecutor. It will reduce per query logs. - Don't log spurious tasks message if job is aborted/failed. Change-Id: I117dd35a05664e6bc48bd3476e8813bbfcbaeb54 Reviewed-on: https://asterix-gerrit.ics.uci.edu/c/asterixdb/+/18356 Reviewed-by: Murtadha Hubail <[email protected]> Tested-by: Jenkins <[email protected]> --- .../org/apache/asterix/active/ActiveManager.java | 2 -- .../http/server/QueryServiceRequestParameters.java | 9 +++++++++ .../api/http/server/QueryServiceServlet.java | 21 ++++++++++++++++----- .../org/apache/asterix/app/nc/RecoveryManager.java | 3 --- .../hyracks/control/cc/executor/JobExecutor.java | 6 +++++- .../control/cc/result/ResultDirectoryService.java | 1 - .../work/RegisterResultPartitionLocationWork.java | 5 +++++ 7 files changed, 35 insertions(+), 12 deletions(-) diff --git a/asterixdb/asterix-active/src/main/java/org/apache/asterix/active/ActiveManager.java b/asterixdb/asterix-active/src/main/java/org/apache/asterix/active/ActiveManager.java index ed481bc666..a75ee33979 100644 --- a/asterixdb/asterix-active/src/main/java/org/apache/asterix/active/ActiveManager.java +++ b/asterixdb/asterix-active/src/main/java/org/apache/asterix/active/ActiveManager.java @@ -140,8 +140,6 @@ public class ActiveManager { IActiveRuntime runtime = runtimes.get(runtimeId); long reqId = message.getReqId(); if (runtime == null) { - LOGGER.warn("Request stats of a runtime that is not registered {}; sending failure response", - runtimeId); // Send a failure message ((NodeControllerService) serviceCtx.getControllerService()).sendApplicationMessageToCC( message.getCcId(), diff --git a/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryServiceRequestParameters.java b/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryServiceRequestParameters.java index 20d79d5e7e..563f49864f 100644 --- a/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryServiceRequestParameters.java +++ b/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryServiceRequestParameters.java @@ -127,6 +127,7 @@ public class QueryServiceRequestParameters { private String path; private String statement; private String clientContextID; + private String requestId; private String dataverse; private String source; private ClientType clientType = ClientType.ASTERIX; @@ -389,6 +390,14 @@ public class QueryServiceRequestParameters { return maxWarnings; } + public void setRequestId(String requestId) { + this.requestId = requestId; + } + + public String getRequestId() { + return requestId; + } + public ObjectNode asJson() { ObjectNode object = OBJECT_MAPPER.createObjectNode(); object.put("host", host); diff --git a/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryServiceServlet.java b/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryServiceServlet.java index 9a8c0d5b23..8de7582a79 100644 --- a/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryServiceServlet.java +++ b/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryServiceServlet.java @@ -90,6 +90,7 @@ import org.apache.hyracks.control.common.controllers.CCConfig; import org.apache.hyracks.http.api.IServletRequest; import org.apache.hyracks.http.api.IServletResponse; import org.apache.hyracks.http.server.utils.HttpUtil; +import org.apache.logging.log4j.Level; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; @@ -269,6 +270,7 @@ public class QueryServiceServlet extends AbstractQueryApiServlet { ResponsePrinter responsePrinter = new ResponsePrinter(sessionOutput); ResultDelivery delivery = ResultDelivery.IMMEDIATE; QueryServiceRequestParameters param = newQueryRequestParameters(); + param.setRequestId(requestRef.getUuid()); RequestExecutionState executionState = newRequestExecutionState(); try { // buffer the output until we are ready to set the status of the response message correctly @@ -431,12 +433,13 @@ public class QueryServiceServlet extends AbstractQueryApiServlet { executionState.setStatus(ResultStatus.FATAL, HttpResponseStatus.BAD_REQUEST); return true; case REQUEST_TIMEOUT: - LOGGER.info(() -> "handleException: request execution timed out: " + param.toString()); + logException(Level.INFO, "request execution timed out", param.getRequestId(), + param.getClientContextID()); executionState.setStatus(ResultStatus.TIMEOUT, HttpResponseStatus.OK); return true; case REJECT_NODE_UNREGISTERED: case REJECT_BAD_CLUSTER_STATE: - LOGGER.warn(() -> "handleException: " + ex.getMessage() + ": " + param.toString()); + logException(Level.WARN, ex.getMessage(), param.getRequestId(), param.getClientContextID()); executionState.setStatus(ResultStatus.FATAL, HttpResponseStatus.SERVICE_UNAVAILABLE); return true; default: @@ -456,9 +459,9 @@ public class QueryServiceServlet extends AbstractQueryApiServlet { QueryServiceRequestParameters param, IServletResponse response) { if (t instanceof org.apache.asterix.lang.sqlpp.parser.TokenMgrError || t instanceof AlgebricksException) { if (LOGGER.isDebugEnabled()) { - LOGGER.debug("handleException: {}: {}", t.getMessage(), param.toString(), t); + logException(Level.DEBUG, t.getMessage(), param.getRequestId(), param.getClientContextID(), t); } else { - LOGGER.info(() -> "handleException: " + t.getMessage() + ": " + param.toString()); + logException(Level.INFO, t.getMessage(), param.getRequestId(), param.getClientContextID()); } executionState.setStatus(ResultStatus.FATAL, HttpResponseStatus.BAD_REQUEST); return; @@ -470,7 +473,7 @@ public class QueryServiceServlet extends AbstractQueryApiServlet { return; } } - LOGGER.warn(() -> "handleException: unexpected exception: " + param.toString(), t); + logException(Level.WARN, "unexpected exception", param.getRequestId(), param.getClientContextID(), t); executionState.setStatus(ResultStatus.FATAL, HttpResponseStatus.INTERNAL_SERVER_ERROR); } @@ -542,4 +545,12 @@ public class QueryServiceServlet extends AbstractQueryApiServlet { protected String getApplicationVersion() { return ApplicationConfigurator.getApplicationVersion(appCtx.getBuildProperties()); } + + private void logException(Level lvl, String msg, String clientCtxId, String uuid) { + LOGGER.log(lvl, "handleException: {}: uuid={}, clientContextID={}", msg, uuid, clientCtxId); + } + + private void logException(Level lvl, String msg, String clientCtxId, String uuid, Throwable t) { + LOGGER.log(lvl, "handleException: {}: uuid={}, clientContextID={}", msg, uuid, clientCtxId, t); + } } diff --git a/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/nc/RecoveryManager.java b/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/nc/RecoveryManager.java index 2ca3fbc4ff..4bc4d62c4c 100644 --- a/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/nc/RecoveryManager.java +++ b/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/nc/RecoveryManager.java @@ -615,9 +615,6 @@ public class RecoveryManager implements IRecoveryManager, ILifeCycleComponent { boolean infoEnabled = LOGGER.isInfoEnabled(); // check if the transaction actually wrote some logs. if (firstLSN == TransactionManagementConstants.LogManagerConstants.TERMINAL_LSN || firstLSN > lastLSN) { - if (infoEnabled) { - LOGGER.info("no need to rollback as there were no operations by " + txnContext.getTxnId()); - } return; } if (infoEnabled) { diff --git a/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-cc/src/main/java/org/apache/hyracks/control/cc/executor/JobExecutor.java b/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-cc/src/main/java/org/apache/hyracks/control/cc/executor/JobExecutor.java index 98918508f4..64f900ea22 100644 --- a/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-cc/src/main/java/org/apache/hyracks/control/cc/executor/JobExecutor.java +++ b/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-cc/src/main/java/org/apache/hyracks/control/cc/executor/JobExecutor.java @@ -654,7 +654,11 @@ public class JobExecutor { } TaskAttempt.TaskStatus taStatus = ta.getStatus(); if (taStatus != TaskAttempt.TaskStatus.RUNNING) { - LOGGER.warn(() -> "Spurious task complete notification: " + taId + " Current state = " + taStatus); + // don't log if aborted/failed because a task could complete just before the job was aborted/failed + if (taStatus != TaskAttempt.TaskStatus.ABORTED && taStatus != TaskAttempt.TaskStatus.FAILED) { + LOGGER.warn("spurious task complete notification {}:{}. current state {}", jobRun.getJobId(), taId, + taStatus); + } return; } ta.setStatus(TaskAttempt.TaskStatus.COMPLETED, null); diff --git a/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-cc/src/main/java/org/apache/hyracks/control/cc/result/ResultDirectoryService.java b/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-cc/src/main/java/org/apache/hyracks/control/cc/result/ResultDirectoryService.java index 46dd3512af..80d7630524 100644 --- a/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-cc/src/main/java/org/apache/hyracks/control/cc/result/ResultDirectoryService.java +++ b/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-cc/src/main/java/org/apache/hyracks/control/cc/result/ResultDirectoryService.java @@ -78,7 +78,6 @@ public class ResultDirectoryService extends AbstractResultManager implements IRe @Override public synchronized void notifyJobCreation(JobId jobId, JobSpecification spec) throws HyracksException { - LOGGER.debug("{} notified of new job {}", getClass().getSimpleName(), jobId); if (jobResultLocations.get(jobId) != null) { throw HyracksDataException.create(ErrorCode.MORE_THAN_ONE_RESULT, jobId); } diff --git a/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-cc/src/main/java/org/apache/hyracks/control/cc/work/RegisterResultPartitionLocationWork.java b/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-cc/src/main/java/org/apache/hyracks/control/cc/work/RegisterResultPartitionLocationWork.java index b788e27dfd..d51776110b 100644 --- a/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-cc/src/main/java/org/apache/hyracks/control/cc/work/RegisterResultPartitionLocationWork.java +++ b/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-cc/src/main/java/org/apache/hyracks/control/cc/work/RegisterResultPartitionLocationWork.java @@ -90,4 +90,9 @@ public class RegisterResultPartitionLocationWork extends AbstractWork { + nPartitions + " ResultPartitionLocation@" + networkAddress + " metadata@" + metadata + " EmptyResult@" + emptyResult; } + + @Override + public Level logLevel() { + return Level.TRACE; + } }
