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

Co-authored-by: MaxKsyunz <maxk@bitquilltech.com> Co-authored-by: forestmvey <forestv@bitquilltech.com> Signed-off-by: Yury-Fridlyand <yuryf@bitquilltech.com>
Bit-Quill · Sep 9, 2022 · 5182e6f · 5182e6f
1 parent 53cde65
commit 5182e6f
Show file tree

Hide file tree

Showing 22 changed files with 575 additions and 155 deletions.
diff --git a/common/src/main/java/org/opensearch/sql/common/utils/QueryContext.java b/common/src/main/java/org/opensearch/sql/common/utils/QueryContext.java
@@ -7,7 +7,6 @@
 package org.opensearch.sql.common.utils;
 
 import java.util.Map;
-import java.util.Optional;
 import java.util.UUID;
 import org.apache.logging.log4j.ThreadContext;
 
@@ -21,6 +20,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>
@@ -48,6 +52,24 @@ 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);
+  }
+
+
   /**
    * Wraps a given instance of {@link Runnable} into a new one which gets all the
    * entries from current ThreadContext map.

diff --git a/core/src/main/java/org/opensearch/sql/expression/datetime/DateTimeFunction.java b/core/src/main/java/org/opensearch/sql/expression/datetime/DateTimeFunction.java
@@ -39,7 +39,6 @@
 import org.opensearch.sql.expression.function.BuiltinFunctionRepository;
 import org.opensearch.sql.expression.function.DefaultFunctionResolver;
 import org.opensearch.sql.expression.function.FunctionName;
-import org.opensearch.sql.expression.function.FunctionResolver;
 
 /**
  * The definition of date and time functions.
@@ -243,12 +242,12 @@ private DefaultFunctionResolver hour() {
     );
   }
 
-  private FunctionResolver makedate() {
+  private DefaultFunctionResolver makedate() {
     return define(BuiltinFunctionName.MAKEDATE.getName(),
         impl(nullMissingHandling(DateTimeFunction::exprMakeDate), DATE, DOUBLE, DOUBLE));
   }
 
-  private FunctionResolver maketime() {
+  private DefaultFunctionResolver maketime() {
     return define(BuiltinFunctionName.MAKETIME.getName(),
         impl(nullMissingHandling(DateTimeFunction::exprMakeTime), TIME, DOUBLE, DOUBLE, DOUBLE));
   }

diff --git a/docs/user/admin/settings.rst b/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": "DELETE clause is disabled by default and will be deprecated. Using the plugins.sql.delete.enabled setting to enable it\nQuery failed on both V1 and V2 SQL parser engines. V2 SQL parser error following: \nFailed to parse query due to offending symbol [DELETE] at: 'DELETE' <--- HERE... More details: Expecting tokens in {<EOF>, 'DESCRIBE', 'SELECT', 'SHOW', ';'}",
         "type": "SQLFeatureDisabledException"
       },
       "status": 400

diff --git a/integ-test/src/test/java/org/opensearch/sql/legacy/PluginIT.java b/integ-test/src/test/java/org/opensearch/sql/legacy/PluginIT.java
@@ -70,8 +70,11 @@ 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\": \"DELETE clause is disabled by default and will be deprecated."
+                    + " Using the plugins.sql.delete.enabled setting to enable it\\nQuery failed "
+                    + "on both V1 and V2 SQL parser engines. V2 SQL parser error following: \\n"
+                    + "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"
                 + "    \"type\": \"SQLFeatureDisabledException\"\n"
                 + "  },\n"
                 + "  \"status\": 400\n"

diff --git a/legacy/src/main/java/org/opensearch/sql/legacy/executor/format/ErrorMessage.java b/legacy/src/main/java/org/opensearch/sql/legacy/executor/format/ErrorMessage.java
@@ -18,6 +18,14 @@ public class ErrorMessage<E extends Exception> {
     private String reason;
     private String details;
 
+    public String getDetails() {
+        return details;
+    }
+
+    public void addDetails(String moreDetails) {
+        details += moreDetails;
+    }
+
     public ErrorMessage(E exception, int status) {
         this.exception = exception;
         this.status = status;

diff --git a/legacy/src/main/java/org/opensearch/sql/legacy/plugin/RestSQLQueryAction.java b/legacy/src/main/java/org/opensearch/sql/legacy/plugin/RestSQLQueryAction.java
@@ -14,6 +14,7 @@
 import java.io.IOException;
 import java.security.PrivilegedExceptionAction;
 import java.util.List;
+
 import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
 import org.opensearch.client.node.NodeClient;
@@ -26,6 +27,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;
@@ -93,6 +95,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;
     }
 
@@ -109,6 +114,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;
     }
 

diff --git a/legacy/src/main/java/org/opensearch/sql/legacy/plugin/RestSqlAction.java b/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;
@@ -53,6 +56,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;
@@ -119,6 +123,13 @@ 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();
@@ -170,6 +181,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);
         }
@@ -189,6 +206,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);
@@ -197,6 +218,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)
@@ -243,7 +274,7 @@ private static boolean isExplainRequest(final RestRequest request) {
         return request.path().endsWith("/_explain");
     }
 
-    private static boolean isClientError(Exception e) {
+    public static boolean isClientError(Exception e) {
         return e instanceof NullPointerException // NPE is hard to differentiate but more likely caused by bad query
             || e instanceof SqlParseException
             || e instanceof ParserException
@@ -262,8 +293,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 sent 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.addDetails(
+                "\nQuery failed on both V1 and V2 SQL parser engines. V2 SQL parser error following: \n"
+                + QueryContext.getError());
+        }
+        sendResponse(channel, message.toString(), status);
     }
 
     private boolean isSQLFeatureEnabled() {

diff --git a/legacy/src/main/java/org/opensearch/sql/legacy/utils/QueryDataAnonymizer.java b/legacy/src/main/java/org/opensearch/sql/legacy/utils/QueryDataAnonymizer.java
@@ -26,7 +26,8 @@ public class QueryDataAnonymizer {
      * Sensitive data includes index names, column names etc.,
      * which in druid parser are parsed to SQLIdentifierExpr instances
      * @param query entire sql query string
-     * @return sql query string with all identifiers replaced with "***"
+     * @return sql query string with all identifiers replaced with "***" on success
+     * and failure string otherwise to ensure no non-anonymized data is logged in production.
      */
     public static String anonymizeData(String query) {
         String resultQuery;
@@ -38,8 +39,9 @@ public static String anonymizeData(String query) {
                     .replaceAll("false", "boolean_literal")
                     .replaceAll("[\\n][\\t]+", " ");
         } catch (Exception e) {
-            LOG.warn("Caught an exception when anonymizing sensitive data");
-            resultQuery = query;
+            LOG.warn("Caught an exception when anonymizing sensitive data.");
+            LOG.debug("String {} failed anonymization.", query);
+            resultQuery = "Failed to anonymize data.";
         }
         return resultQuery;
     }