Skip to content
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.

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

feat: include SQL statement in error message #355

Merged
merged 1 commit into from Jul 17, 2020
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
Expand Up @@ -607,7 +607,7 @@ ExecuteBatchDmlRequest.Builder getExecuteBatchDmlRequestBuilder(Iterable<Stateme
}

ResultSet executeQueryInternalWithOptions(
Statement statement,
final Statement statement,
com.google.spanner.v1.ExecuteSqlRequest.QueryMode queryMode,
Options options,
ByteString partitionToken) {
Expand All @@ -622,7 +622,7 @@ ResultSet executeQueryInternalWithOptions(
new ResumableStreamIterator(MAX_BUFFERED_CHUNKS, SpannerImpl.QUERY, span) {
@Override
CloseableIterator<PartialResultSet> startStream(@Nullable ByteString resumeToken) {
GrpcStreamIterator stream = new GrpcStreamIterator(prefetchChunks);
GrpcStreamIterator stream = new GrpcStreamIterator(statement, prefetchChunks);
if (resumeToken != null) {
request.setResumeToken(resumeToken);
}
Expand Down
Expand Up @@ -763,16 +763,24 @@ interface CloseableIterator<T> extends Iterator<T> {
@VisibleForTesting
static class GrpcStreamIterator extends AbstractIterator<PartialResultSet>
implements CloseableIterator<PartialResultSet> {
private static final Logger logger = Logger.getLogger(GrpcStreamIterator.class.getName());
private static final PartialResultSet END_OF_STREAM = PartialResultSet.newBuilder().build();

private final ConsumerImpl consumer = new ConsumerImpl();
private final BlockingQueue<PartialResultSet> stream;
private final Statement statement;

private SpannerRpc.StreamingCall call;
private SpannerException error;

// Visible for testing.
@VisibleForTesting
GrpcStreamIterator(int prefetchChunks) {
this(null, prefetchChunks);
}

@VisibleForTesting
GrpcStreamIterator(Statement statement, int prefetchChunks) {
this.statement = statement;
// One extra to allow for END_OF_STREAM message.
this.stream = new LinkedBlockingQueue<>(prefetchChunks + 1);
}
Expand Down Expand Up @@ -839,6 +847,23 @@ public void onCompleted() {

@Override
public void onError(SpannerException e) {
if (statement != null) {
if (logger.isLoggable(Level.FINEST)) {
// Include parameter values if logging level is set to FINEST or higher.
e =
SpannerExceptionFactory.newSpannerExceptionPreformatted(
e.getErrorCode(),
String.format("%s - Statement: '%s'", e.getMessage(), statement.toString()),
e);
logger.log(Level.FINEST, "Error executing statement", e);
} else {
e =
SpannerExceptionFactory.newSpannerExceptionPreformatted(
e.getErrorCode(),
String.format("%s - Statement: '%s'", e.getMessage(), statement.getSql()),
e);
}
}
error = e;
addToStream(END_OF_STREAM);
}
Expand Down
Expand Up @@ -188,7 +188,7 @@ private static ResourceInfo extractResourceInfo(Throwable cause) {
return null;
}

private static SpannerException newSpannerExceptionPreformatted(
static SpannerException newSpannerExceptionPreformatted(
ErrorCode code, @Nullable String message, @Nullable Throwable cause) {
// This is the one place in the codebase that is allowed to call constructors directly.
DoNotConstructDirectly token = DoNotConstructDirectly.ALLOWED;
Expand Down
Expand Up @@ -25,6 +25,7 @@
import com.google.api.gax.grpc.testing.LocalChannelProvider;
import com.google.api.gax.retrying.RetrySettings;
import com.google.cloud.NoCredentials;
import com.google.cloud.spanner.AbstractResultSet.GrpcStreamIterator;
import com.google.cloud.spanner.AsyncResultSet.CallbackResponse;
import com.google.cloud.spanner.AsyncResultSet.ReadyCallback;
import com.google.cloud.spanner.AsyncRunner.AsyncWork;
Expand All @@ -33,6 +34,7 @@
import com.google.cloud.spanner.ReadContext.QueryAnalyzeMode;
import com.google.cloud.spanner.TransactionRunner.TransactionCallable;
import com.google.common.base.Stopwatch;
import com.google.common.collect.ImmutableList;
import com.google.common.util.concurrent.SettableFuture;
import com.google.protobuf.AbstractMessage;
import com.google.spanner.v1.ExecuteSqlRequest;
Expand All @@ -52,6 +54,8 @@
import java.util.concurrent.ScheduledThreadPoolExecutor;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicInteger;
import java.util.logging.Level;
import java.util.logging.Logger;
import org.junit.After;
import org.junit.AfterClass;
import org.junit.Before;
Expand Down Expand Up @@ -1483,4 +1487,65 @@ public void testBatchCreateSessionsPermissionDenied() {
}
}
}

@Test
public void testExceptionIncludesStatement() {
mockSpanner.setExecuteStreamingSqlExecutionTime(
SimulatedExecutionTime.ofException(
Status.INVALID_ARGUMENT.withDescription("Invalid query").asRuntimeException()));
DatabaseClient client =
spanner.getDatabaseClient(DatabaseId.of(TEST_PROJECT, TEST_INSTANCE, TEST_DATABASE));
try (ResultSet rs =
client
.singleUse()
.executeQuery(
Statement.newBuilder("SELECT * FROM FOO WHERE ID=@id").bind("id").to(1L).build())) {
rs.next();
fail("missing expected exception");
} catch (SpannerException e) {
assertThat(e.getErrorCode()).isEqualTo(ErrorCode.INVALID_ARGUMENT);
assertThat(e.getMessage()).contains("Statement: 'SELECT * FROM FOO WHERE ID=@id'");
// The error message should normally not include the parameter values to prevent sensitive
// information from accidentally being logged.
assertThat(e.getMessage()).doesNotContain("id: 1");
}

mockSpanner.setExecuteStreamingSqlExecutionTime(
SimulatedExecutionTime.ofException(
Status.INVALID_ARGUMENT.withDescription("Invalid query").asRuntimeException()));
Logger logger = Logger.getLogger(GrpcStreamIterator.class.getName());
Level currentLevel = logger.getLevel();
try (ResultSet rs =
client
.singleUse()
.executeQuery(
Statement.newBuilder("SELECT * FROM FOO WHERE ID=@id").bind("id").to(1L).build())) {
logger.setLevel(Level.FINEST);
rs.next();
fail("missing expected exception");
} catch (SpannerException e) {
// With log level set to FINEST the error should also include the parameter values.
assertThat(e.getErrorCode()).isEqualTo(ErrorCode.INVALID_ARGUMENT);
assertThat(e.getMessage()).contains("Statement: 'SELECT * FROM FOO WHERE ID=@id {id: 1}'");
} finally {
logger.setLevel(currentLevel);
}
}

@Test
public void testReadDoesNotIncludeStatement() {
mockSpanner.setStreamingReadExecutionTime(
SimulatedExecutionTime.ofException(
Status.INVALID_ARGUMENT.withDescription("Invalid read").asRuntimeException()));
DatabaseClient client =
spanner.getDatabaseClient(DatabaseId.of(TEST_PROJECT, TEST_INSTANCE, TEST_DATABASE));
try (ResultSet rs =
client.singleUse().read("FOO", KeySet.singleKey(Key.of(1L)), ImmutableList.of("BAR"))) {
rs.next();
fail("missing expected exception");
} catch (SpannerException e) {
assertThat(e.getErrorCode()).isEqualTo(ErrorCode.INVALID_ARGUMENT);
assertThat(e.getMessage()).doesNotContain("Statement:");
}
}
}