[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 <mhubail@apache.org>
Tested-by: Jenkins <jenkins@fulliautomatix.ics.uci.edu>
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 ed481bc..a75ee33 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 @@
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 20d79d5..563f498 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 @@
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 @@
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 9a8c0d5..8de7582 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.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 @@
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 @@
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 @@
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 @@
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 @@
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 2ca3fbc..4bc4d62 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 @@
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 9891850..64f900e 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 @@
}
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 46dd351..80d7630 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 @@
@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 b788e27..d517761 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 @@
+ nPartitions + " ResultPartitionLocation@" + networkAddress + " metadata@" + metadata + " EmptyResult@"
+ emptyResult;
}
+
+ @Override
+ public Level logLevel() {
+ return Level.TRACE;
+ }
}