Rework on error reporting to make it more verbose and human-friendly. (…

…#116)

Co-authored-by: MaxKsyunz <maxk@bitquilltech.com>
Co-authored-by: forestmvey <forestv@bitquilltech.com>
Signed-off-by: Yury-Fridlyand <yuryf@bitquilltech.com>

Solved Merge Conflicts

common/src/main/java/org/opensearch/sql/common/utils/QueryContext.java

@@ -8,7 +8,6 @@
 
 import java.time.LocalDateTime;
 import java.util.Map;
-import java.util.Optional;
 import java.util.UUID;
 import org.apache.logging.log4j.ThreadContext;
 
@@ -24,6 +23,11 @@ public class QueryContext {
    */
   private static final String REQUEST_ID_KEY = "request_id";
 
+  /**
+   * The key of the error message in the context map.
+   */
+  private static final String ERROR_KEY = "error";
+
   /**
    * Generates a random UUID and adds to the {@link ThreadContext} as the request id.
    * <p>
@@ -51,6 +55,31 @@ public static String getRequestId() {
     return id;
   }
 
+  /**
+   * Capture error message to aggregate diagnostics
+   * for both legacy and new SQL engines.
+   * Can be deleted once the
+   * legacy SQL engine is deprecated.
+   */
+  public static void setError(String error) {
+    ThreadContext.put(ERROR_KEY, error);
+  }
+
+  /**
+   * Get all captured error messages.
+   */
+  public static String getError() {
+    return ThreadContext.get(ERROR_KEY);
+  }
+
+  /**
+   * Clear saved error messages.
+   */
+  public static void clearError() {
+    ThreadContext.remove(ERROR_KEY);
+  }
+
+
   /**
    * Wraps a given instance of {@link Runnable} into a new one which gets all the
    * entries from current ThreadContext map.

docs/user/admin/settings.rst

@@ -305,7 +305,7 @@ SQL query::
     {
       "error": {
         "reason": "Invalid SQL query",
-        "details": "DELETE clause is disabled by default and will be deprecated. Using the plugins.sql.delete.enabled setting to enable it",
+        "details": "Failed to parse query due to offending symbol [DELETE] at: 'DELETE' <--- HERE... More details: Expecting tokens in {<EOF>, 'DESCRIBE', 'SELECT', 'SHOW', ';'}\nQuery failed on both V1 and V2 SQL engines. V1 SQL engine error following: \nDELETE clause is disabled by default and will be deprecated. Using the plugins.sql.delete.enabled setting to enable it",
         "type": "SQLFeatureDisabledException"
       },
       "status": 400

integ-test/src/test/java/org/opensearch/sql/legacy/PluginIT.java

@@ -70,8 +70,12 @@ public void sqlDeleteSettingsTest() throws IOException {
             "{\n"
                 + "  \"error\": {\n"
                 + "    \"reason\": \"Invalid SQL query\",\n"
-                + "    \"details\": \"DELETE clause is disabled by default and will be deprecated. Using "
-                + "the plugins.sql.delete.enabled setting to enable it\",\n"
+                + "    \"details\": \""
+                    + "Query request is not supported. Either unsupported fields are present, the "
+                    + "request is not a cursor request, or the response format is not supported.\\n"
+                    + "Query failed on both V1 and V2 SQL engines. V1 SQL engine error following: \\n"
+                    + "DELETE clause is disabled by default and will be deprecated."
+                    + " Using the plugins.sql.delete.enabled setting to enable it\",\n"
                 + "    \"type\": \"SQLFeatureDisabledException\"\n"
                 + "  },\n"
                 + "  \"status\": 400\n"

legacy/src/main/java/org/opensearch/sql/legacy/executor/format/ErrorMessage.java

@@ -6,6 +6,8 @@
 
 package org.opensearch.sql.legacy.executor.format;
 
+import lombok.Getter;
+import lombok.Setter;
 import org.json.JSONObject;
 import org.opensearch.rest.RestStatus;
 
@@ -16,6 +18,8 @@ public class ErrorMessage<E extends Exception> {
     private int status;
     private String type;
     private String reason;
+    @Setter
+    @Getter
     private String details;
 
     public ErrorMessage(E exception, int status) {

legacy/src/main/java/org/opensearch/sql/legacy/plugin/RestSQLQueryAction.java

@@ -28,6 +28,7 @@
 import org.opensearch.sql.common.antlr.SyntaxCheckException;
 import org.opensearch.sql.common.response.ResponseListener;
 import org.opensearch.sql.common.setting.Settings;
+import org.opensearch.sql.common.utils.QueryContext;
 import org.opensearch.sql.executor.ExecutionEngine.ExplainResponse;
 import org.opensearch.sql.legacy.metrics.MetricName;
 import org.opensearch.sql.legacy.metrics.Metrics;
@@ -98,6 +99,9 @@ protected RestChannelConsumer prepareRequest(RestRequest request, NodeClient nod
    */
   public RestChannelConsumer prepareRequest(SQLQueryRequest request, NodeClient nodeClient) {
     if (!request.isSupported()) {
+      QueryContext.setError(
+          "Query request is not supported. Either unsupported fields are present," +
+          " the request is not a cursor request, or the response format is not supported.");
       return NOT_SUPPORTED_YET;
     }
 
@@ -114,6 +118,12 @@ public RestChannelConsumer prepareRequest(SQLQueryRequest request, NodeClient no
       if (request.isExplainRequest()) {
         LOG.info("Request is falling back to old SQL engine due to: " + e.getMessage());
       }
+
+      /*
+       * Setting error to aggregate error messages when both legacy and new SQL engines fail.
+       * This implementation can be removed when the legacy SQL engine is deprecated.
+       */
+      QueryContext.setError(e.getMessage());
       return NOT_SUPPORTED_YET;
     }
 

legacy/src/main/java/org/opensearch/sql/legacy/plugin/RestSqlAction.java

@@ -13,6 +13,9 @@
 
 import com.alibaba.druid.sql.parser.ParserException;
 import com.google.common.collect.ImmutableList;
+
+import java.io.PrintWriter;
+import java.io.StringWriter;
 import java.sql.SQLFeatureNotSupportedException;
 import java.util.Arrays;
 import java.util.HashMap;
@@ -54,6 +57,7 @@
 import org.opensearch.sql.legacy.executor.RestExecutor;
 import org.opensearch.sql.legacy.executor.cursor.CursorActionRequestRestExecutorFactory;
 import org.opensearch.sql.legacy.executor.cursor.CursorAsyncRestExecutor;
+import org.opensearch.sql.legacy.executor.format.ErrorMessage;
 import org.opensearch.sql.legacy.executor.format.ErrorMessageFactory;
 import org.opensearch.sql.legacy.metrics.MetricName;
 import org.opensearch.sql.legacy.metrics.Metrics;
@@ -121,11 +125,19 @@ public String getName() {
         return "sql_action";
     }
 
+    /**
+     * Prepare and execute rest SQL request. In the event the V2 SQL engine fails, the V1
+     * engine attempts the query.
+     * @param request : Rest request being made.
+     * @param client : Rest client for making the request.
+     * @return : Resulting values for request.
+     */
     @Override
     protected RestChannelConsumer prepareRequest(RestRequest request, NodeClient client) {
         Metrics.getInstance().getNumericalMetric(MetricName.REQ_TOTAL).increment();
         Metrics.getInstance().getNumericalMetric(MetricName.REQ_COUNT_TOTAL).increment();
 
+        QueryContext.clearError();
         QueryContext.addRequestId();
 
         try {
@@ -172,6 +184,12 @@ protected RestChannelConsumer prepareRequest(RestRequest request, NodeClient cli
                 }
             });
         } catch (Exception e) {
+            if (null != QueryContext.getError()) {
+                LOG.error(QueryContext.getRequestId() + " V2 SQL error during query execution", e,
+                    "previously collected error(s):", QueryDataAnonymizer.anonymizeData(QueryContext.getError()));
+            } else {
+                LOG.error(QueryContext.getRequestId() + " V2 SQL error during query execution", e);
+            }
             logAndPublishMetrics(e);
             return channel -> reportError(channel, e, isClientError(e) ? BAD_REQUEST : SERVICE_UNAVAILABLE);
         }
@@ -191,6 +209,10 @@ private void handleCursorRequest(final RestRequest request, final String cursor,
         cursorRestExecutor.execute(client, request.params(), channel);
     }
 
+    /**
+     * Log error message for exception and increment failure statistics.
+     * @param e : Caught exception.
+     */
     private static void logAndPublishMetrics(final Exception e) {
         if (isClientError(e)) {
             LOG.error(QueryContext.getRequestId() + " Client side error during query execution", e);
@@ -199,6 +221,16 @@ private static void logAndPublishMetrics(final Exception e) {
             LOG.error(QueryContext.getRequestId() + " Server side error during query execution", e);
             Metrics.getInstance().getNumericalMetric(MetricName.FAILED_REQ_COUNT_SYS).increment();
         }
+
+        /**
+         * Use PrintWriter to copy the stack trace for logging. This is used to anonymize
+         * log messages, and can be reverted to the simpler implementation when
+         * the anonymizer is fixed.
+         */
+        StringWriter sw = new StringWriter();
+        e.printStackTrace(new PrintWriter(sw));
+        String stackTrace = sw.toString();
+        LOG.error(stackTrace);
     }
 
     private static QueryAction explainRequest(final NodeClient client, final SqlRequest sqlRequest, Format format)
@@ -264,8 +296,20 @@ private void sendResponse(final RestChannel channel, final String message, final
         channel.sendResponse(new BytesRestResponse(status, message));
     }
 
+    /**
+     * Report Error message to user.
+     * @param channel : Rest channel to send response through.
+     * @param e : Exception caught when attempting query.
+     * @param status : Status for rest request made.
+     */
     private void reportError(final RestChannel channel, final Exception e, final RestStatus status) {
-        sendResponse(channel, ErrorMessageFactory.createErrorMessage(e, status.getStatus()).toString(), status);
+        var message = ErrorMessageFactory.createErrorMessage(e, status.getStatus());
+        if (null != QueryContext.getError()) {
+            message.setDetails(QueryContext.getError() +
+                "\nQuery failed on both V1 and V2 SQL engines. V1 SQL engine error following: \n"
+                + message.getDetails());
+        }
+        sendResponse(channel, message.toString(), status);
     }
 
     private boolean isSQLFeatureEnabled() {

legacy/src/main/java/org/opensearch/sql/legacy/plugin/RestSqlStatsAction.java

@@ -67,6 +67,7 @@ public List<ReplacedRoute> replacedRoutes() {
     @Override
     protected RestChannelConsumer prepareRequest(RestRequest request, NodeClient client) {
 
+        QueryContext.clearError();
         QueryContext.addRequestId();
 
         try {

plugin/src/main/java/org/opensearch/sql/plugin/rest/RestPPLStatsAction.java

@@ -67,6 +67,7 @@ public List<ReplacedRoute> replacedRoutes() {
   @Override
   protected RestChannelConsumer prepareRequest(RestRequest request, NodeClient client) {
 
+    QueryContext.clearError();
     QueryContext.addRequestId();
 
     try {

plugin/src/main/java/org/opensearch/sql/plugin/rest/RestQuerySettingsAction.java

@@ -74,6 +74,7 @@ public List<ReplacedRoute> replacedRoutes() {
   @Override
   protected RestChannelConsumer prepareRequest(RestRequest request, NodeClient client)
       throws IOException {
+    QueryContext.clearError();
     QueryContext.addRequestId();
     final ClusterUpdateSettingsRequest clusterUpdateSettingsRequest =
         Requests.clusterUpdateSettingsRequest();

plugin/src/main/java/org/opensearch/sql/plugin/transport/TransportPPLQueryAction.java

@@ -80,6 +80,7 @@ protected void doExecute(
     Metrics.getInstance().getNumericalMetric(MetricName.PPL_REQ_TOTAL).increment();
     Metrics.getInstance().getNumericalMetric(MetricName.PPL_REQ_COUNT_TOTAL).increment();
 
+    QueryContext.clearError();
     QueryContext.addRequestId();
 
     PPLService pplService = createPPLService(client);