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

…#116) * 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 17, 2022 · aaa4fda · aaa4fda
1 parent 4c778ed
commit aaa4fda
Show file tree

Hide file tree

Showing 22 changed files with 614 additions and 156 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": "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

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,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"

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
@@ -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) {

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
@@ -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;
     }
 

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;
@@ -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,6 +125,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();
@@ -172,6 +183,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 +208,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 +220,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)
@@ -245,7 +276,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
@@ -264,8 +295,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() {

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;
     }