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>

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.

core/src/main/java/org/opensearch/sql/expression/datetime/DateTimeFunction.java

@@ -130,32 +130,32 @@ public void register(BuiltinFunctionRepository repository) {
    * `fsp` argument support is removed until refactoring to avoid bug where `now()`, `now(x)` and
    * `now(y) return different values.
    */
-  private FunctionResolver now(FunctionName functionName) {
+  private DefaultFunctionResolver now(FunctionName functionName) {
     return define(functionName,
         impl(() -> new ExprDatetimeValue(formatNow(null)), DATETIME)
     );
   }
 
-  private FunctionResolver now() {
+  private DefaultFunctionResolver now() {
     return now(BuiltinFunctionName.NOW.getName());
   }
 
-  private FunctionResolver current_timestamp() {
+  private DefaultFunctionResolver current_timestamp() {
     return now(BuiltinFunctionName.CURRENT_TIMESTAMP.getName());
   }
 
-  private FunctionResolver localtimestamp() {
+  private DefaultFunctionResolver localtimestamp() {
     return now(BuiltinFunctionName.LOCALTIMESTAMP.getName());
   }
 
-  private FunctionResolver localtime() {
+  private DefaultFunctionResolver localtime() {
     return now(BuiltinFunctionName.LOCALTIME.getName());
   }
 
   /**
    * SYSDATE() returns the time at which it executes.
    */
-  private FunctionResolver sysdate() {
+  private DefaultFunctionResolver sysdate() {
     return define(BuiltinFunctionName.SYSDATE.getName(),
         impl(() -> new ExprDatetimeValue(formatNow(null)), DATETIME),
         impl((v) -> new ExprDatetimeValue(formatNow(v.integerValue())), DATETIME, INTEGER)
@@ -165,31 +165,31 @@ private FunctionResolver sysdate() {
   /**
    * Synonym for @see `now`.
    */
-  private FunctionResolver curtime(FunctionName functionName) {
+  private DefaultFunctionResolver curtime(FunctionName functionName) {
     return define(functionName,
         impl(() -> new ExprTimeValue(formatNow(null).toLocalTime()), TIME)
     );
   }
 
-  private FunctionResolver curtime() {
+  private DefaultFunctionResolver curtime() {
     return curtime(BuiltinFunctionName.CURTIME.getName());
   }
 
-  private FunctionResolver current_time() {
+  private DefaultFunctionResolver current_time() {
     return curtime(BuiltinFunctionName.CURRENT_TIME.getName());
   }
 
-  private FunctionResolver curdate(FunctionName functionName) {
+  private DefaultFunctionResolver curdate(FunctionName functionName) {
     return define(functionName,
         impl(() -> new ExprDateValue(formatNow(null).toLocalDate()), DATE)
     );
   }
 
-  private FunctionResolver curdate() {
+  private DefaultFunctionResolver curdate() {
     return curdate(BuiltinFunctionName.CURDATE.getName());
   }
 
-  private FunctionResolver current_date() {
+  private DefaultFunctionResolver current_date() {
     return curdate(BuiltinFunctionName.CURRENT_DATE.getName());
   }
 
@@ -255,7 +255,7 @@ private DefaultFunctionResolver date() {
    * (STRING, STRING) -> DATETIME
    * (STRING) -> DATETIME
    */
-  private FunctionResolver datetime() {
+  private DefaultFunctionResolver datetime() {
     return define(BuiltinFunctionName.DATETIME.getName(),
         impl(nullMissingHandling(DateTimeFunction::exprDateTime),
             DATETIME, STRING, STRING),
@@ -367,7 +367,7 @@ private DefaultFunctionResolver from_days() {
         impl(nullMissingHandling(DateTimeFunction::exprFromDays), DATE, LONG));
   }
 
-  private FunctionResolver from_unixtime() {
+  private DefaultFunctionResolver from_unixtime() {
     return define(BuiltinFunctionName.FROM_UNIXTIME.getName(),
         impl(nullMissingHandling(DateTimeFunction::exprFromUnixTime), DATETIME, DOUBLE),
         impl(nullMissingHandling(DateTimeFunction::exprFromUnixTimeFormat),
@@ -386,12 +386,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));
   }
@@ -522,7 +522,7 @@ private DefaultFunctionResolver to_days() {
         impl(nullMissingHandling(DateTimeFunction::exprToDays), LONG, DATETIME));
   }
 
-  private FunctionResolver unix_timestamp() {
+  private DefaultFunctionResolver unix_timestamp() {
     return define(BuiltinFunctionName.UNIX_TIMESTAMP.getName(),
         impl(DateTimeFunction::unixTimeStamp, LONG),
         impl(nullMissingHandling(DateTimeFunction::unixTimeStampOf), DOUBLE, DATE),

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 {

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