Skip to content

Improve Error Reporting for New SQL Engine #691

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
forestmvey wants to merge 7 commits into from
Closed

Improve Error Reporting for New SQL Engine #691

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
1531f38
Initial Implementation
forestmvey Jul 11, 2022
0211c0d
Adding JAVADOC and code cleanup
forestmvey Jul 12, 2022
0867d08
Fixing output errors on tests, variable name formatting, minor revisions
forestmvey Jul 12, 2022
19e4c2c
Fixed so only successfully anonymized data is logged. Handled stack t…
forestmvey Jul 13, 2022
245156c
Fix whitespace and add comments on updates for anonymizing string fun…
forestmvey Jul 13, 2022
9e0c70c
Fix bug where old error message for V2 engine was saved and re-used. …
forestmvey Jul 15, 2022
0898159
Updated to use annotations for getters and setters. Added grammar fix…
forestmvey Jul 21, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
9 changes: 9 additions & 0 deletions docs/user/admin/settings.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -310,4 +310,13 @@ SQL query::
},
"status": 400
}
Query failed on both V1 and V2 SQL parser engines. V2 SQL parser error following:
{
"error": {
"reason": "Invalid SQL query",
"details": "Failed to parse query due to offending symbol [DELETE] at: 'DELETE' <--- HERE... More details: Expecting tokens in {<EOF>, 'DESCRIBE', 'SELECT', 'SHOW', ';'}",
"type": "SyntaxCheckException"
},
"status": 400
}

25 changes: 25 additions & 0 deletions legacy/src/main/java/org/opensearch/sql/legacy/plugin/RestSQLQueryAction.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,14 +6,20 @@

package org.opensearch.sql.legacy.plugin;

import static org.opensearch.rest.RestStatus.BAD_REQUEST;
import static org.opensearch.rest.RestStatus.INTERNAL_SERVER_ERROR;
import static org.opensearch.rest.RestStatus.OK;
import static org.opensearch.rest.RestStatus.SERVICE_UNAVAILABLE;
import static org.opensearch.sql.executor.ExecutionEngine.QueryResponse;
import static org.opensearch.sql.legacy.plugin.RestSqlAction.isClientError;
import static org.opensearch.sql.protocol.response.format.JsonResponseFormatter.Style.PRETTY;

import java.io.IOException;
import java.security.PrivilegedExceptionAction;
import java.util.List;

import lombok.Getter;
import lombok.Setter;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.opensearch.client.node.NodeClient;
Expand All @@ -27,6 +33,7 @@
import org.opensearch.sql.common.response.ResponseListener;
import org.opensearch.sql.common.setting.Settings;
import org.opensearch.sql.executor.ExecutionEngine.ExplainResponse;
import org.opensearch.sql.legacy.executor.format.ErrorMessageFactory;
import org.opensearch.sql.legacy.metrics.MetricName;
import org.opensearch.sql.legacy.metrics.Metrics;
import org.opensearch.sql.opensearch.security.SecurityAccess;
Expand Down Expand Up @@ -61,6 +68,16 @@ public class RestSQLQueryAction extends BaseRestHandler {
*/
private final Settings pluginSettings;

/**
* Captured error message to aggregate diagnostics
* for both legacy and new SQL engines.
* This member variable and it's usage can be deleted once the
* legacy SQL engine is deprecated.
*/
@Setter
@Getter
private String errorStr;
Copy link
Collaborator

@MaxKsyunz MaxKsyunz Jul 19, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You can use @Getter and @Setter annotations instead of creating setErrorStr and getErrorStr.

Copy link
Collaborator Author

@forestmvey forestmvey Jul 25, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Resolved under: 08981598f03df7da85f23fd547b70c1a08318c8c

Copy link
Collaborator

@dai-chen dai-chen Aug 4, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just want to confirm is this class (or RestSqlAction who create this) a singleton or created per request?

Copy link
Collaborator

@penghuo penghuo Aug 5, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

do we really need errorStr? or Exception e? Could we use RestSqlAction produce the error message from e.

Copy link
Collaborator Author

@forestmvey forestmvey Aug 5, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@dai-chen This class is a singleton.
@penghuo We need to be able to capture error messages form potentially 2 exceptions. That is why we need the errorStr member variable.

Copy link
Collaborator

@acarbonetto acarbonetto Aug 5, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

RestSqlAction is created per request.


/**
* Constructor of RestSQLQueryAction.
*/
Expand Down Expand Up @@ -93,6 +110,8 @@ protected RestChannelConsumer prepareRequest(RestRequest request, NodeClient nod
*/
public RestChannelConsumer prepareRequest(SQLQueryRequest request, NodeClient nodeClient) {
if (!request.isSupported()) {
setErrorStr("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;
}

Expand All @@ -109,6 +128,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 errorStr member variable is used to aggregate error messages when both legacy and new SQL engines fail.
* This implementation can be removed when the legacy SQL engine is deprecated.
*/
setErrorStr(ErrorMessageFactory.createErrorMessage(e, isClientError(e) ? BAD_REQUEST.getStatus() : SERVICE_UNAVAILABLE.getStatus()).toString());
return NOT_SUPPORTED_YET;
}

Expand Down
49 changes: 43 additions & 6 deletions legacy/src/main/java/org/opensearch/sql/legacy/plugin/RestSqlAction.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,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;
Expand Down Expand Up @@ -118,12 +121,20 @@ 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();

LogUtils.addRequestId();
newSqlQueryHandler.setErrorStr("");
Copy link
Collaborator

@penghuo penghuo Aug 5, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is it necessary?

Copy link
Collaborator Author

@forestmvey forestmvey Aug 5, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since this class is a singleton we can potentially re-use old error messages. This ensures we are starting with an empty error message.

Copy link
Member

@joshuali925 joshuali925 Aug 8, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

if it's singleton will errorStr handle concurrent errors?


try {
if (!isSQLFeatureEnabled()) {
Expand Down Expand Up @@ -161,8 +172,9 @@ protected RestChannelConsumer prepareRequest(RestRequest request, NodeClient cli
final QueryAction queryAction = explainRequest(client, sqlRequest, format);
return channel -> executeSqlRequest(request, queryAction, client, channel);
} catch (Exception e) {
LOG.error(LogUtils.getRequestId() + " V2 SQL error during query execution", QueryDataAnonymizer.anonymizeData(newSqlQueryHandler.getErrorStr()));
Copy link
Collaborator

@Yury-Fridlyand Yury-Fridlyand Aug 13, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

errorStr never holds the query, so call to anonymizer will always fail.

logAndPublishMetrics(e);
return channel -> reportError(channel, e, isClientError(e) ? BAD_REQUEST : SERVICE_UNAVAILABLE);
return channel -> reportError(channel, e, isClientError(e) ? BAD_REQUEST : SERVICE_UNAVAILABLE, newSqlQueryHandler.getErrorStr());
}
}

Expand All @@ -180,14 +192,28 @@ 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(LogUtils.getRequestId() + " Client side error during query execution", e);
LOG.error(LogUtils.getRequestId() + " Client side error during query execution", QueryDataAnonymizer.anonymizeData(e.getMessage()));
Metrics.getInstance().getNumericalMetric(MetricName.FAILED_REQ_COUNT_CUS).increment();
} else {
LOG.error(LogUtils.getRequestId() + " Server side error during query execution", e);
LOG.error(LogUtils.getRequestId() + " Server side error during query execution", QueryDataAnonymizer.anonymizeData(e.getMessage()));
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();
Copy link
Collaborator

@MaxKsyunz MaxKsyunz Jul 19, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can't his block (205-207) be with line 215? It'll be easier to follow.

Copy link
Collaborator Author

@forestmvey forestmvey Jul 25, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Resolved under: 08981598f03df7da85f23fd547b70c1a08318c8c

Copy link
Collaborator

@penghuo penghuo Aug 5, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It is for debug purpose, right? could it be wrap inside if (log.debug)?

Copy link
Collaborator Author

@forestmvey forestmvey Aug 5, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We want the stack trace to be logged under normal debug levels as error. So not for debugging purposes only but error reporting like prior to this new implementation. I could wrap this inside of a Log.Error if that is more of your liking.

LOG.error(stackTrace);
}

private static QueryAction explainRequest(final NodeClient client, final SqlRequest sqlRequest, Format format)
Expand Down Expand Up @@ -234,7 +260,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) {
Copy link
Collaborator

@penghuo penghuo Aug 5, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why change to public?

Copy link
Collaborator Author

@forestmvey forestmvey Aug 5, 2022 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I updated this function to public to allow RestSqlQueryAction to output the same error format as this class. As well it seemed like a function that would be appropriately public.

return e instanceof NullPointerException // NPE is hard to differentiate but more likely caused by bad query
|| e instanceof SqlParseException
|| e instanceof ParserException
Expand All @@ -253,8 +279,19 @@ private void sendResponse(final RestChannel channel, final String message, final
channel.sendResponse(new BytesRestResponse(status, message));
}

private void reportError(final RestChannel channel, final Exception e, final RestStatus status) {
sendResponse(channel, ErrorMessageFactory.createErrorMessage(e, status.getStatus()).toString(), status);
/**
* 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.
* @param v2SqlEngineError : Error message for new SQL engine. Can be removed when old SQL engine is deprecated.
*/
private void reportError(final RestChannel channel, final Exception e, final RestStatus status, String v2SqlEngineError) {
String errorMsg = ErrorMessageFactory.createErrorMessage(e, status.getStatus()).toString();
errorMsg += v2SqlEngineError.isEmpty() ? "" :
"\nQuery failed on both V1 and V2 SQL parser engines. V2 SQL parser error following: \n"
+ v2SqlEngineError;
Comment on lines +289 to +293
Copy link
Collaborator

@Yury-Fridlyand Yury-Fridlyand Aug 13, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just discovered that you're concatenating 2 json objects here. In my test I'm getting

{
  "error": {
    "reason": "Invalid SQL query",
    "details": "unsupported method: simple_query_string",
    "type": "SqlParseException"
  },
  "status": 400
}
Query failed on both V1 and V2 SQL parser engines. V2 SQL parser error following:
{
  "error": {
    "reason": "Invalid SQL query",
    "details": "Failed to parse query due to offending symbol [1] at: 'select `key`, str2 from calcs where simple_query_string([str2], one, analyzer = standard, 1' <--- HERE... More details: Expecting tokens in {'ALLOW_LEADING_WILDCARD', 'ANALYZER', 'ANALYZE_WILDCARD', 'AUTO_GENERATE_SYNONYMS_PHRASE_QUERY', 'BOOST', 'CUTOFF_FREQUENCY', 'DEFAULT_FIELD', 'DEFAULT_OPERATOR', 'ESCAPE', 'ENABLE_POSITION_INCREMENTS', 'FIELDS', 'FLAGS', 'FUZZINESS', 'FUZZY_MAX_EXPANSIONS', 'FUZZY_PREFIX_LENGTH', 'FUZZY_REWRITE', 'FUZZY_TRANSPOSITIONS', 'LENIENT', 'LOW_FREQ_OPERATOR', 'MAX_DETERMINIZED_STATES', 'MAX_EXPANSIONS', 'MINIMUM_SHOULD_MATCH', 'OPERATOR', 'PHRASE_SLOP', 'PREFIX_LENGTH', 'QUOTE_ANALYZER', 'QUOTE_FIELD_SUFFIX', 'REWRITE', 'SLOP', 'TIE_BREAKER', 'TIME_ZONE', 'TYPE', 'ZERO_TERMS_QUERY'}",
    "type": "SyntaxCheckException"
  },
  "status": 400
}

You should update details block of ErrorMessage instead.

sendResponse(channel, errorMsg, status);
}

private boolean isSQLFeatureEnabled() {
Expand Down
8 changes: 5 additions & 3 deletions legacy/src/main/java/org/opensearch/sql/legacy/utils/QueryDataAnonymizer.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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);
Copy link
Collaborator

@penghuo penghuo Jul 14, 2022 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why not combine with LOG.warn?

Copy link
Collaborator

@acarbonetto acarbonetto Jul 14, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For syntax errors, the query variable contains the details of the failed query and is not anonymized (since the anonymization failed). This could, potentially, put sensitive data into the logs that we don't want to be included in production data. Setting it to debug level means that it doesn't go out to the logs by default.

resultQuery = "Failed to anonymize data.";
}
return resultQuery;
}
Expand Down