From 92b6eee2b5bcb839ca5694d40d81d36a2f269353 Mon Sep 17 00:00:00 2001 From: Andrew Weaver Date: Mon, 5 Jun 2023 14:54:04 -0500 Subject: [PATCH 1/4] Add ExecutionInfo to RequestTracker methods --- .../ContinuousRequestHandlerBase.java | 80 ++++++++++---- .../core/graph/GraphRequestHandler.java | 48 +++++---- .../api/core/tracker/RequestTracker.java | 102 +++++++++++++++--- .../internal/core/cql/CqlRequestHandler.java | 63 +++++++---- .../DefaultLoadBalancingPolicy.java | 3 + .../tracker/MultiplexingRequestTracker.java | 20 +++- .../core/tracker/NoopRequestTracker.java | 6 ++ .../internal/core/tracker/RequestLogger.java | 6 ++ .../ContinuousCqlRequestHandlerTest.java | 4 + .../core/graph/GraphRequestHandlerTest.java | 3 + .../cql/CqlRequestHandlerTrackerTest.java | 6 +- ...LoadBalancingPolicyRequestTrackerTest.java | 18 ++-- .../MultiplexingRequestTrackerTest.java | 34 +++--- .../tracker/RequestNodeLoggerExample.java | 4 + 14 files changed, 299 insertions(+), 98 deletions(-) diff --git a/core/src/main/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousRequestHandlerBase.java b/core/src/main/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousRequestHandlerBase.java index 0453022cb6a..303b05c9843 100644 --- a/core/src/main/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousRequestHandlerBase.java +++ b/core/src/main/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousRequestHandlerBase.java @@ -19,11 +19,13 @@ import com.datastax.dse.driver.api.core.DseProtocolVersion; import com.datastax.dse.driver.api.core.cql.continuous.ContinuousAsyncResultSet; +import com.datastax.dse.driver.api.core.graph.AsyncGraphResultSet; import com.datastax.dse.driver.internal.core.DseProtocolFeature; import com.datastax.dse.driver.internal.core.cql.DseConversions; import com.datastax.dse.protocol.internal.request.Revise; import com.datastax.dse.protocol.internal.response.result.DseRowsMetadata; import com.datastax.oss.driver.api.core.AllNodesFailedException; +import com.datastax.oss.driver.api.core.AsyncPagingIterable; import com.datastax.oss.driver.api.core.CqlIdentifier; import com.datastax.oss.driver.api.core.DriverTimeoutException; import com.datastax.oss.driver.api.core.NodeUnavailableException; @@ -627,7 +629,7 @@ public void operationComplete(@NonNull Future future) { Throwable error = future.cause(); if (error instanceof EncoderException && error.getCause() instanceof FrameTooLongException) { - trackNodeError(node, error.getCause()); + trackNodeError(node, error.getCause(), null); lock.lock(); try { abort(error.getCause(), false); @@ -644,7 +646,7 @@ public void operationComplete(@NonNull Future future) { .getMetricUpdater() .incrementCounter(DefaultNodeMetric.UNSENT_REQUESTS, executionProfile.getName()); recordError(node, error); - trackNodeError(node, error.getCause()); + trackNodeError(node, error.getCause(), null); sendRequest(statement, null, executionIndex, retryCount, scheduleSpeculativeExecution); } } else { @@ -739,7 +741,8 @@ private void onPageTimeout(int expectedPage) { * Invoked when a continuous paging response is received, either a successful or failed one. * *

Delegates further processing to appropriate methods: {@link #processResultResponse(Result, - * Frame)} if the response was successful, or {@link #processErrorResponse(Error)} if it wasn't. + * Frame)} if the response was successful, or {@link #processErrorResponse(Error, Frame)} if it + * wasn't. * * @param response the received {@link Frame}. */ @@ -760,15 +763,15 @@ public void onResponse(@NonNull Frame response) { processResultResponse((Result) responseMessage, response); } else if (responseMessage instanceof Error) { LOG.trace("[{}] Got error response", logPrefix); - processErrorResponse((Error) responseMessage); + processErrorResponse((Error) responseMessage, response); } else { IllegalStateException error = new IllegalStateException("Unexpected response " + responseMessage); - trackNodeError(node, error); + trackNodeError(node, error, response); abort(error, false); } } catch (Throwable t) { - trackNodeError(node, t); + trackNodeError(node, t, response); abort(t, false); } } finally { @@ -902,7 +905,7 @@ private void processResultResponse(@NonNull Result result, @Nullable Frame frame * @param errorMessage the error message received. */ @SuppressWarnings("GuardedBy") // this method is only called with the lock held - private void processErrorResponse(@NonNull Error errorMessage) { + private void processErrorResponse(@NonNull Error errorMessage, @NonNull Frame frame) { assert lock.isHeldByCurrentThread(); if (errorMessage instanceof Unprepared) { processUnprepared((Unprepared) errorMessage); @@ -911,7 +914,7 @@ private void processErrorResponse(@NonNull Error errorMessage) { if (error instanceof BootstrappingException) { LOG.trace("[{}] {} is bootstrapping, trying next node", logPrefix, node); recordError(node, error); - trackNodeError(node, error); + trackNodeError(node, error, frame); sendRequest(statement, null, executionIndex, retryCount, false); } else if (error instanceof QueryValidationException || error instanceof FunctionFailureException @@ -923,7 +926,7 @@ private void processErrorResponse(@NonNull Error errorMessage) { NodeMetricUpdater metricUpdater = ((DefaultNode) node).getMetricUpdater(); metricUpdater.incrementCounter( DefaultNodeMetric.OTHER_ERRORS, executionProfile.getName()); - trackNodeError(node, error); + trackNodeError(node, error, frame); abort(error, true); } else { try { @@ -1062,7 +1065,7 @@ private void processUnprepared(@NonNull Unprepared errorMessage) { + "This usually happens when you run a 'USE...' query after " + "the statement was prepared.", Bytes.toHexString(idToReprepare), Bytes.toHexString(repreparedId))); - trackNodeError(node, illegalStateException); + trackNodeError(node, illegalStateException, null); fatalError = illegalStateException; } else { LOG.trace( @@ -1081,18 +1084,18 @@ private void processUnprepared(@NonNull Unprepared errorMessage) { || prepareError instanceof FunctionFailureException || prepareError instanceof ProtocolError) { LOG.trace("[{}] Unrecoverable error on re-prepare, rethrowing", logPrefix); - trackNodeError(node, prepareError); + trackNodeError(node, prepareError, null); fatalError = prepareError; } } } else if (exception instanceof RequestThrottlingException) { - trackNodeError(node, exception); + trackNodeError(node, exception, null); fatalError = exception; } if (fatalError == null) { LOG.trace("[{}] Re-prepare failed, trying next node", logPrefix); recordError(node, exception); - trackNodeError(node, exception); + trackNodeError(node, exception, null); sendRequest(statement, null, executionIndex, retryCount, false); } } @@ -1120,18 +1123,18 @@ private void processRetryVerdict(@NonNull RetryVerdict verdict, @NonNull Throwab switch (verdict.getRetryDecision()) { case RETRY_SAME: recordError(node, error); - trackNodeError(node, error); + trackNodeError(node, error, null); sendRequest( verdict.getRetryRequest(statement), node, executionIndex, retryCount + 1, false); break; case RETRY_NEXT: recordError(node, error); - trackNodeError(node, error); + trackNodeError(node, error, null); sendRequest( verdict.getRetryRequest(statement), null, executionIndex, retryCount + 1, false); break; case RETHROW: - trackNodeError(node, error); + trackNodeError(node, error, null); abort(error, true); break; case IGNORE: @@ -1444,12 +1447,20 @@ private void reenableAutoReadIfNeeded() { // ERROR HANDLING - private void trackNodeError(@NonNull Node node, @NonNull Throwable error) { + private void trackNodeError( + @NonNull Node node, @NonNull Throwable error, @Nullable Frame frame) { if (nodeErrorReported.compareAndSet(false, true)) { long latencyNanos = System.nanoTime() - this.messageStartTimeNanos; context .getRequestTracker() - .onNodeError(this.statement, error, latencyNanos, executionProfile, node, logPrefix); + .onNodeError( + this.statement, + error, + latencyNanos, + executionProfile, + node, + createExecutionInfo(frame), + logPrefix); } } @@ -1563,21 +1574,32 @@ private void completeResultSetFuture( if (resultSetClass.isInstance(pageOrError)) { if (future.complete(resultSetClass.cast(pageOrError))) { throttler.signalSuccess(ContinuousRequestHandlerBase.this); + + ExecutionInfo executionInfo = null; + if (pageOrError instanceof AsyncPagingIterable) { + executionInfo = ((AsyncPagingIterable) pageOrError).getExecutionInfo(); + } else if (pageOrError instanceof AsyncGraphResultSet) { + executionInfo = ((AsyncGraphResultSet) pageOrError).getRequestExecutionInfo(); + } + if (nodeSuccessReported.compareAndSet(false, true)) { context .getRequestTracker() - .onNodeSuccess(statement, nodeLatencyNanos, executionProfile, node, logPrefix); + .onNodeSuccess( + statement, nodeLatencyNanos, executionProfile, node, executionInfo, logPrefix); } context .getRequestTracker() - .onSuccess(statement, totalLatencyNanos, executionProfile, node, logPrefix); + .onSuccess( + statement, totalLatencyNanos, executionProfile, node, executionInfo, logPrefix); } } else { Throwable error = (Throwable) pageOrError; if (future.completeExceptionally(error)) { context .getRequestTracker() - .onError(statement, error, totalLatencyNanos, executionProfile, node, logPrefix); + .onError( + statement, error, totalLatencyNanos, executionProfile, node, null, logPrefix); if (error instanceof DriverTimeoutException) { throttler.signalTimeout(ContinuousRequestHandlerBase.this); session @@ -1608,6 +1630,22 @@ private ExecutionInfo createExecutionInfo(@NonNull Result result, @Nullable Fram executionProfile); } + @NonNull + private ExecutionInfo createExecutionInfo(@Nullable Frame response) { + return new DefaultExecutionInfo( + statement, + node, + startedSpeculativeExecutionsCount.get(), + executionIndex, + errors, + null, + response, + true, + session, + context, + executionProfile); + } + private void logTimeoutSchedulingError(IllegalStateException timeoutError) { // If we're racing with session shutdown, the timer might be stopped already. We don't want // to schedule more executions anyway, so swallow the error. diff --git a/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandler.java b/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandler.java index 5c9ceb00df2..6c78c343fdd 100644 --- a/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandler.java +++ b/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandler.java @@ -361,9 +361,19 @@ private void setFinalResult( totalLatencyNanos = completionTimeNanos - startTimeNanos; long nodeLatencyNanos = completionTimeNanos - callback.nodeStartTimeNanos; requestTracker.onNodeSuccess( - callback.statement, nodeLatencyNanos, executionProfile, callback.node, logPrefix); + callback.statement, + nodeLatencyNanos, + executionProfile, + callback.node, + executionInfo, + logPrefix); requestTracker.onSuccess( - callback.statement, totalLatencyNanos, executionProfile, callback.node, logPrefix); + callback.statement, + totalLatencyNanos, + executionProfile, + callback.node, + executionInfo, + logPrefix); } if (sessionMetricUpdater.isEnabled( DseSessionMetric.GRAPH_REQUESTS, executionProfile.getName())) { @@ -447,27 +457,28 @@ private void setFinalError( GraphStatement statement, Throwable error, Node node, int execution) { DriverExecutionProfile executionProfile = Conversions.resolveExecutionProfile(statement, context); + ExecutionInfo executionInfo = + new DefaultExecutionInfo( + statement, + node, + startedSpeculativeExecutionsCount.get(), + execution, + errors, + null, + null, + true, + session, + context, + executionProfile); if (error instanceof DriverException) { - ((DriverException) error) - .setExecutionInfo( - new DefaultExecutionInfo( - statement, - node, - startedSpeculativeExecutionsCount.get(), - execution, - errors, - null, - null, - true, - session, - context, - executionProfile)); + ((DriverException) error).setExecutionInfo(executionInfo); } if (result.completeExceptionally(error)) { cancelScheduledTasks(); if (!(requestTracker instanceof NoopRequestTracker)) { long latencyNanos = System.nanoTime() - startTimeNanos; - requestTracker.onError(statement, error, latencyNanos, executionProfile, node, logPrefix); + requestTracker.onError( + statement, error, latencyNanos, executionProfile, node, executionInfo, logPrefix); } if (error instanceof DriverTimeoutException) { throttler.signalTimeout(this); @@ -860,7 +871,8 @@ private void trackNodeError(Node node, Throwable error, long nodeResponseTimeNan nodeResponseTimeNanos = System.nanoTime(); } long latencyNanos = nodeResponseTimeNanos - this.nodeStartTimeNanos; - requestTracker.onNodeError(statement, error, latencyNanos, executionProfile, node, logPrefix); + requestTracker.onNodeError( + statement, error, latencyNanos, executionProfile, node, null, logPrefix); } @Override diff --git a/core/src/main/java/com/datastax/oss/driver/api/core/tracker/RequestTracker.java b/core/src/main/java/com/datastax/oss/driver/api/core/tracker/RequestTracker.java index d29ee48d352..a3988f360f4 100644 --- a/core/src/main/java/com/datastax/oss/driver/api/core/tracker/RequestTracker.java +++ b/core/src/main/java/com/datastax/oss/driver/api/core/tracker/RequestTracker.java @@ -18,6 +18,7 @@ package com.datastax.oss.driver.api.core.tracker; import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; +import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.metadata.Node; import com.datastax.oss.driver.api.core.session.Request; import com.datastax.oss.driver.api.core.session.Session; @@ -37,7 +38,7 @@ public interface RequestTracker extends AutoCloseable { /** * @deprecated This method only exists for backward compatibility. Override {@link - * #onSuccess(Request, long, DriverExecutionProfile, Node, String)} instead. + * #onSuccess(Request, long, DriverExecutionProfile, Node, ExecutionInfo, String)} instead. */ @Deprecated default void onSuccess( @@ -46,6 +47,21 @@ default void onSuccess( @NonNull DriverExecutionProfile executionProfile, @NonNull Node node) {} + /** + * @deprecated This method only exists for backward compatibility. Override {@link + * #onSuccess(Request, long, DriverExecutionProfile, Node, ExecutionInfo, String)} instead. + */ + @Deprecated + default void onSuccess( + @NonNull Request request, + long latencyNanos, + @NonNull DriverExecutionProfile executionProfile, + @NonNull Node node, + @NonNull String requestLogPrefix) { + // If client doesn't override onSuccess with requestLogPrefix delegate call to the old method + onSuccess(request, latencyNanos, executionProfile, node); + } + /** * Invoked each time a request succeeds. * @@ -53,6 +69,7 @@ default void onSuccess( * GenericType) session.execute} call until the result is made available to the client). * @param executionProfile the execution profile of this request. * @param node the node that returned the successful response. + * @param executionInfo the execution info containing the results of this request * @param requestLogPrefix the dedicated log prefix for this request */ default void onSuccess( @@ -60,14 +77,16 @@ default void onSuccess( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, + @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { - // If client doesn't override onSuccess with requestLogPrefix delegate call to the old method - onSuccess(request, latencyNanos, executionProfile, node); + // If client doesn't override onSuccess with executionInfo delegate call to the old method + onSuccess(request, latencyNanos, executionProfile, node, requestLogPrefix); } /** * @deprecated This method only exists for backward compatibility. Override {@link - * #onError(Request, Throwable, long, DriverExecutionProfile, Node, String)} instead. + * #onError(Request, Throwable, long, DriverExecutionProfile, Node, ExecutionInfo, String)} + * instead. */ @Deprecated default void onError( @@ -77,6 +96,23 @@ default void onError( @NonNull DriverExecutionProfile executionProfile, @Nullable Node node) {} + /** + * @deprecated This method only exists for backward compatibility. Override {@link + * #onError(Request, Throwable, long, DriverExecutionProfile, Node, ExecutionInfo, String)} + * instead. + */ + @Deprecated + default void onError( + @NonNull Request request, + @NonNull Throwable error, + long latencyNanos, + @NonNull DriverExecutionProfile executionProfile, + @Nullable Node node, + @NonNull String requestLogPrefix) { + // If client doesn't override onError with requestLogPrefix delegate call to the old method + onError(request, error, latencyNanos, executionProfile, node); + } + /** * Invoked each time a request fails. * @@ -84,6 +120,8 @@ default void onError( * GenericType) session.execute} call until the error is propagated to the client). * @param executionProfile the execution profile of this request. * @param node the node that returned the error response, or {@code null} if the error occurred + * @param executionInfo the execution info being returned to the client for this request if + * available * @param requestLogPrefix the dedicated log prefix for this request */ default void onError( @@ -92,14 +130,16 @@ default void onError( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @Nullable Node node, + @Nullable ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { - // If client doesn't override onError with requestLogPrefix delegate call to the old method - onError(request, error, latencyNanos, executionProfile, node); + // delegate call to the old method + onError(request, error, latencyNanos, executionProfile, node, requestLogPrefix); } /** * @deprecated This method only exists for backward compatibility. Override {@link - * #onNodeError(Request, Throwable, long, DriverExecutionProfile, Node, String)} instead. + * #onNodeError(Request, Throwable, long, DriverExecutionProfile, Node, ExecutionInfo, + * String)} instead. */ @Deprecated default void onNodeError( @@ -109,6 +149,23 @@ default void onNodeError( @NonNull DriverExecutionProfile executionProfile, @NonNull Node node) {} + /** + * @deprecated This method only exists for backward compatibility. Override {@link + * #onNodeError(Request, Throwable, long, DriverExecutionProfile, Node, ExecutionInfo, + * String)} instead. + */ + @Deprecated + default void onNodeError( + @NonNull Request request, + @NonNull Throwable error, + long latencyNanos, + @NonNull DriverExecutionProfile executionProfile, + @NonNull Node node, + @NonNull String requestLogPrefix) { + // If client doesn't override onNodeError with requestLogPrefix delegate call to the old method + onNodeError(request, error, latencyNanos, executionProfile, node); + } + /** * Invoked each time a request fails at the node level. Similar to {@link #onError(Request, * Throwable, long, DriverExecutionProfile, Node, String)} but at a per node level. @@ -117,6 +174,7 @@ default void onNodeError( * GenericType) session.execute} call until the error is propagated to the client). * @param executionProfile the execution profile of this request. * @param node the node that returned the error response. + * @param executionInfo the execution info containing the results of this request if available * @param requestLogPrefix the dedicated log prefix for this request */ default void onNodeError( @@ -125,14 +183,16 @@ default void onNodeError( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, + @Nullable ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { // If client doesn't override onNodeError with requestLogPrefix delegate call to the old method - onNodeError(request, error, latencyNanos, executionProfile, node); + onNodeError(request, error, latencyNanos, executionProfile, node, requestLogPrefix); } /** * @deprecated This method only exists for backward compatibility. Override {@link - * #onNodeSuccess(Request, long, DriverExecutionProfile, Node, String)} instead. + * #onNodeSuccess(Request, long, DriverExecutionProfile, Node, ExecutionInfo, String)} + * instead. */ @Deprecated default void onNodeSuccess( @@ -141,6 +201,23 @@ default void onNodeSuccess( @NonNull DriverExecutionProfile executionProfile, @NonNull Node node) {} + /** + * @deprecated This method only exists for backward compatibility. Override {@link + * #onNodeSuccess(Request, long, DriverExecutionProfile, Node, ExecutionInfo, String)} + * instead. + */ + @Deprecated + default void onNodeSuccess( + @NonNull Request request, + long latencyNanos, + @NonNull DriverExecutionProfile executionProfile, + @NonNull Node node, + @NonNull String requestLogPrefix) { + // If client doesn't override onNodeSuccess with requestLogPrefix delegate call to the old + // method + onNodeSuccess(request, latencyNanos, executionProfile, node); + } + /** * Invoked each time a request succeeds at the node level. Similar to {@link #onSuccess(Request, * long, DriverExecutionProfile, Node, String)} but at per node level. @@ -149,6 +226,7 @@ default void onNodeSuccess( * GenericType) session.execute} call until the result is made available to the client). * @param executionProfile the execution profile of this request. * @param node the node that returned the successful response. + * @param executionInfo the execution info containing the results of this request * @param requestLogPrefix the dedicated log prefix for this request */ default void onNodeSuccess( @@ -156,10 +234,10 @@ default void onNodeSuccess( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, + @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { - // If client doesn't override onNodeSuccess with requestLogPrefix delegate call to the old - // method - onNodeSuccess(request, latencyNanos, executionProfile, node); + // delegate call to the old method + onNodeSuccess(request, latencyNanos, executionProfile, node, requestLogPrefix); } /** diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandler.java b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandler.java index 0808bdce63f..a83dc53c655 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandler.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandler.java @@ -335,9 +335,19 @@ private void setFinalResult( totalLatencyNanos = completionTimeNanos - startTimeNanos; long nodeLatencyNanos = completionTimeNanos - callback.nodeStartTimeNanos; requestTracker.onNodeSuccess( - callback.statement, nodeLatencyNanos, executionProfile, callback.node, logPrefix); + callback.statement, + nodeLatencyNanos, + executionProfile, + callback.node, + executionInfo, + logPrefix); requestTracker.onSuccess( - callback.statement, totalLatencyNanos, executionProfile, callback.node, logPrefix); + callback.statement, + totalLatencyNanos, + executionProfile, + callback.node, + executionInfo, + logPrefix); } if (sessionMetricUpdater.isEnabled( DefaultSessionMetric.CQL_REQUESTS, executionProfile.getName())) { @@ -419,27 +429,30 @@ public void onThrottleFailure(@NonNull RequestThrottlingException error) { } private void setFinalError(Statement statement, Throwable error, Node node, int execution) { + DriverExecutionProfile executionProfile = + Conversions.resolveExecutionProfile(statement, context); + ExecutionInfo executionInfo = + new DefaultExecutionInfo( + statement, + node, + startedSpeculativeExecutionsCount.get(), + execution, + errors, + null, + null, + true, + session, + context, + executionProfile); if (error instanceof DriverException) { - ((DriverException) error) - .setExecutionInfo( - new DefaultExecutionInfo( - statement, - node, - startedSpeculativeExecutionsCount.get(), - execution, - errors, - null, - null, - true, - session, - context, - executionProfile)); + ((DriverException) error).setExecutionInfo(executionInfo); } if (result.completeExceptionally(error)) { cancelScheduledTasks(); if (!(requestTracker instanceof NoopRequestTracker)) { long latencyNanos = System.nanoTime() - startTimeNanos; - requestTracker.onError(statement, error, latencyNanos, executionProfile, node, logPrefix); + requestTracker.onError( + statement, error, latencyNanos, executionProfile, node, executionInfo, logPrefix); } if (error instanceof DriverTimeoutException) { throttler.signalTimeout(this); @@ -932,7 +945,21 @@ private void trackNodeError(Node node, Throwable error, long nodeResponseTimeNan nodeResponseTimeNanos = System.nanoTime(); } long latencyNanos = nodeResponseTimeNanos - this.nodeStartTimeNanos; - requestTracker.onNodeError(statement, error, latencyNanos, executionProfile, node, logPrefix); + ExecutionInfo executionInfo = + new DefaultExecutionInfo( + statement, + node, + startedSpeculativeExecutionsCount.get(), + execution, + errors, + null, + null, + true, + session, + context, + executionProfile); + requestTracker.onNodeError( + statement, error, latencyNanos, executionProfile, node, executionInfo, logPrefix); } @Override diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/loadbalancing/DefaultLoadBalancingPolicy.java b/core/src/main/java/com/datastax/oss/driver/internal/core/loadbalancing/DefaultLoadBalancingPolicy.java index 0f03cbb3643..cb0d20214fa 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/loadbalancing/DefaultLoadBalancingPolicy.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/loadbalancing/DefaultLoadBalancingPolicy.java @@ -23,6 +23,7 @@ import com.datastax.oss.driver.api.core.config.DefaultDriverOption; import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; import com.datastax.oss.driver.api.core.context.DriverContext; +import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.metadata.Node; import com.datastax.oss.driver.api.core.session.Request; import com.datastax.oss.driver.api.core.session.Session; @@ -245,6 +246,7 @@ public void onNodeSuccess( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, + @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { updateResponseTimes(node); } @@ -256,6 +258,7 @@ public void onNodeError( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, + @Nullable ExecutionInfo executionInfo, @NonNull String logPrefix) { updateResponseTimes(node); } diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTracker.java b/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTracker.java index d4d20f3eb78..3173a56b1df 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTracker.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTracker.java @@ -18,6 +18,7 @@ package com.datastax.oss.driver.internal.core.tracker; import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; +import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.metadata.Node; import com.datastax.oss.driver.api.core.session.Request; import com.datastax.oss.driver.api.core.session.Session; @@ -82,9 +83,12 @@ public void onSuccess( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, + @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { invokeTrackers( - tracker -> tracker.onSuccess(request, latencyNanos, executionProfile, node, logPrefix), + tracker -> + tracker.onSuccess( + request, latencyNanos, executionProfile, node, executionInfo, logPrefix), logPrefix, "onSuccess"); } @@ -96,9 +100,12 @@ public void onError( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @Nullable Node node, + @Nullable ExecutionInfo executionInfo, @NonNull String logPrefix) { invokeTrackers( - tracker -> tracker.onError(request, error, latencyNanos, executionProfile, node, logPrefix), + tracker -> + tracker.onError( + request, error, latencyNanos, executionProfile, node, executionInfo, logPrefix), logPrefix, "onError"); } @@ -109,9 +116,12 @@ public void onNodeSuccess( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, + @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { invokeTrackers( - tracker -> tracker.onNodeSuccess(request, latencyNanos, executionProfile, node, logPrefix), + tracker -> + tracker.onNodeSuccess( + request, latencyNanos, executionProfile, node, executionInfo, logPrefix), logPrefix, "onNodeSuccess"); } @@ -123,10 +133,12 @@ public void onNodeError( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, + ExecutionInfo executionInfo, @NonNull String logPrefix) { invokeTrackers( tracker -> - tracker.onNodeError(request, error, latencyNanos, executionProfile, node, logPrefix), + tracker.onNodeError( + request, error, latencyNanos, executionProfile, node, executionInfo, logPrefix), logPrefix, "onNodeError"); } diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/NoopRequestTracker.java b/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/NoopRequestTracker.java index 09ac27e5e75..921a1135c03 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/NoopRequestTracker.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/NoopRequestTracker.java @@ -19,10 +19,12 @@ import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; import com.datastax.oss.driver.api.core.context.DriverContext; +import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.metadata.Node; import com.datastax.oss.driver.api.core.session.Request; import com.datastax.oss.driver.api.core.tracker.RequestTracker; import edu.umd.cs.findbugs.annotations.NonNull; +import edu.umd.cs.findbugs.annotations.Nullable; import net.jcip.annotations.ThreadSafe; /** @@ -42,6 +44,7 @@ public void onSuccess( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, + @NonNull ExecutionInfo executionInfo, @NonNull String requestPrefix) { // nothing to do } @@ -53,6 +56,7 @@ public void onError( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, Node node, + @Nullable ExecutionInfo executionInfo, @NonNull String requestPrefix) { // nothing to do } @@ -64,6 +68,7 @@ public void onNodeError( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, + @Nullable ExecutionInfo executionInfo, @NonNull String requestPrefix) { // nothing to do } @@ -74,6 +79,7 @@ public void onNodeSuccess( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, + @NonNull ExecutionInfo executionInfo, @NonNull String requestPrefix) { // nothing to do } diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/RequestLogger.java b/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/RequestLogger.java index 235ef051b40..fa51e281071 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/RequestLogger.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/RequestLogger.java @@ -20,11 +20,13 @@ import com.datastax.oss.driver.api.core.config.DefaultDriverOption; import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; import com.datastax.oss.driver.api.core.context.DriverContext; +import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.metadata.Node; import com.datastax.oss.driver.api.core.session.Request; import com.datastax.oss.driver.api.core.session.SessionBuilder; import com.datastax.oss.driver.api.core.tracker.RequestTracker; import edu.umd.cs.findbugs.annotations.NonNull; +import edu.umd.cs.findbugs.annotations.Nullable; import java.time.Duration; import net.jcip.annotations.ThreadSafe; import org.slf4j.Logger; @@ -86,6 +88,7 @@ public void onSuccess( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, + @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { boolean successEnabled = @@ -139,6 +142,7 @@ public void onError( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, Node node, + @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { if (!executionProfile.getBoolean(DefaultDriverOption.REQUEST_LOGGER_ERROR_ENABLED, false)) { @@ -183,6 +187,7 @@ public void onNodeError( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, + @Nullable ExecutionInfo executionInfo, @NonNull String logPrefix) { // Nothing to do } @@ -193,6 +198,7 @@ public void onNodeSuccess( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, + @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { // Nothing to do } diff --git a/core/src/test/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousCqlRequestHandlerTest.java b/core/src/test/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousCqlRequestHandlerTest.java index a816183e9ee..29709e0b11d 100644 --- a/core/src/test/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousCqlRequestHandlerTest.java +++ b/core/src/test/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousCqlRequestHandlerTest.java @@ -31,6 +31,7 @@ import static org.mockito.ArgumentMatchers.argThat; import static org.mockito.ArgumentMatchers.eq; import static org.mockito.ArgumentMatchers.matches; +import static org.mockito.ArgumentMatchers.nullable; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.never; import static org.mockito.Mockito.verify; @@ -498,6 +499,7 @@ public void should_invoke_request_tracker(DseProtocolVersion version) { anyLong(), any(DriverExecutionProfile.class), eq(node1), + nullable(ExecutionInfo.class), matches(LOG_PREFIX_PER_REQUEST)); verify(requestTracker) .onNodeSuccess( @@ -505,6 +507,7 @@ public void should_invoke_request_tracker(DseProtocolVersion version) { anyLong(), any(DriverExecutionProfile.class), eq(node2), + any(ExecutionInfo.class), matches(LOG_PREFIX_PER_REQUEST)); verify(requestTracker) .onSuccess( @@ -512,6 +515,7 @@ public void should_invoke_request_tracker(DseProtocolVersion version) { anyLong(), any(DriverExecutionProfile.class), eq(node2), + any(ExecutionInfo.class), matches(LOG_PREFIX_PER_REQUEST)); verifyNoMoreInteractions(requestTracker); }); diff --git a/core/src/test/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandlerTest.java b/core/src/test/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandlerTest.java index 9f325003610..09713b4ac6e 100644 --- a/core/src/test/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandlerTest.java +++ b/core/src/test/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandlerTest.java @@ -56,6 +56,7 @@ import com.datastax.oss.driver.api.core.Version; import com.datastax.oss.driver.api.core.config.DefaultDriverOption; import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; +import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.tracker.RequestTracker; import com.datastax.oss.driver.api.core.uuid.Uuids; import com.datastax.oss.driver.internal.core.cql.Conversions; @@ -521,6 +522,7 @@ public void should_invoke_request_tracker_and_update_metrics( anyLong(), any(DriverExecutionProfile.class), eq(node), + any(ExecutionInfo.class), matches(LOG_PREFIX_PER_REQUEST)); verify(requestTracker) .onNodeSuccess( @@ -528,6 +530,7 @@ public void should_invoke_request_tracker_and_update_metrics( anyLong(), any(DriverExecutionProfile.class), eq(node), + any(ExecutionInfo.class), matches(LOG_PREFIX_PER_REQUEST)); verifyNoMoreInteractions(requestTracker); diff --git a/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandlerTrackerTest.java b/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandlerTrackerTest.java index ecc087fb8ac..c5a9d6d4cb2 100644 --- a/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandlerTrackerTest.java +++ b/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandlerTrackerTest.java @@ -21,6 +21,7 @@ import static org.mockito.ArgumentMatchers.any; import static org.mockito.ArgumentMatchers.anyLong; import static org.mockito.ArgumentMatchers.eq; +import static org.mockito.ArgumentMatchers.nullable; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.spy; import static org.mockito.Mockito.verify; @@ -29,6 +30,7 @@ import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; import com.datastax.oss.driver.api.core.cql.AsyncResultSet; +import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.servererrors.BootstrappingException; import com.datastax.oss.driver.api.core.tracker.RequestTracker; import com.datastax.oss.driver.internal.core.tracker.NoopRequestTracker; @@ -38,7 +40,6 @@ import org.junit.Test; public class CqlRequestHandlerTrackerTest extends CqlRequestHandlerTestBase { - @Test public void should_invoke_request_tracker() { try (RequestHandlerTestHarness harness = @@ -72,6 +73,7 @@ public void should_invoke_request_tracker() { anyLong(), any(DriverExecutionProfile.class), eq(node1), + nullable(ExecutionInfo.class), any(String.class)); verify(requestTracker) .onNodeSuccess( @@ -79,6 +81,7 @@ public void should_invoke_request_tracker() { anyLong(), any(DriverExecutionProfile.class), eq(node2), + any(ExecutionInfo.class), any(String.class)); verify(requestTracker) .onSuccess( @@ -86,6 +89,7 @@ public void should_invoke_request_tracker() { anyLong(), any(DriverExecutionProfile.class), eq(node2), + any(ExecutionInfo.class), any(String.class)); verifyNoMoreInteractions(requestTracker); }); diff --git a/core/src/test/java/com/datastax/oss/driver/internal/core/loadbalancing/DefaultLoadBalancingPolicyRequestTrackerTest.java b/core/src/test/java/com/datastax/oss/driver/internal/core/loadbalancing/DefaultLoadBalancingPolicyRequestTrackerTest.java index 757af43ef67..468c92ba0a3 100644 --- a/core/src/test/java/com/datastax/oss/driver/internal/core/loadbalancing/DefaultLoadBalancingPolicyRequestTrackerTest.java +++ b/core/src/test/java/com/datastax/oss/driver/internal/core/loadbalancing/DefaultLoadBalancingPolicyRequestTrackerTest.java @@ -22,6 +22,7 @@ import static org.mockito.BDDMockito.given; import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; +import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.session.Request; import com.datastax.oss.driver.shaded.guava.common.collect.ImmutableMap; import com.datastax.oss.driver.shaded.guava.common.collect.ImmutableSet; @@ -34,6 +35,7 @@ public class DefaultLoadBalancingPolicyRequestTrackerTest extends LoadBalancingP @Mock Request request; @Mock DriverExecutionProfile profile; + @Mock ExecutionInfo executionInfo; final String logPrefix = "lbp-test-log-prefix"; private DefaultLoadBalancingPolicy policy; @@ -65,7 +67,7 @@ public void should_record_first_response_time_on_node_success() { nextNanoTime = 123; // When - policy.onNodeSuccess(request, 0, profile, node1, logPrefix); + policy.onNodeSuccess(request, 0, profile, node1, executionInfo, logPrefix); // Then assertThat(policy.responseTimes) @@ -83,7 +85,7 @@ public void should_record_second_response_time_on_node_success() { nextNanoTime = 456; // When - policy.onNodeSuccess(request, 0, profile, node1, logPrefix); + policy.onNodeSuccess(request, 0, profile, node1, executionInfo, logPrefix); // Then assertThat(policy.responseTimes) @@ -107,8 +109,8 @@ public void should_record_further_response_times_on_node_success() { nextNanoTime = 789; // When - policy.onNodeSuccess(request, 0, profile, node1, logPrefix); - policy.onNodeSuccess(request, 0, profile, node2, logPrefix); + policy.onNodeSuccess(request, 0, profile, node1, executionInfo, logPrefix); + policy.onNodeSuccess(request, 0, profile, node2, executionInfo, logPrefix); // Then assertThat(policy.responseTimes) @@ -133,7 +135,7 @@ public void should_record_first_response_time_on_node_error() { Throwable iae = new IllegalArgumentException(); // When - policy.onNodeError(request, iae, 0, profile, node1, logPrefix); + policy.onNodeError(request, iae, 0, profile, node1, executionInfo, logPrefix); // Then assertThat(policy.responseTimes) @@ -152,7 +154,7 @@ public void should_record_second_response_time_on_node_error() { Throwable iae = new IllegalArgumentException(); // When - policy.onNodeError(request, iae, 0, profile, node1, logPrefix); + policy.onNodeError(request, iae, 0, profile, node1, executionInfo, logPrefix); // Then assertThat(policy.responseTimes) @@ -177,8 +179,8 @@ public void should_record_further_response_times_on_node_error() { Throwable iae = new IllegalArgumentException(); // When - policy.onNodeError(request, iae, 0, profile, node1, logPrefix); - policy.onNodeError(request, iae, 0, profile, node2, logPrefix); + policy.onNodeError(request, iae, 0, profile, node1, executionInfo, logPrefix); + policy.onNodeError(request, iae, 0, profile, node2, executionInfo, logPrefix); // Then assertThat(policy.responseTimes) diff --git a/core/src/test/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTrackerTest.java b/core/src/test/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTrackerTest.java index 8dcad99b459..adbad606712 100644 --- a/core/src/test/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTrackerTest.java +++ b/core/src/test/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTrackerTest.java @@ -28,6 +28,7 @@ import ch.qos.logback.core.Appender; import com.datastax.oss.driver.api.core.DriverExecutionException; import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; +import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.metadata.Node; import com.datastax.oss.driver.api.core.session.Request; import com.datastax.oss.driver.api.core.session.Session; @@ -51,6 +52,7 @@ public class MultiplexingRequestTrackerTest { @Mock private DriverExecutionProfile profile; @Mock private Node node; @Mock private Session session; + @Mock private ExecutionInfo executionInfo; @Mock private Appender appender; @Captor private ArgumentCaptor loggingEventCaptor; @@ -111,12 +113,12 @@ public void should_notify_onSuccess() { MultiplexingRequestTracker tracker = new MultiplexingRequestTracker(child1, child2); willThrow(new NullPointerException()) .given(child1) - .onSuccess(request, 123456L, profile, node, "test"); + .onSuccess(request, 123456L, profile, node, executionInfo, "test"); // when - tracker.onSuccess(request, 123456L, profile, node, "test"); + tracker.onSuccess(request, 123456L, profile, node, executionInfo, "test"); // then - verify(child1).onSuccess(request, 123456L, profile, node, "test"); - verify(child2).onSuccess(request, 123456L, profile, node, "test"); + verify(child1).onSuccess(request, 123456L, profile, node, executionInfo, "test"); + verify(child2).onSuccess(request, 123456L, profile, node, executionInfo, "test"); verify(appender).doAppend(loggingEventCaptor.capture()); assertThat(loggingEventCaptor.getAllValues().stream().map(ILoggingEvent::getFormattedMessage)) .contains( @@ -129,12 +131,12 @@ public void should_notify_onError() { MultiplexingRequestTracker tracker = new MultiplexingRequestTracker(child1, child2); willThrow(new NullPointerException()) .given(child1) - .onError(request, error, 123456L, profile, node, "test"); + .onError(request, error, 123456L, profile, node, executionInfo, "test"); // when - tracker.onError(request, error, 123456L, profile, node, "test"); + tracker.onError(request, error, 123456L, profile, node, executionInfo, "test"); // then - verify(child1).onError(request, error, 123456L, profile, node, "test"); - verify(child2).onError(request, error, 123456L, profile, node, "test"); + verify(child1).onError(request, error, 123456L, profile, node, executionInfo, "test"); + verify(child2).onError(request, error, 123456L, profile, node, executionInfo, "test"); verify(appender).doAppend(loggingEventCaptor.capture()); assertThat(loggingEventCaptor.getAllValues().stream().map(ILoggingEvent::getFormattedMessage)) .contains( @@ -147,12 +149,12 @@ public void should_notify_onNodeSuccess() { MultiplexingRequestTracker tracker = new MultiplexingRequestTracker(child1, child2); willThrow(new NullPointerException()) .given(child1) - .onNodeSuccess(request, 123456L, profile, node, "test"); + .onNodeSuccess(request, 123456L, profile, node, executionInfo, "test"); // when - tracker.onNodeSuccess(request, 123456L, profile, node, "test"); + tracker.onNodeSuccess(request, 123456L, profile, node, executionInfo, "test"); // then - verify(child1).onNodeSuccess(request, 123456L, profile, node, "test"); - verify(child2).onNodeSuccess(request, 123456L, profile, node, "test"); + verify(child1).onNodeSuccess(request, 123456L, profile, node, executionInfo, "test"); + verify(child2).onNodeSuccess(request, 123456L, profile, node, executionInfo, "test"); verify(appender).doAppend(loggingEventCaptor.capture()); assertThat(loggingEventCaptor.getAllValues().stream().map(ILoggingEvent::getFormattedMessage)) .contains( @@ -165,12 +167,12 @@ public void should_notify_onNodeError() { MultiplexingRequestTracker tracker = new MultiplexingRequestTracker(child1, child2); willThrow(new NullPointerException()) .given(child1) - .onNodeError(request, error, 123456L, profile, node, "test"); + .onNodeError(request, error, 123456L, profile, node, executionInfo, "test"); // when - tracker.onNodeError(request, error, 123456L, profile, node, "test"); + tracker.onNodeError(request, error, 123456L, profile, node, executionInfo, "test"); // then - verify(child1).onNodeError(request, error, 123456L, profile, node, "test"); - verify(child2).onNodeError(request, error, 123456L, profile, node, "test"); + verify(child1).onNodeError(request, error, 123456L, profile, node, executionInfo, "test"); + verify(child2).onNodeError(request, error, 123456L, profile, node, executionInfo, "test"); verify(appender).doAppend(loggingEventCaptor.capture()); assertThat(loggingEventCaptor.getAllValues().stream().map(ILoggingEvent::getFormattedMessage)) .contains( diff --git a/integration-tests/src/test/java/com/datastax/oss/driver/core/tracker/RequestNodeLoggerExample.java b/integration-tests/src/test/java/com/datastax/oss/driver/core/tracker/RequestNodeLoggerExample.java index eae98339637..f22475b5aca 100644 --- a/integration-tests/src/test/java/com/datastax/oss/driver/core/tracker/RequestNodeLoggerExample.java +++ b/integration-tests/src/test/java/com/datastax/oss/driver/core/tracker/RequestNodeLoggerExample.java @@ -20,11 +20,13 @@ import com.datastax.oss.driver.api.core.config.DefaultDriverOption; import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; import com.datastax.oss.driver.api.core.context.DriverContext; +import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.metadata.Node; import com.datastax.oss.driver.api.core.session.Request; import com.datastax.oss.driver.internal.core.tracker.RequestLogFormatter; import com.datastax.oss.driver.internal.core.tracker.RequestLogger; import edu.umd.cs.findbugs.annotations.NonNull; +import edu.umd.cs.findbugs.annotations.Nullable; public class RequestNodeLoggerExample extends RequestLogger { @@ -39,6 +41,7 @@ public void onNodeError( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, + @Nullable ExecutionInfo executionInfo, @NonNull String logPrefix) { if (!executionProfile.getBoolean(DefaultDriverOption.REQUEST_LOGGER_ERROR_ENABLED)) { return; @@ -75,6 +78,7 @@ public void onNodeSuccess( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, + @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { boolean successEnabled = executionProfile.getBoolean(DefaultDriverOption.REQUEST_LOGGER_SUCCESS_ENABLED); From d5a79a74a06cdd59ada5c72368a56203f84e0dbb Mon Sep 17 00:00:00 2001 From: Lukasz Antoniak Date: Fri, 7 Jun 2024 13:01:46 +0200 Subject: [PATCH 2/4] Add ExecutionInfo to RequestTracker callbacks --- .../api/core/graph/GraphExecutionInfo.java | 8 + .../ContinuousRequestHandlerBase.java | 32 +-- .../graph/GraphExecutionInfoConverter.java | 11 + .../core/graph/GraphRequestHandler.java | 52 ++--- .../driver/api/core/cql/ExecutionInfo.java | 7 + .../api/core/tracker/RequestTracker.java | 211 +++++++++--------- .../internal/core/cql/CqlRequestHandler.java | 203 +++++++++-------- .../core/cql/DefaultExecutionInfo.java | 96 +++++++- .../cql/CqlRequestHandlerTrackerTest.java | 30 +++ 9 files changed, 393 insertions(+), 257 deletions(-) diff --git a/core/src/main/java/com/datastax/dse/driver/api/core/graph/GraphExecutionInfo.java b/core/src/main/java/com/datastax/dse/driver/api/core/graph/GraphExecutionInfo.java index 758f6b358ed..c10fdf1ce3c 100644 --- a/core/src/main/java/com/datastax/dse/driver/api/core/graph/GraphExecutionInfo.java +++ b/core/src/main/java/com/datastax/dse/driver/api/core/graph/GraphExecutionInfo.java @@ -18,8 +18,10 @@ package com.datastax.dse.driver.api.core.graph; import com.datastax.oss.driver.api.core.DefaultProtocolVersion; +import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; import com.datastax.oss.driver.api.core.metadata.Node; import com.datastax.oss.driver.api.core.specex.SpeculativeExecutionPolicy; +import edu.umd.cs.findbugs.annotations.Nullable; import java.nio.ByteBuffer; import java.util.List; import java.util.Map; @@ -37,6 +39,12 @@ public interface GraphExecutionInfo { /** The statement that was executed. */ GraphStatement getStatement(); + /** @return Execution profile applied when executing given request. */ + @Nullable + default DriverExecutionProfile getExecutionProfile() { + return null; + } + /** The node that was used as a coordinator to successfully complete the query. */ Node getCoordinator(); diff --git a/core/src/main/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousRequestHandlerBase.java b/core/src/main/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousRequestHandlerBase.java index 303b05c9843..e55b4be1748 100644 --- a/core/src/main/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousRequestHandlerBase.java +++ b/core/src/main/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousRequestHandlerBase.java @@ -834,7 +834,8 @@ public void onFailure(@NonNull Throwable error) { private void processResultResponse(@NonNull Result result, @Nullable Frame frame) { assert lock.isHeldByCurrentThread(); try { - ExecutionInfo executionInfo = createExecutionInfo(result, frame); + ExecutionInfo executionInfo = + createExecutionInfo().withServerResponse(result, frame).build(); if (result instanceof Rows) { DseRowsMetadata rowsMetadata = (DseRowsMetadata) ((Rows) result).getMetadata(); if (columnDefinitions == null) { @@ -1459,7 +1460,7 @@ private void trackNodeError( latencyNanos, executionProfile, node, - createExecutionInfo(frame), + createExecutionInfo().withServerResponse(frame).build(), logPrefix); } } @@ -1577,7 +1578,7 @@ private void completeResultSetFuture( ExecutionInfo executionInfo = null; if (pageOrError instanceof AsyncPagingIterable) { - executionInfo = ((AsyncPagingIterable) pageOrError).getExecutionInfo(); + executionInfo = ((AsyncPagingIterable) pageOrError).getExecutionInfo(); } else if (pageOrError instanceof AsyncGraphResultSet) { executionInfo = ((AsyncGraphResultSet) pageOrError).getRequestExecutionInfo(); } @@ -1613,34 +1614,13 @@ private void completeResultSetFuture( } @NonNull - private ExecutionInfo createExecutionInfo(@NonNull Result result, @Nullable Frame response) { - ByteBuffer pagingState = - result instanceof Rows ? ((Rows) result).getMetadata().pagingState : null; - return new DefaultExecutionInfo( + private DefaultExecutionInfo.Builder createExecutionInfo() { + return DefaultExecutionInfo.builder( statement, node, startedSpeculativeExecutionsCount.get(), executionIndex, errors, - pagingState, - response, - true, - session, - context, - executionProfile); - } - - @NonNull - private ExecutionInfo createExecutionInfo(@Nullable Frame response) { - return new DefaultExecutionInfo( - statement, - node, - startedSpeculativeExecutionsCount.get(), - executionIndex, - errors, - null, - response, - true, session, context, executionProfile); diff --git a/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphExecutionInfoConverter.java b/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphExecutionInfoConverter.java index b6472f690d3..7500c26d691 100644 --- a/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphExecutionInfoConverter.java +++ b/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphExecutionInfoConverter.java @@ -18,6 +18,7 @@ package com.datastax.dse.driver.internal.core.graph; import com.datastax.dse.driver.api.core.graph.GraphStatement; +import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.cql.QueryTrace; import com.datastax.oss.driver.api.core.cql.Statement; @@ -62,6 +63,11 @@ public Statement getStatement() { throw new ClassCastException("GraphStatement cannot be cast to Statement"); } + @Override + public DriverExecutionProfile getExecutionProfile() { + return graphExecutionInfo.getExecutionProfile(); + } + @Nullable @Override public Node getCoordinator() { @@ -146,6 +152,11 @@ public GraphStatement getStatement() { return (GraphStatement) executionInfo.getRequest(); } + @Override + public DriverExecutionProfile getExecutionProfile() { + return executionInfo.getExecutionProfile(); + } + @Override public Node getCoordinator() { return executionInfo.getCoordinator(); diff --git a/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandler.java b/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandler.java index 6c78c343fdd..1cb69d2ec9d 100644 --- a/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandler.java +++ b/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandler.java @@ -330,7 +330,18 @@ private void cancelScheduledTasks() { private void setFinalResult( Result resultMessage, Frame responseFrame, NodeResponseCallback callback) { try { - ExecutionInfo executionInfo = buildExecutionInfo(callback, responseFrame); + ExecutionInfo executionInfo = + DefaultExecutionInfo.builder( + callback.statement, + callback.node, + startedSpeculativeExecutionsCount.get(), + callback.execution, + errors, + session, + context, + callback.executionProfile) + .withServerResponse(resultMessage, responseFrame) + .build(); DriverExecutionProfile executionProfile = Conversions.resolveExecutionProfile(callback.statement, context); GraphProtocol subProtocol = @@ -427,23 +438,6 @@ private void logServerWarnings(GraphStatement statement, List warning LOG.warn("Query '{}' generated server side warning(s): {}", statementString, warning)); } - private ExecutionInfo buildExecutionInfo(NodeResponseCallback callback, Frame responseFrame) { - DriverExecutionProfile executionProfile = - Conversions.resolveExecutionProfile(callback.statement, context); - return new DefaultExecutionInfo( - callback.statement, - callback.node, - startedSpeculativeExecutionsCount.get(), - callback.execution, - errors, - null, - responseFrame, - true, - session, - context, - executionProfile); - } - @Override public void onThrottleFailure(@NonNull RequestThrottlingException error) { DriverExecutionProfile executionProfile = @@ -458,18 +452,16 @@ private void setFinalError( DriverExecutionProfile executionProfile = Conversions.resolveExecutionProfile(statement, context); ExecutionInfo executionInfo = - new DefaultExecutionInfo( - statement, - node, - startedSpeculativeExecutionsCount.get(), - execution, - errors, - null, - null, - true, - session, - context, - executionProfile); + DefaultExecutionInfo.builder( + statement, + node, + startedSpeculativeExecutionsCount.get(), + execution, + errors, + session, + context, + executionProfile) + .build(); if (error instanceof DriverException) { ((DriverException) error).setExecutionInfo(executionInfo); } diff --git a/core/src/main/java/com/datastax/oss/driver/api/core/cql/ExecutionInfo.java b/core/src/main/java/com/datastax/oss/driver/api/core/cql/ExecutionInfo.java index 40cfca827d1..43e1f2515b2 100644 --- a/core/src/main/java/com/datastax/oss/driver/api/core/cql/ExecutionInfo.java +++ b/core/src/main/java/com/datastax/oss/driver/api/core/cql/ExecutionInfo.java @@ -21,6 +21,7 @@ import com.datastax.oss.driver.api.core.DriverException; import com.datastax.oss.driver.api.core.RequestThrottlingException; import com.datastax.oss.driver.api.core.config.DefaultDriverOption; +import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; import com.datastax.oss.driver.api.core.detach.AttachmentPoint; import com.datastax.oss.driver.api.core.metadata.Node; import com.datastax.oss.driver.api.core.retry.RetryDecision; @@ -66,6 +67,12 @@ default Request getRequest() { @Deprecated Statement getStatement(); + /** @return Execution profile applied when executing given request. */ + @Nullable + default DriverExecutionProfile getExecutionProfile() { + return null; + } + /** * The node that acted as a coordinator for the query. * diff --git a/core/src/main/java/com/datastax/oss/driver/api/core/tracker/RequestTracker.java b/core/src/main/java/com/datastax/oss/driver/api/core/tracker/RequestTracker.java index a3988f360f4..bf623d3de9c 100644 --- a/core/src/main/java/com/datastax/oss/driver/api/core/tracker/RequestTracker.java +++ b/core/src/main/java/com/datastax/oss/driver/api/core/tracker/RequestTracker.java @@ -37,33 +37,52 @@ public interface RequestTracker extends AutoCloseable { /** - * @deprecated This method only exists for backward compatibility. Override {@link - * #onSuccess(Request, long, DriverExecutionProfile, Node, ExecutionInfo, String)} instead. + * Invoked each time a request succeeds. + * + * @param latencyNanos the overall execution time (from the {@link Session#execute(Request, + * GenericType) session.execute} call until the result is made available to the client). + * @param executionProfile the execution profile of this request. + * @param node the node that returned the successful response. + * @param executionInfo the execution info containing the results of this request + * @param requestLogPrefix the dedicated log prefix for this request */ - @Deprecated default void onSuccess( @NonNull Request request, long latencyNanos, @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node) {} + @NonNull Node node, + @NonNull ExecutionInfo executionInfo, + @NonNull String requestLogPrefix) { + // delegate call to the old method + onSuccess(request, latencyNanos, executionProfile, node, requestLogPrefix); + } /** - * @deprecated This method only exists for backward compatibility. Override {@link - * #onSuccess(Request, long, DriverExecutionProfile, Node, ExecutionInfo, String)} instead. + * Invoked each time a request fails. + * + * @param latencyNanos the overall execution time (from the {@link Session#execute(Request, + * GenericType) session.execute} call until the error is propagated to the client). + * @param executionProfile the execution profile of this request. + * @param node the node that returned the error response, or {@code null} if the error occurred + * @param executionInfo the execution info being returned to the client for this request if + * available + * @param requestLogPrefix the dedicated log prefix for this request */ - @Deprecated - default void onSuccess( + default void onError( @NonNull Request request, + @NonNull Throwable error, long latencyNanos, @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, + @Nullable Node node, + @Nullable ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { - // If client doesn't override onSuccess with requestLogPrefix delegate call to the old method - onSuccess(request, latencyNanos, executionProfile, node); + // delegate call to the old method + onError(request, error, latencyNanos, executionProfile, node, requestLogPrefix); } /** - * Invoked each time a request succeeds. + * Invoked each time a request succeeds at the node level. Similar to {@link #onSuccess(Request, + * long, DriverExecutionProfile, Node, String)} but at per node level. * * @param latencyNanos the overall execution time (from the {@link Session#execute(Request, * GenericType) session.execute} call until the result is made available to the client). @@ -72,29 +91,88 @@ default void onSuccess( * @param executionInfo the execution info containing the results of this request * @param requestLogPrefix the dedicated log prefix for this request */ - default void onSuccess( + default void onNodeSuccess( @NonNull Request request, long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { - // If client doesn't override onSuccess with executionInfo delegate call to the old method - onSuccess(request, latencyNanos, executionProfile, node, requestLogPrefix); + // delegate call to the old method + onNodeSuccess(request, latencyNanos, executionProfile, node, requestLogPrefix); + } + + /** + * Invoked each time a request fails at the node level. Similar to {@link #onError(Request, + * Throwable, long, DriverExecutionProfile, Node, String)} but at a per node level. + * + * @param latencyNanos the overall execution time (from the {@link Session#execute(Request, + * GenericType) session.execute} call until the error is propagated to the client). + * @param executionProfile the execution profile of this request. + * @param node the node that returned the error response. + * @param executionInfo the execution info containing the results of this request if available + * @param requestLogPrefix the dedicated log prefix for this request + */ + default void onNodeError( + @NonNull Request request, + @NonNull Throwable error, + long latencyNanos, + @NonNull DriverExecutionProfile executionProfile, + @NonNull Node node, + @Nullable ExecutionInfo executionInfo, + @NonNull String requestLogPrefix) { + // delegate call to the old method + onNodeError(request, error, latencyNanos, executionProfile, node, requestLogPrefix); } + /** + * Invoked when the session is ready to process user requests. + * + *

WARNING: if you use {@code session.execute()} in your tracker implementation, keep in + * mind that those requests will in turn recurse back into {@code onSuccess} / {@code onError} + * methods. Make sure you don't trigger an infinite loop; one way to do that is to use a + * custom execution profile for internal requests. + * + *

This corresponds to the moment when {@link SessionBuilder#build()} returns, or the future + * returned by {@link SessionBuilder#buildAsync()} completes. If the session initialization fails, + * this method will not get called. + * + *

Listener methods are invoked from different threads; if you store the session in a field, + * make it at least volatile to guarantee proper publication. + * + *

This method is guaranteed to be the first one invoked on this object. + * + *

The default implementation is empty. + */ + default void onSessionReady(@NonNull Session session) {} + + // ----- Below methods have been deprecated and will be removed in next releases ----- + /** * @deprecated This method only exists for backward compatibility. Override {@link - * #onError(Request, Throwable, long, DriverExecutionProfile, Node, ExecutionInfo, String)} - * instead. + * #onSuccess(Request, long, DriverExecutionProfile, Node, ExecutionInfo, String)} instead. */ @Deprecated - default void onError( + default void onSuccess( @NonNull Request request, - @NonNull Throwable error, long latencyNanos, @NonNull DriverExecutionProfile executionProfile, - @Nullable Node node) {} + @NonNull Node node) {} + + /** + * @deprecated This method only exists for backward compatibility. Override {@link + * #onSuccess(Request, long, DriverExecutionProfile, Node, ExecutionInfo, String)} instead. + */ + @Deprecated + default void onSuccess( + @NonNull Request request, + long latencyNanos, + @NonNull DriverExecutionProfile executionProfile, + @NonNull Node node, + @NonNull String requestLogPrefix) { + // delegate call to the old method + onSuccess(request, latencyNanos, executionProfile, node); + } /** * @deprecated This method only exists for backward compatibility. Override {@link @@ -107,33 +185,23 @@ default void onError( @NonNull Throwable error, long latencyNanos, @NonNull DriverExecutionProfile executionProfile, - @Nullable Node node, - @NonNull String requestLogPrefix) { - // If client doesn't override onError with requestLogPrefix delegate call to the old method - onError(request, error, latencyNanos, executionProfile, node); - } + @Nullable Node node) {} /** - * Invoked each time a request fails. - * - * @param latencyNanos the overall execution time (from the {@link Session#execute(Request, - * GenericType) session.execute} call until the error is propagated to the client). - * @param executionProfile the execution profile of this request. - * @param node the node that returned the error response, or {@code null} if the error occurred - * @param executionInfo the execution info being returned to the client for this request if - * available - * @param requestLogPrefix the dedicated log prefix for this request + * @deprecated This method only exists for backward compatibility. Override {@link + * #onError(Request, Throwable, long, DriverExecutionProfile, Node, ExecutionInfo, String)} + * instead. */ + @Deprecated default void onError( @NonNull Request request, @NonNull Throwable error, long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @Nullable Node node, - @Nullable ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { // delegate call to the old method - onError(request, error, latencyNanos, executionProfile, node, requestLogPrefix); + onError(request, error, latencyNanos, executionProfile, node); } /** @@ -162,33 +230,10 @@ default void onNodeError( @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, @NonNull String requestLogPrefix) { - // If client doesn't override onNodeError with requestLogPrefix delegate call to the old method + // delegate call to the old method onNodeError(request, error, latencyNanos, executionProfile, node); } - /** - * Invoked each time a request fails at the node level. Similar to {@link #onError(Request, - * Throwable, long, DriverExecutionProfile, Node, String)} but at a per node level. - * - * @param latencyNanos the overall execution time (from the {@link Session#execute(Request, - * GenericType) session.execute} call until the error is propagated to the client). - * @param executionProfile the execution profile of this request. - * @param node the node that returned the error response. - * @param executionInfo the execution info containing the results of this request if available - * @param requestLogPrefix the dedicated log prefix for this request - */ - default void onNodeError( - @NonNull Request request, - @NonNull Throwable error, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @Nullable ExecutionInfo executionInfo, - @NonNull String requestLogPrefix) { - // If client doesn't override onNodeError with requestLogPrefix delegate call to the old method - onNodeError(request, error, latencyNanos, executionProfile, node, requestLogPrefix); - } - /** * @deprecated This method only exists for backward compatibility. Override {@link * #onNodeSuccess(Request, long, DriverExecutionProfile, Node, ExecutionInfo, String)} @@ -213,51 +258,7 @@ default void onNodeSuccess( @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, @NonNull String requestLogPrefix) { - // If client doesn't override onNodeSuccess with requestLogPrefix delegate call to the old - // method - onNodeSuccess(request, latencyNanos, executionProfile, node); - } - - /** - * Invoked each time a request succeeds at the node level. Similar to {@link #onSuccess(Request, - * long, DriverExecutionProfile, Node, String)} but at per node level. - * - * @param latencyNanos the overall execution time (from the {@link Session#execute(Request, - * GenericType) session.execute} call until the result is made available to the client). - * @param executionProfile the execution profile of this request. - * @param node the node that returned the successful response. - * @param executionInfo the execution info containing the results of this request - * @param requestLogPrefix the dedicated log prefix for this request - */ - default void onNodeSuccess( - @NonNull Request request, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @NonNull ExecutionInfo executionInfo, - @NonNull String requestLogPrefix) { // delegate call to the old method - onNodeSuccess(request, latencyNanos, executionProfile, node, requestLogPrefix); + onNodeSuccess(request, latencyNanos, executionProfile, node); } - - /** - * Invoked when the session is ready to process user requests. - * - *

WARNING: if you use {@code session.execute()} in your tracker implementation, keep in - * mind that those requests will in turn recurse back into {@code onSuccess} / {@code onError} - * methods. Make sure you don't trigger an infinite loop; one way to do that is to use a - * custom execution profile for internal requests. - * - *

This corresponds to the moment when {@link SessionBuilder#build()} returns, or the future - * returned by {@link SessionBuilder#buildAsync()} completes. If the session initialization fails, - * this method will not get called. - * - *

Listener methods are invoked from different threads; if you store the session in a field, - * make it at least volatile to guarantee proper publication. - * - *

This method is guaranteed to be the first one invoked on this object. - * - *

The default implementation is empty. - */ - default void onSessionReady(@NonNull Session session) {} } diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandler.java b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandler.java index a83dc53c655..63e6ee0a916 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandler.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandler.java @@ -66,7 +66,6 @@ import com.datastax.oss.protocol.internal.response.Error; import com.datastax.oss.protocol.internal.response.Result; import com.datastax.oss.protocol.internal.response.error.Unprepared; -import com.datastax.oss.protocol.internal.response.result.Rows; import com.datastax.oss.protocol.internal.response.result.SchemaChange; import com.datastax.oss.protocol.internal.response.result.SetKeyspace; import com.datastax.oss.protocol.internal.response.result.Void; @@ -206,12 +205,12 @@ private Timeout scheduleTimeout(Duration timeoutDuration) { if (timeoutDuration.toNanos() > 0) { try { return this.timer.newTimeout( - (Timeout timeout1) -> - setFinalError( - initialStatement, - new DriverTimeoutException("Query timed out after " + timeoutDuration), - null, - -1), + (Timeout timeout1) -> { + ExecutionInfo executionInfo = failedExecutionInfoNoRequestSent().build(); + setFinalError( + executionInfo, + new DriverTimeoutException("Query timed out after " + timeoutDuration)); + }, timeoutDuration.toNanos(), TimeUnit.NANOSECONDS); } catch (IllegalStateException e) { @@ -264,7 +263,8 @@ private void sendRequest( // We've reached the end of the query plan without finding any node to write to if (!result.isDone() && activeExecutionsCount.decrementAndGet() == 0) { // We're the last execution so fail the result - setFinalError(statement, AllNodesFailedException.fromErrors(this.errors), null, -1); + ExecutionInfo executionInfo = failedExecutionInfoNoRequestSent(statement).build(); + setFinalError(executionInfo, AllNodesFailedException.fromErrors(this.errors)); } } else { NodeResponseCallback nodeResponseCallback = @@ -319,7 +319,10 @@ private void setFinalResult( NodeResponseCallback callback) { try { ExecutionInfo executionInfo = - buildExecutionInfo(callback, resultMessage, responseFrame, schemaInAgreement); + defaultExecutionInfo(callback) + .withServerResponse(resultMessage, responseFrame) + .withSchemaInAgreement(schemaInAgreement) + .build(); AsyncResultSet resultSet = Conversions.toResultSet(resultMessage, executionInfo, session, context); if (result.complete(resultSet)) { @@ -369,7 +372,9 @@ private void setFinalResult( logServerWarnings(callback.statement, executionProfile, executionInfo.getWarnings()); } } catch (Throwable error) { - setFinalError(callback.statement, error, callback.node, -1); + // something unpredictable unexpected happened here that we can't blame on the request itself + ExecutionInfo executionInfo = defaultExecutionInfo(callback, -1).build(); + setFinalError(executionInfo, error); } } @@ -400,50 +405,15 @@ private void logServerWarnings( LOG.warn("Query '{}' generated server side warning(s): {}", statementString, warning)); } - private ExecutionInfo buildExecutionInfo( - NodeResponseCallback callback, - Result resultMessage, - Frame responseFrame, - boolean schemaInAgreement) { - ByteBuffer pagingState = - (resultMessage instanceof Rows) ? ((Rows) resultMessage).getMetadata().pagingState : null; - return new DefaultExecutionInfo( - callback.statement, - callback.node, - startedSpeculativeExecutionsCount.get(), - callback.execution, - errors, - pagingState, - responseFrame, - schemaInAgreement, - session, - context, - executionProfile); - } - @Override public void onThrottleFailure(@NonNull RequestThrottlingException error) { sessionMetricUpdater.incrementCounter( DefaultSessionMetric.THROTTLING_ERRORS, executionProfile.getName()); - setFinalError(initialStatement, error, null, -1); + ExecutionInfo executionInfo = failedExecutionInfoNoRequestSent().build(); + setFinalError(executionInfo, error); } - private void setFinalError(Statement statement, Throwable error, Node node, int execution) { - DriverExecutionProfile executionProfile = - Conversions.resolveExecutionProfile(statement, context); - ExecutionInfo executionInfo = - new DefaultExecutionInfo( - statement, - node, - startedSpeculativeExecutionsCount.get(), - execution, - errors, - null, - null, - true, - session, - context, - executionProfile); + private void setFinalError(ExecutionInfo executionInfo, Throwable error) { if (error instanceof DriverException) { ((DriverException) error).setExecutionInfo(executionInfo); } @@ -452,12 +422,19 @@ private void setFinalError(Statement statement, Throwable error, Node node, i if (!(requestTracker instanceof NoopRequestTracker)) { long latencyNanos = System.nanoTime() - startTimeNanos; requestTracker.onError( - statement, error, latencyNanos, executionProfile, node, executionInfo, logPrefix); + executionInfo.getRequest(), + error, + latencyNanos, + executionInfo.getExecutionProfile(), + executionInfo.getCoordinator(), + executionInfo, + logPrefix); } if (error instanceof DriverTimeoutException) { throttler.signalTimeout(this); sessionMetricUpdater.incrementCounter( - DefaultSessionMetric.CQL_CLIENT_TIMEOUTS, executionProfile.getName()); + DefaultSessionMetric.CQL_CLIENT_TIMEOUTS, + executionInfo.getExecutionProfile().getName()); } else if (!(error instanceof RequestThrottlingException)) { throttler.signalError(this, error); } @@ -505,23 +482,25 @@ private NodeResponseCallback( this.logPrefix = logPrefix + "|" + execution; } - // this gets invoked once the write completes. + // this gets invoked once the write request completes. @Override public void operationComplete(Future future) throws Exception { if (!future.isSuccess()) { Throwable error = future.cause(); + ExecutionInfo executionInfo = CqlRequestHandler.this.defaultExecutionInfo(this).build(); if (error instanceof EncoderException && error.getCause() instanceof FrameTooLongException) { - trackNodeError(node, error.getCause(), NANOTIME_NOT_MEASURED_YET); - setFinalError(statement, error.getCause(), node, execution); + trackNodeError(error.getCause(), executionInfo, NANOTIME_NOT_MEASURED_YET); + setFinalError(executionInfo, error.getCause()); } else { LOG.trace( "[{}] Failed to send request on {}, trying next node (cause: {})", logPrefix, channel, + error.getMessage(), error); recordError(node, error); - trackNodeError(node, error, NANOTIME_NOT_MEASURED_YET); + trackNodeError(error, executionInfo, NANOTIME_NOT_MEASURED_YET); ((DefaultNode) node) .getMetricUpdater() .incrementCounter(DefaultNodeMetric.UNSENT_REQUESTS, executionProfile.getName()); @@ -657,19 +636,18 @@ public void onResponse(Frame responseFrame) { LOG.trace("[{}] Got error response, processing", logPrefix); processErrorResponse((Error) responseMessage); } else { + ExecutionInfo executionInfo = defaultExecutionInfo().build(); trackNodeError( - node, new IllegalStateException("Unexpected response " + responseMessage), + executionInfo, nodeResponseTimeNanos); setFinalError( - statement, - new IllegalStateException("Unexpected response " + responseMessage), - node, - execution); + executionInfo, new IllegalStateException("Unexpected response " + responseMessage)); } } catch (Throwable t) { - trackNodeError(node, t, nodeResponseTimeNanos); - setFinalError(statement, t, node, execution); + ExecutionInfo executionInfo = defaultExecutionInfo().build(); + trackNodeError(t, executionInfo, nodeResponseTimeNanos); + setFinalError(executionInfo, t); } } @@ -703,6 +681,7 @@ private void processErrorResponse(Error errorMessage) { .start() .handle( (repreparedId, exception) -> { + ExecutionInfo executionInfo = defaultExecutionInfo().build(); if (exception != null) { // If the error is not recoverable, surface it to the client instead of retrying if (exception instanceof UnexpectedResponseException) { @@ -715,18 +694,18 @@ private void processErrorResponse(Error errorMessage) { || prepareError instanceof FunctionFailureException || prepareError instanceof ProtocolError) { LOG.trace("[{}] Unrecoverable error on reprepare, rethrowing", logPrefix); - trackNodeError(node, prepareError, NANOTIME_NOT_MEASURED_YET); - setFinalError(statement, prepareError, node, execution); + trackNodeError(prepareError, executionInfo, NANOTIME_NOT_MEASURED_YET); + setFinalError(executionInfo, prepareError); return null; } } } else if (exception instanceof RequestThrottlingException) { - trackNodeError(node, exception, NANOTIME_NOT_MEASURED_YET); - setFinalError(statement, exception, node, execution); + trackNodeError(exception, executionInfo, NANOTIME_NOT_MEASURED_YET); + setFinalError(executionInfo, exception); return null; } recordError(node, exception); - trackNodeError(node, exception, NANOTIME_NOT_MEASURED_YET); + trackNodeError(exception, executionInfo, NANOTIME_NOT_MEASURED_YET); LOG.trace("[{}] Reprepare failed, trying next node", logPrefix); sendRequest(statement, null, queryPlan, execution, retryCount, false); } else { @@ -740,8 +719,9 @@ private void processErrorResponse(Error errorMessage) { + "the statement was prepared.", Bytes.toHexString(idToReprepare), Bytes.toHexString(repreparedId))); - trackNodeError(node, illegalStateException, NANOTIME_NOT_MEASURED_YET); - setFinalError(statement, illegalStateException, node, execution); + trackNodeError( + illegalStateException, executionInfo, NANOTIME_NOT_MEASURED_YET); + setFinalError(executionInfo, illegalStateException); } LOG.trace("[{}] Reprepare sucessful, retrying", logPrefix); sendRequest(statement, node, queryPlan, execution, retryCount, false); @@ -754,16 +734,18 @@ private void processErrorResponse(Error errorMessage) { NodeMetricUpdater metricUpdater = ((DefaultNode) node).getMetricUpdater(); if (error instanceof BootstrappingException) { LOG.trace("[{}] {} is bootstrapping, trying next node", logPrefix, node); + ExecutionInfo executionInfo = defaultExecutionInfo().build(); recordError(node, error); - trackNodeError(node, error, NANOTIME_NOT_MEASURED_YET); + trackNodeError(error, executionInfo, NANOTIME_NOT_MEASURED_YET); sendRequest(statement, null, queryPlan, execution, retryCount, false); } else if (error instanceof QueryValidationException || error instanceof FunctionFailureException || error instanceof ProtocolError) { LOG.trace("[{}] Unrecoverable error, rethrowing", logPrefix); metricUpdater.incrementCounter(DefaultNodeMetric.OTHER_ERRORS, executionProfile.getName()); - trackNodeError(node, error, NANOTIME_NOT_MEASURED_YET); - setFinalError(statement, error, node, execution); + ExecutionInfo executionInfo = defaultExecutionInfo().build(); + trackNodeError(error, executionInfo, NANOTIME_NOT_MEASURED_YET); + setFinalError(executionInfo, error); } else { RetryPolicy retryPolicy = Conversions.resolveRetryPolicy(context, executionProfile); RetryVerdict verdict; @@ -834,10 +816,11 @@ private void processErrorResponse(Error errorMessage) { private void processRetryVerdict(RetryVerdict verdict, Throwable error) { LOG.trace("[{}] Processing retry decision {}", logPrefix, verdict); + ExecutionInfo executionInfo = defaultExecutionInfo().build(); switch (verdict.getRetryDecision()) { case RETRY_SAME: recordError(node, error); - trackNodeError(node, error, NANOTIME_NOT_MEASURED_YET); + trackNodeError(error, executionInfo, NANOTIME_NOT_MEASURED_YET); sendRequest( verdict.getRetryRequest(statement), node, @@ -848,7 +831,7 @@ private void processRetryVerdict(RetryVerdict verdict, Throwable error) { break; case RETRY_NEXT: recordError(node, error); - trackNodeError(node, error, NANOTIME_NOT_MEASURED_YET); + trackNodeError(error, executionInfo, NANOTIME_NOT_MEASURED_YET); sendRequest( verdict.getRetryRequest(statement), null, @@ -858,8 +841,8 @@ private void processRetryVerdict(RetryVerdict verdict, Throwable error) { false); break; case RETHROW: - trackNodeError(node, error, NANOTIME_NOT_MEASURED_YET); - setFinalError(statement, error, node, execution); + trackNodeError(error, executionInfo, NANOTIME_NOT_MEASURED_YET); + setFinalError(executionInfo, error); break; case IGNORE: setFinalResult(Void.INSTANCE, null, true, this); @@ -885,7 +868,7 @@ private void updateErrorMetrics( metricUpdater.incrementCounter(ignoresOnError, executionProfile.getName()); break; case RETHROW: - // nothing do do + // nothing to do } } @@ -905,11 +888,10 @@ public void onFailure(Throwable error) { RetryPolicy retryPolicy = Conversions.resolveRetryPolicy(context, executionProfile); verdict = retryPolicy.onRequestAbortedVerdict(statement, error, retryCount); } catch (Throwable cause) { + ExecutionInfo executionInfo = defaultExecutionInfo().build(); setFinalError( - statement, - new IllegalStateException("Unexpected error while invoking the retry policy", cause), - null, - execution); + executionInfo, + new IllegalStateException("Unexpected error while invoking the retry policy", cause)); return; } } @@ -937,7 +919,8 @@ public void cancel() { * measured. If {@link #NANOTIME_NOT_MEASURED_YET}, it hasn't and we need to measure it now * (this is to avoid unnecessary calls to System.nanoTime) */ - private void trackNodeError(Node node, Throwable error, long nodeResponseTimeNanos) { + private void trackNodeError( + Throwable error, ExecutionInfo executionInfo, long nodeResponseTimeNanos) { if (requestTracker instanceof NoopRequestTracker) { return; } @@ -945,21 +928,18 @@ private void trackNodeError(Node node, Throwable error, long nodeResponseTimeNan nodeResponseTimeNanos = System.nanoTime(); } long latencyNanos = nodeResponseTimeNanos - this.nodeStartTimeNanos; - ExecutionInfo executionInfo = - new DefaultExecutionInfo( - statement, - node, - startedSpeculativeExecutionsCount.get(), - execution, - errors, - null, - null, - true, - session, - context, - executionProfile); requestTracker.onNodeError( - statement, error, latencyNanos, executionProfile, node, executionInfo, logPrefix); + statement, + error, + latencyNanos, + executionProfile, + executionInfo.getCoordinator(), + executionInfo, + logPrefix); + } + + private DefaultExecutionInfo.Builder defaultExecutionInfo() { + return CqlRequestHandler.this.defaultExecutionInfo(this, execution); } @Override @@ -967,4 +947,37 @@ public String toString() { return logPrefix; } } + + private DefaultExecutionInfo.Builder defaultExecutionInfo(NodeResponseCallback callback) { + return defaultExecutionInfo(callback, callback.execution); + } + + private DefaultExecutionInfo.Builder defaultExecutionInfo( + NodeResponseCallback callback, int execution) { + return new DefaultExecutionInfo.Builder( + callback.statement, + callback.node, + startedSpeculativeExecutionsCount.get(), + execution, + errors, + session, + context, + executionProfile); + } + + private DefaultExecutionInfo.Builder failedExecutionInfoNoRequestSent() { + return failedExecutionInfoNoRequestSent(initialStatement); + } + + private DefaultExecutionInfo.Builder failedExecutionInfoNoRequestSent(Statement statement) { + return new DefaultExecutionInfo.Builder( + statement, + null, + startedSpeculativeExecutionsCount.get(), + -1, + errors, + session, + context, + executionProfile); + } } diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/DefaultExecutionInfo.java b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/DefaultExecutionInfo.java index 3ab57ddc598..1dd4354d6e6 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/DefaultExecutionInfo.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/DefaultExecutionInfo.java @@ -28,6 +28,8 @@ import com.datastax.oss.driver.internal.core.session.DefaultSession; import com.datastax.oss.driver.internal.core.util.concurrent.CompletableFutures; import com.datastax.oss.protocol.internal.Frame; +import com.datastax.oss.protocol.internal.response.Result; +import com.datastax.oss.protocol.internal.response.result.Rows; import edu.umd.cs.findbugs.annotations.NonNull; import edu.umd.cs.findbugs.annotations.Nullable; import java.nio.ByteBuffer; @@ -57,7 +59,7 @@ public class DefaultExecutionInfo implements ExecutionInfo { private final InternalDriverContext context; private final DriverExecutionProfile executionProfile; - public DefaultExecutionInfo( + private DefaultExecutionInfo( Request request, Node coordinator, int speculativeExecutionCount, @@ -102,6 +104,11 @@ public Request getRequest() { return request; } + @Override + public DriverExecutionProfile getExecutionProfile() { + return executionProfile; + } + @Nullable @Override public Node getCoordinator() { @@ -189,4 +196,91 @@ public int getResponseSizeInBytes() { public int getCompressedResponseSizeInBytes() { return compressedResponseSizeInBytes; } + + public static Builder builder( + Request request, + Node coordinator, + int speculativeExecutionCount, + int successfulExecutionIndex, + List> errors, + DefaultSession session, + InternalDriverContext context, + DriverExecutionProfile executionProfile) { + return new Builder( + request, + coordinator, + speculativeExecutionCount, + successfulExecutionIndex, + errors, + session, + context, + executionProfile); + } + + public static class Builder { + private final Request request; + private final Node coordinator; + private final int speculativeExecutionCount; + private final int successfulExecutionIndex; + private final List> errors; + private final DefaultSession session; + private final InternalDriverContext context; + private final DriverExecutionProfile executionProfile; + + private Result response; + private Frame frame; + private boolean schemaInAgreement = true; + + public Builder( + Request request, + Node coordinator, + int speculativeExecutionCount, + int successfulExecutionIndex, + List> errors, + DefaultSession session, + InternalDriverContext context, + DriverExecutionProfile executionProfile) { + this.request = request; + this.coordinator = coordinator; + this.speculativeExecutionCount = speculativeExecutionCount; + this.successfulExecutionIndex = successfulExecutionIndex; + this.errors = errors; + this.session = session; + this.context = context; + this.executionProfile = executionProfile; + } + + public Builder withServerResponse(Result response, Frame frame) { + this.response = response; + this.frame = frame; + return this; + } + + /** Client received a response, but it could not be parsed to expected message. */ + public Builder withServerResponse(Frame frame) { + return withServerResponse(null, frame); + } + + public Builder withSchemaInAgreement(boolean schemaInAgreement) { + this.schemaInAgreement = schemaInAgreement; + return this; + } + + public DefaultExecutionInfo build() { + final ByteBuffer pagingState = + (response instanceof Rows) ? ((Rows) response).getMetadata().pagingState : null; + return new DefaultExecutionInfo( + request, + coordinator, + speculativeExecutionCount, + successfulExecutionIndex, + errors, + pagingState, + frame, + schemaInAgreement, + session, + context, + executionProfile); + } + } } diff --git a/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandlerTrackerTest.java b/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandlerTrackerTest.java index c5a9d6d4cb2..533fe3be87a 100644 --- a/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandlerTrackerTest.java +++ b/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandlerTrackerTest.java @@ -18,11 +18,13 @@ package com.datastax.oss.driver.internal.core.cql; import static com.datastax.oss.driver.Assertions.assertThatStage; +import static org.assertj.core.api.Assertions.assertThat; import static org.mockito.ArgumentMatchers.any; import static org.mockito.ArgumentMatchers.anyLong; import static org.mockito.ArgumentMatchers.eq; import static org.mockito.ArgumentMatchers.nullable; import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.mockingDetails; import static org.mockito.Mockito.spy; import static org.mockito.Mockito.verify; import static org.mockito.Mockito.verifyNoMoreInteractions; @@ -31,13 +33,18 @@ import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; import com.datastax.oss.driver.api.core.cql.AsyncResultSet; import com.datastax.oss.driver.api.core.cql.ExecutionInfo; +import com.datastax.oss.driver.api.core.metadata.Node; import com.datastax.oss.driver.api.core.servererrors.BootstrappingException; +import com.datastax.oss.driver.api.core.session.Request; import com.datastax.oss.driver.api.core.tracker.RequestTracker; import com.datastax.oss.driver.internal.core.tracker.NoopRequestTracker; import com.datastax.oss.protocol.internal.ProtocolConstants; import com.datastax.oss.protocol.internal.response.Error; +import java.util.ArrayList; +import java.util.List; import java.util.concurrent.CompletionStage; import org.junit.Test; +import org.mockito.invocation.Invocation; public class CqlRequestHandlerTrackerTest extends CqlRequestHandlerTestBase { @Test @@ -93,9 +100,32 @@ public void should_invoke_request_tracker() { any(String.class)); verifyNoMoreInteractions(requestTracker); }); + + // verify that passed ExecutionInfo object had correct details + List invocations = + new ArrayList<>(mockingDetails(requestTracker).getInvocations()); + checkExecutionInfo( + (ExecutionInfo) invocations.get(0).getRawArguments()[5], + UNDEFINED_IDEMPOTENCE_STATEMENT, + node1); + checkExecutionInfo( + (ExecutionInfo) invocations.get(1).getRawArguments()[4], + UNDEFINED_IDEMPOTENCE_STATEMENT, + node2); + checkExecutionInfo( + (ExecutionInfo) invocations.get(2).getRawArguments()[4], + UNDEFINED_IDEMPOTENCE_STATEMENT, + node2); } } + private void checkExecutionInfo( + ExecutionInfo executionInfo, Request expectedRequest, Node expectedNode) { + assertThat(executionInfo.getRequest()).isEqualTo(expectedRequest); + assertThat(executionInfo.getExecutionProfile()).isNotNull(); + assertThat(executionInfo.getCoordinator()).isEqualTo(expectedNode); + } + @Test public void should_not_invoke_noop_request_tracker() { try (RequestHandlerTestHarness harness = From 81ecc8c4089068bc45daf05ac7d117567accf1da Mon Sep 17 00:00:00 2001 From: Lukasz Antoniak Date: Wed, 4 Sep 2024 12:02:44 +0200 Subject: [PATCH 3/4] JAVA-3046: Extend RequestTracker interface for observability Co-authored-by: Andrew Tolbert <6889771+tolbertam@users.noreply.github.com> --- .../ContinuousRequestHandlerBase.java | 7 +- .../core/graph/GraphRequestHandler.java | 2 + .../driver/api/core/cql/ExecutionInfo.java | 5 + .../api/core/tracker/RequestTracker.java | 28 ++ .../driver/internal/core/cql/Conversions.java | 5 + .../internal/core/cql/CqlPrepareHandler.java | 125 +++++- .../internal/core/cql/CqlRequestHandler.java | 357 ++++++++++++------ .../core/cql/DefaultExecutionInfo.java | 15 + .../tracker/MultiplexingRequestTracker.java | 26 +- .../core/cql/CqlPrepareHandlerTest.java | 71 +--- .../core/cql/CqlPrepareHandlerTestBase.java | 97 +++++ .../cql/CqlPrepareHandlerTrackerTest.java | 134 +++++++ .../cql/CqlRequestHandlerTrackerTest.java | 164 +++++++- .../core/cql/PagingIterableSpliteratorIT.java | 159 +++++++- .../driver/core/tracker/RequestLoggerIT.java | 4 +- 15 files changed, 986 insertions(+), 213 deletions(-) create mode 100644 core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandlerTestBase.java create mode 100644 core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandlerTrackerTest.java diff --git a/core/src/main/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousRequestHandlerBase.java b/core/src/main/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousRequestHandlerBase.java index e55b4be1748..530e59b5a32 100644 --- a/core/src/main/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousRequestHandlerBase.java +++ b/core/src/main/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousRequestHandlerBase.java @@ -835,7 +835,7 @@ private void processResultResponse(@NonNull Result result, @Nullable Frame frame assert lock.isHeldByCurrentThread(); try { ExecutionInfo executionInfo = - createExecutionInfo().withServerResponse(result, frame).build(); + createExecutionInfo(null).withServerResponse(result, frame).build(); if (result instanceof Rows) { DseRowsMetadata rowsMetadata = (DseRowsMetadata) ((Rows) result).getMetadata(); if (columnDefinitions == null) { @@ -1460,7 +1460,7 @@ private void trackNodeError( latencyNanos, executionProfile, node, - createExecutionInfo().withServerResponse(frame).build(), + createExecutionInfo(error).withServerResponse(frame).build(), logPrefix); } } @@ -1614,12 +1614,13 @@ private void completeResultSetFuture( } @NonNull - private DefaultExecutionInfo.Builder createExecutionInfo() { + private DefaultExecutionInfo.Builder createExecutionInfo(Throwable error) { return DefaultExecutionInfo.builder( statement, node, startedSpeculativeExecutionsCount.get(), executionIndex, + error, errors, session, context, diff --git a/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandler.java b/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandler.java index 1cb69d2ec9d..ad57604726f 100644 --- a/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandler.java +++ b/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandler.java @@ -336,6 +336,7 @@ private void setFinalResult( callback.node, startedSpeculativeExecutionsCount.get(), callback.execution, + null, errors, session, context, @@ -457,6 +458,7 @@ private void setFinalError( node, startedSpeculativeExecutionsCount.get(), execution, + error, errors, session, context, diff --git a/core/src/main/java/com/datastax/oss/driver/api/core/cql/ExecutionInfo.java b/core/src/main/java/com/datastax/oss/driver/api/core/cql/ExecutionInfo.java index 43e1f2515b2..b38183b84fb 100644 --- a/core/src/main/java/com/datastax/oss/driver/api/core/cql/ExecutionInfo.java +++ b/core/src/main/java/com/datastax/oss/driver/api/core/cql/ExecutionInfo.java @@ -120,6 +120,11 @@ default DriverExecutionProfile getExecutionProfile() { @NonNull List> getErrors(); + @Nullable + default Throwable getDriverError() { + return null; + } + /** * The paging state of the query, in its raw form. * diff --git a/core/src/main/java/com/datastax/oss/driver/api/core/tracker/RequestTracker.java b/core/src/main/java/com/datastax/oss/driver/api/core/tracker/RequestTracker.java index bf623d3de9c..2964539f29c 100644 --- a/core/src/main/java/com/datastax/oss/driver/api/core/tracker/RequestTracker.java +++ b/core/src/main/java/com/datastax/oss/driver/api/core/tracker/RequestTracker.java @@ -36,6 +36,33 @@ */ public interface RequestTracker extends AutoCloseable { + /** + * Invoked each time new request is created. + * + * @param request the request to be executed + * @param executionProfile the execution profile of this request + * @param requestLogPrefix the dedicated log prefix for this request + */ + default void onRequestCreated( + @NonNull Request request, + @NonNull DriverExecutionProfile executionProfile, + @NonNull String requestLogPrefix) {} + + /** + * Invoked each time a new request is created and sent to next node. Due to retry policy, this + * method can be triggered multiple times while processing one logical request. + * + * @param request the request to be executed + * @param executionProfile the execution profile of this request + * @param node the node which will receive the request + * @param requestLogPrefix the dedicated log prefix for this request + */ + default void onRequestCreatedForNode( + @NonNull Request request, + @NonNull DriverExecutionProfile executionProfile, + @NonNull Node node, + @NonNull String requestLogPrefix) {} + /** * Invoked each time a request succeeds. * @@ -71,6 +98,7 @@ default void onSuccess( default void onError( @NonNull Request request, @NonNull Throwable error, + // TODO: Shall we expose start and end timestamp so that users do not need to call nanoTime()? long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @Nullable Node node, diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/Conversions.java b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/Conversions.java index ff9384b3e24..0afb182b365 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/Conversions.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/Conversions.java @@ -74,6 +74,7 @@ import com.datastax.oss.protocol.internal.ProtocolConstants; import com.datastax.oss.protocol.internal.request.Batch; import com.datastax.oss.protocol.internal.request.Execute; +import com.datastax.oss.protocol.internal.request.Prepare; import com.datastax.oss.protocol.internal.request.Query; import com.datastax.oss.protocol.internal.request.query.QueryOptions; import com.datastax.oss.protocol.internal.response.Error; @@ -359,6 +360,10 @@ public static ColumnDefinitions getResultDefinitions( } } + public static PrepareRequest toPrepareRequest(Prepare request) { + return new DefaultPrepareRequest(SimpleStatement.newInstance(request.cqlQuery)); + } + public static DefaultPreparedStatement toPreparedStatement( Prepared response, PrepareRequest request, InternalDriverContext context) { ColumnDefinitions variableDefinitions = diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandler.java b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandler.java index 1ee1f303ab2..44f6490d594 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandler.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandler.java @@ -25,6 +25,7 @@ import com.datastax.oss.driver.api.core.RequestThrottlingException; import com.datastax.oss.driver.api.core.config.DefaultDriverOption; import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; +import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.cql.PrepareRequest; import com.datastax.oss.driver.api.core.cql.PreparedStatement; import com.datastax.oss.driver.api.core.metadata.Node; @@ -37,8 +38,10 @@ import com.datastax.oss.driver.api.core.servererrors.FunctionFailureException; import com.datastax.oss.driver.api.core.servererrors.ProtocolError; import com.datastax.oss.driver.api.core.servererrors.QueryValidationException; +import com.datastax.oss.driver.api.core.session.Request; import com.datastax.oss.driver.api.core.session.throttling.RequestThrottler; import com.datastax.oss.driver.api.core.session.throttling.Throttled; +import com.datastax.oss.driver.api.core.tracker.RequestTracker; import com.datastax.oss.driver.internal.core.DefaultProtocolFeature; import com.datastax.oss.driver.internal.core.ProtocolVersionRegistry; import com.datastax.oss.driver.internal.core.adminrequest.ThrottledAdminRequestHandler; @@ -46,6 +49,7 @@ import com.datastax.oss.driver.internal.core.channel.ResponseCallback; import com.datastax.oss.driver.internal.core.context.InternalDriverContext; import com.datastax.oss.driver.internal.core.session.DefaultSession; +import com.datastax.oss.driver.internal.core.tracker.NoopRequestTracker; import com.datastax.oss.driver.internal.core.util.Loggers; import com.datastax.oss.driver.internal.core.util.concurrent.CompletableFutures; import com.datastax.oss.protocol.internal.Frame; @@ -90,6 +94,7 @@ public class CqlPrepareHandler implements Throttled { protected final CompletableFuture result; private final Timer timer; private final Timeout scheduledTimeout; + private final RequestTracker requestTracker; private final RequestThrottler throttler; private final Boolean prepareOnAllNodes; private final DriverExecutionProfile executionProfile; @@ -112,7 +117,7 @@ protected CqlPrepareHandler( this.initialRequest = request; this.session = session; this.context = context; - executionProfile = Conversions.resolveExecutionProfile(request, context); + this.executionProfile = Conversions.resolveExecutionProfile(request, context); this.queryPlan = context .getLoadBalancingPolicyWrapper() @@ -137,14 +142,15 @@ protected CqlPrepareHandler( this.scheduledTimeout = scheduleTimeout(timeout); this.prepareOnAllNodes = executionProfile.getBoolean(DefaultDriverOption.PREPARE_ON_ALL_NODES); + this.requestTracker = context.getRequestTracker(); + trackStart(); + this.throttler = context.getRequestThrottler(); this.throttler.register(this); } @Override public void onThrottleReady(boolean wasDelayed) { - DriverExecutionProfile executionProfile = - Conversions.resolveExecutionProfile(initialRequest, context); if (wasDelayed) { session .getMetricUpdater() @@ -165,7 +171,8 @@ private Timeout scheduleTimeout(Duration timeoutDuration) { if (timeoutDuration.toNanos() > 0) { return this.timer.newTimeout( (Timeout timeout1) -> { - setFinalError(new DriverTimeoutException("Query timed out after " + timeoutDuration)); + setFinalError( + new DriverTimeoutException("Query timed out after " + timeoutDuration), null); if (initialCallback != null) { initialCallback.cancel(); } @@ -199,13 +206,12 @@ private void sendRequest(PrepareRequest request, Node node, int retryCount) { } } if (channel == null) { - setFinalError(AllNodesFailedException.fromErrors(this.errors)); + setFinalError(AllNodesFailedException.fromErrors(this.errors), node); } else { InitialPrepareCallback initialPrepareCallback = new InitialPrepareCallback(request, node, channel, retryCount); - Prepare message = toPrepareMessage(request); - + trackNodeStart(request, node); channel .write(message, false, request.getCustomPayload(), initialPrepareCallback) .addListener(initialPrepareCallback); @@ -226,7 +232,7 @@ private Prepare toPrepareMessage(PrepareRequest request) { } private void recordError(Node node, Throwable error) { - // Use a local variable to do only a single single volatile read in the nominal case + // Use a local variable to do only a single volatile read in the nominal case List> errorsSnapshot = this.errors; if (errorsSnapshot == null) { synchronized (CqlPrepareHandler.this) { @@ -239,7 +245,8 @@ private void recordError(Node node, Throwable error) { errorsSnapshot.add(new AbstractMap.SimpleEntry<>(node, error)); } - private void setFinalResult(PrepareRequest request, Prepared response) { + private void setFinalResult( + PrepareRequest request, Prepared response, InitialPrepareCallback callback) { // Whatever happens below, we're done with this stream id throttler.signalSuccess(this); @@ -247,6 +254,8 @@ private void setFinalResult(PrepareRequest request, Prepared response) { DefaultPreparedStatement preparedStatement = Conversions.toPreparedStatement(response, request, context); + trackNodeEnd(request, callback.node, null, callback.nodeStartTimeNanos); + session .getRepreparePayloads() .put(preparedStatement.getId(), preparedStatement.getRepreparePayload()); @@ -257,15 +266,18 @@ private void setFinalResult(PrepareRequest request, Prepared response) { LOG.trace( "[{}] Done repreparing on other nodes, completing the request", logPrefix); result.complete(preparedStatement); + trackEnd(callback.node, null); }) .exceptionally( error -> { result.completeExceptionally(error); + trackEnd(callback.node, error); return null; }); } else { LOG.trace("[{}] Prepare on all nodes is disabled, completing the request", logPrefix); result.complete(preparedStatement); + trackEnd(callback.node, null); } } @@ -298,15 +310,19 @@ private CompletionStage prepareOnOtherNode(PrepareRequest request, Node no throttler, session.getMetricUpdater(), logPrefix); + long nodeStartTimeNanos = System.nanoTime(); + trackNodeStart(request, node); return handler .start() .handle( (result, error) -> { if (error == null) { LOG.trace("[{}] Successfully reprepared on {}", logPrefix, node); + trackNodeEnd(request, node, null, nodeStartTimeNanos); } else { Loggers.warnWithException( LOG, "[{}] Error while repreparing on {}", node, logPrefix, error); + trackNodeEnd(request, node, error, nodeStartTimeNanos); } return null; }); @@ -320,12 +336,13 @@ public void onThrottleFailure(@NonNull RequestThrottlingException error) { session .getMetricUpdater() .incrementCounter(DefaultSessionMetric.THROTTLING_ERRORS, executionProfile.getName()); - setFinalError(error); + setFinalError(error, null); } - private void setFinalError(Throwable error) { + private void setFinalError(Throwable error, Node node) { if (result.completeExceptionally(error)) { cancelTimeout(); + trackEnd(node, error); if (error instanceof DriverTimeoutException) { throttler.signalTimeout(this); } else if (!(error instanceof RequestThrottlingException)) { @@ -336,6 +353,7 @@ private void setFinalError(Throwable error) { private class InitialPrepareCallback implements ResponseCallback, GenericFutureListener> { + private final long nodeStartTimeNanos = System.nanoTime(); private final PrepareRequest request; private final Node node; private final DriverChannel channel; @@ -361,6 +379,7 @@ public void operationComplete(Future future) { node, future.cause().toString()); recordError(node, future.cause()); + trackNodeEnd(request, node, future.cause(), nodeStartTimeNanos); sendRequest(request, null, retryCount); // try next host } else { if (result.isDone()) { @@ -382,15 +401,15 @@ public void onResponse(Frame responseFrame) { Message responseMessage = responseFrame.message; if (responseMessage instanceof Prepared) { LOG.trace("[{}] Got result, completing", logPrefix); - setFinalResult(request, (Prepared) responseMessage); + setFinalResult(request, (Prepared) responseMessage, this); } else if (responseMessage instanceof Error) { LOG.trace("[{}] Got error response, processing", logPrefix); processErrorResponse((Error) responseMessage); } else { - setFinalError(new IllegalStateException("Unexpected response " + responseMessage)); + setFinalError(new IllegalStateException("Unexpected response " + responseMessage), node); } } catch (Throwable t) { - setFinalError(t); + setFinalError(t, node); } } @@ -404,20 +423,21 @@ private void processErrorResponse(Error errorMessage) { || errorMessage.code == ProtocolConstants.ErrorCode.UNAVAILABLE || errorMessage.code == ProtocolConstants.ErrorCode.TRUNCATE_ERROR) { setFinalError( - new IllegalStateException( - "Unexpected server error for a PREPARE query" + errorMessage)); + new IllegalStateException("Unexpected server error for a PREPARE query" + errorMessage), + node); return; } CoordinatorException error = Conversions.toThrowable(node, errorMessage, context); if (error instanceof BootstrappingException) { LOG.trace("[{}] {} is bootstrapping, trying next node", logPrefix, node); recordError(node, error); + trackNodeEnd(request, node, error, nodeStartTimeNanos); sendRequest(request, null, retryCount); } else if (error instanceof QueryValidationException || error instanceof FunctionFailureException || error instanceof ProtocolError) { LOG.trace("[{}] Unrecoverable error, rethrowing", logPrefix); - setFinalError(error); + setFinalError(error, node); } else { // Because prepare requests are known to always be idempotent, we call the retry policy // directly, without checking the flag. @@ -433,20 +453,24 @@ private void processRetryVerdict(RetryVerdict verdict, Throwable error) { switch (decision) { case RETRY_SAME: recordError(node, error); + trackNodeEnd(request, node, error, nodeStartTimeNanos); sendRequest(verdict.getRetryRequest(request), node, retryCount + 1); break; case RETRY_NEXT: recordError(node, error); + trackNodeEnd(request, node, error, nodeStartTimeNanos); sendRequest(verdict.getRetryRequest(request), null, retryCount + 1); break; case RETHROW: - setFinalError(error); + trackNodeEnd(request, node, error, nodeStartTimeNanos); + setFinalError(error, node); break; case IGNORE: setFinalError( new IllegalArgumentException( "IGNORE decisions are not allowed for prepare requests, " - + "please fix your retry policy.")); + + "please fix your retry policy."), + node); break; } } @@ -463,7 +487,8 @@ public void onFailure(Throwable error) { verdict = retryPolicy.onRequestAbortedVerdict(request, error, retryCount); } catch (Throwable cause) { setFinalError( - new IllegalStateException("Unexpected error while invoking the retry policy", cause)); + new IllegalStateException("Unexpected error while invoking the retry policy", cause), + node); return; } processRetryVerdict(verdict, error); @@ -484,4 +509,64 @@ public String toString() { return logPrefix; } } + + /** Notify request tracker that processing of initial statement starts. */ + private void trackStart() { + if (requestTracker instanceof NoopRequestTracker) { + return; + } + requestTracker.onRequestCreated(initialRequest, executionProfile, logPrefix); + } + + /** + * Notify request tracker that processing of statement starts at a given node. Statement is passed + * as a separate parameter, because it might have been changed by custom retry policy. + */ + private void trackNodeStart(Request request, Node node) { + if (requestTracker instanceof NoopRequestTracker) { + return; + } + requestTracker.onRequestCreatedForNode(request, executionProfile, node, logPrefix); + } + + /** Notify request tracker that processing of statement has been completed by a given node. */ + private void trackNodeEnd(Request request, Node node, Throwable error, long startTimeNanos) { + if (requestTracker instanceof NoopRequestTracker) { + return; + } + long latencyNanos = System.nanoTime() - startTimeNanos; + ExecutionInfo executionInfo = defaultExecutionInfo(request, node, error).build(); + if (error == null) { + requestTracker.onNodeSuccess( + request, latencyNanos, executionProfile, node, executionInfo, logPrefix); + } else { + requestTracker.onNodeError( + request, error, latencyNanos, executionProfile, node, executionInfo, logPrefix); + } + } + + /** + * Notify request tracker that processing of initial statement has been completed (successfully or + * with error). + */ + private void trackEnd(Node node, Throwable error) { + if (requestTracker instanceof NoopRequestTracker) { + return; + } + long latencyNanos = System.nanoTime() - this.startTimeNanos; + ExecutionInfo executionInfo = defaultExecutionInfo(initialRequest, node, error).build(); + if (error == null) { + requestTracker.onSuccess( + initialRequest, latencyNanos, executionProfile, node, executionInfo, logPrefix); + } else { + requestTracker.onError( + initialRequest, error, latencyNanos, executionProfile, node, executionInfo, logPrefix); + } + } + + private DefaultExecutionInfo.Builder defaultExecutionInfo( + Request statement, Node node, Throwable error) { + return new DefaultExecutionInfo.Builder( + statement, node, -1, 0, error, null, session, context, executionProfile); + } } diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandler.java b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandler.java index 63e6ee0a916..ae218a31033 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandler.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandler.java @@ -28,6 +28,7 @@ import com.datastax.oss.driver.api.core.connection.FrameTooLongException; import com.datastax.oss.driver.api.core.cql.AsyncResultSet; import com.datastax.oss.driver.api.core.cql.ExecutionInfo; +import com.datastax.oss.driver.api.core.cql.PrepareRequest; import com.datastax.oss.driver.api.core.cql.Statement; import com.datastax.oss.driver.api.core.metadata.Node; import com.datastax.oss.driver.api.core.metrics.DefaultNodeMetric; @@ -42,6 +43,7 @@ import com.datastax.oss.driver.api.core.servererrors.ReadTimeoutException; import com.datastax.oss.driver.api.core.servererrors.UnavailableException; import com.datastax.oss.driver.api.core.servererrors.WriteTimeoutException; +import com.datastax.oss.driver.api.core.session.Request; import com.datastax.oss.driver.api.core.session.throttling.RequestThrottler; import com.datastax.oss.driver.api.core.session.throttling.Throttled; import com.datastax.oss.driver.api.core.tracker.RequestTracker; @@ -99,6 +101,7 @@ public class CqlRequestHandler implements Throttled { private static final long NANOTIME_NOT_MEASURED_YET = -1; private final long startTimeNanos; + private long endTimeNanos = NANOTIME_NOT_MEASURED_YET; private final String logPrefix; private final Statement initialStatement; private final DefaultSession session; @@ -172,6 +175,7 @@ protected CqlRequestHandler( Duration timeout = Conversions.resolveRequestTimeout(statement, executionProfile); this.scheduledTimeout = scheduleTimeout(timeout); + trackStart(); this.throttler = context.getRequestThrottler(); this.throttler.register(this); } @@ -206,10 +210,11 @@ private Timeout scheduleTimeout(Duration timeoutDuration) { try { return this.timer.newTimeout( (Timeout timeout1) -> { - ExecutionInfo executionInfo = failedExecutionInfoNoRequestSent().build(); - setFinalError( - executionInfo, - new DriverTimeoutException("Query timed out after " + timeoutDuration)); + DriverTimeoutException timeoutException = + new DriverTimeoutException("Query timed out after " + timeoutDuration); + ExecutionInfo executionInfo = + failedExecutionInfoNoRequestSent(timeoutException).build(); + setFinalError(executionInfo, timeoutException); }, timeoutDuration.toNanos(), TimeUnit.NANOSECONDS); @@ -263,7 +268,7 @@ private void sendRequest( // We've reached the end of the query plan without finding any node to write to if (!result.isDone() && activeExecutionsCount.decrementAndGet() == 0) { // We're the last execution so fail the result - ExecutionInfo executionInfo = failedExecutionInfoNoRequestSent(statement).build(); + ExecutionInfo executionInfo = failedExecutionInfoNoRequestSent(statement, null).build(); setFinalError(executionInfo, AllNodesFailedException.fromErrors(this.errors)); } } else { @@ -278,6 +283,7 @@ private void sendRequest( scheduleNextExecution, logPrefix); Message message = Conversions.toMessage(statement, executionProfile, context); + trackNodeStart(statement, node, nodeResponseCallback.logPrefix); channel .write(message, statement.isTracing(), statement.getCustomPayload(), nodeResponseCallback) .addListener(nodeResponseCallback); @@ -285,7 +291,7 @@ private void sendRequest( } private void recordError(Node node, Throwable error) { - // Use a local variable to do only a single single volatile read in the nominal case + // Use a local variable to do only a single volatile read in the nominal case List> errorsSnapshot = this.errors; if (errorsSnapshot == null) { synchronized (CqlRequestHandler.this) { @@ -319,7 +325,7 @@ private void setFinalResult( NodeResponseCallback callback) { try { ExecutionInfo executionInfo = - defaultExecutionInfo(callback) + defaultExecutionInfo(callback, null) .withServerResponse(resultMessage, responseFrame) .withSchemaInAgreement(schemaInAgreement) .build(); @@ -329,35 +335,15 @@ private void setFinalResult( cancelScheduledTasks(); throttler.signalSuccess(this); - // Only call nanoTime() if we're actually going to use it - long completionTimeNanos = NANOTIME_NOT_MEASURED_YET, - totalLatencyNanos = NANOTIME_NOT_MEASURED_YET; - - if (!(requestTracker instanceof NoopRequestTracker)) { - completionTimeNanos = System.nanoTime(); - totalLatencyNanos = completionTimeNanos - startTimeNanos; - long nodeLatencyNanos = completionTimeNanos - callback.nodeStartTimeNanos; - requestTracker.onNodeSuccess( - callback.statement, - nodeLatencyNanos, - executionProfile, - callback.node, - executionInfo, - logPrefix); - requestTracker.onSuccess( - callback.statement, - totalLatencyNanos, - executionProfile, - callback.node, - executionInfo, - logPrefix); - } + long endTimeNanos = trackNodeEnd(callback, executionInfo, null); + trackEnd(executionInfo, null); if (sessionMetricUpdater.isEnabled( DefaultSessionMetric.CQL_REQUESTS, executionProfile.getName())) { - if (completionTimeNanos == NANOTIME_NOT_MEASURED_YET) { - completionTimeNanos = System.nanoTime(); - totalLatencyNanos = completionTimeNanos - startTimeNanos; + // Only call nanoTime() if we're actually going to use it + if (endTimeNanos == NANOTIME_NOT_MEASURED_YET) { + endTimeNanos = System.nanoTime(); } + long totalLatencyNanos = endTimeNanos - startTimeNanos; sessionMetricUpdater.updateTimer( DefaultSessionMetric.CQL_REQUESTS, executionProfile.getName(), @@ -373,7 +359,7 @@ private void setFinalResult( } } catch (Throwable error) { // something unpredictable unexpected happened here that we can't blame on the request itself - ExecutionInfo executionInfo = defaultExecutionInfo(callback, -1).build(); + ExecutionInfo executionInfo = defaultExecutionInfo(callback, -1, error).build(); setFinalError(executionInfo, error); } } @@ -409,7 +395,7 @@ private void logServerWarnings( public void onThrottleFailure(@NonNull RequestThrottlingException error) { sessionMetricUpdater.incrementCounter( DefaultSessionMetric.THROTTLING_ERRORS, executionProfile.getName()); - ExecutionInfo executionInfo = failedExecutionInfoNoRequestSent().build(); + ExecutionInfo executionInfo = failedExecutionInfoNoRequestSent(error).build(); setFinalError(executionInfo, error); } @@ -419,17 +405,7 @@ private void setFinalError(ExecutionInfo executionInfo, Throwable error) { } if (result.completeExceptionally(error)) { cancelScheduledTasks(); - if (!(requestTracker instanceof NoopRequestTracker)) { - long latencyNanos = System.nanoTime() - startTimeNanos; - requestTracker.onError( - executionInfo.getRequest(), - error, - latencyNanos, - executionInfo.getExecutionProfile(), - executionInfo.getCoordinator(), - executionInfo, - logPrefix); - } + trackEnd(executionInfo, error); if (error instanceof DriverTimeoutException) { throttler.signalTimeout(this); sessionMetricUpdater.incrementCounter( @@ -450,6 +426,7 @@ private class NodeResponseCallback implements ResponseCallback, GenericFutureListener> { private final long nodeStartTimeNanos = System.nanoTime(); + private long nodeEndTimeNanos = NANOTIME_NOT_MEASURED_YET; private final Statement statement; private final Node node; private final Queue queryPlan; @@ -487,10 +464,11 @@ private NodeResponseCallback( public void operationComplete(Future future) throws Exception { if (!future.isSuccess()) { Throwable error = future.cause(); - ExecutionInfo executionInfo = CqlRequestHandler.this.defaultExecutionInfo(this).build(); + ExecutionInfo executionInfo = + CqlRequestHandler.this.defaultExecutionInfo(this, error).build(); if (error instanceof EncoderException && error.getCause() instanceof FrameTooLongException) { - trackNodeError(error.getCause(), executionInfo, NANOTIME_NOT_MEASURED_YET); + trackNodeEnd(this, executionInfo, error.getCause()); setFinalError(executionInfo, error.getCause()); } else { LOG.trace( @@ -500,7 +478,7 @@ public void operationComplete(Future future) throws Exception { error.getMessage(), error); recordError(node, error); - trackNodeError(error, executionInfo, NANOTIME_NOT_MEASURED_YET); + trackNodeEnd(this, executionInfo, error); ((DefaultNode) node) .getMetricUpdater() .incrementCounter(DefaultNodeMetric.UNSENT_REQUESTS, executionProfile.getName()); @@ -590,7 +568,7 @@ public void onResponse(Frame responseFrame) { NodeMetricUpdater nodeMetricUpdater = ((DefaultNode) node).getMetricUpdater(); if (nodeMetricUpdater.isEnabled(DefaultNodeMetric.CQL_MESSAGES, executionProfile.getName())) { nodeResponseTimeNanos = System.nanoTime(); - long nodeLatency = System.nanoTime() - nodeStartTimeNanos; + long nodeLatency = nodeResponseTimeNanos - nodeStartTimeNanos; nodeMetricUpdater.updateTimer( DefaultNodeMetric.CQL_MESSAGES, executionProfile.getName(), @@ -634,24 +612,22 @@ public void onResponse(Frame responseFrame) { setFinalResult((Result) responseMessage, responseFrame, true, this); } else if (responseMessage instanceof Error) { LOG.trace("[{}] Got error response, processing", logPrefix); - processErrorResponse((Error) responseMessage); + processErrorResponse((Error) responseMessage, responseFrame); } else { - ExecutionInfo executionInfo = defaultExecutionInfo().build(); - trackNodeError( - new IllegalStateException("Unexpected response " + responseMessage), - executionInfo, - nodeResponseTimeNanos); - setFinalError( - executionInfo, new IllegalStateException("Unexpected response " + responseMessage)); + IllegalStateException error = + new IllegalStateException("Unexpected response " + responseMessage); + ExecutionInfo executionInfo = defaultExecutionInfo(error).build(); + trackNodeEnd(this, executionInfo, error); + setFinalError(executionInfo, error); } } catch (Throwable t) { - ExecutionInfo executionInfo = defaultExecutionInfo().build(); - trackNodeError(t, executionInfo, nodeResponseTimeNanos); + ExecutionInfo executionInfo = defaultExecutionInfo(t).build(); + trackNodeEnd(this, executionInfo, t); setFinalError(executionInfo, t); } } - private void processErrorResponse(Error errorMessage) { + private void processErrorResponse(Error errorMessage, Frame errorFrame) { if (errorMessage.code == ProtocolConstants.ErrorCode.UNPREPARED) { ByteBuffer idToReprepare = ByteBuffer.wrap(((Unprepared) errorMessage).id); LOG.trace( @@ -677,11 +653,20 @@ private void processErrorResponse(Error errorMessage) { throttler, sessionMetricUpdater, logPrefix); + PrepareRequest reprepareRequest = Conversions.toPrepareRequest(reprepareMessage); + long reprepareStartNanos = System.nanoTime(); + IllegalStateException driverError = + new IllegalStateException("Unexpected response " + errorMessage); + trackNodeEnd( + this, + defaultExecutionInfo(driverError).withServerResponse(errorFrame).build(), + driverError); + // TODO: Shall we have different logPrefix? + trackReprepareStatementStart(reprepareRequest, this, logPrefix); reprepareHandler .start() .handle( (repreparedId, exception) -> { - ExecutionInfo executionInfo = defaultExecutionInfo().build(); if (exception != null) { // If the error is not recoverable, surface it to the client instead of retrying if (exception instanceof UnexpectedResponseException) { @@ -694,18 +679,28 @@ private void processErrorResponse(Error errorMessage) { || prepareError instanceof FunctionFailureException || prepareError instanceof ProtocolError) { LOG.trace("[{}] Unrecoverable error on reprepare, rethrowing", logPrefix); - trackNodeError(prepareError, executionInfo, NANOTIME_NOT_MEASURED_YET); + trackReprepareStatementEnd( + reprepareRequest, this, prepareError, reprepareStartNanos, logPrefix); + ExecutionInfo executionInfo = defaultExecutionInfo(prepareError).build(); + trackNodeEnd(this, executionInfo, prepareError); setFinalError(executionInfo, prepareError); return null; } } } else if (exception instanceof RequestThrottlingException) { - trackNodeError(exception, executionInfo, NANOTIME_NOT_MEASURED_YET); + trackReprepareStatementEnd( + reprepareRequest, this, exception, reprepareStartNanos, logPrefix); + ExecutionInfo executionInfo = defaultExecutionInfo(exception).build(); + trackNodeEnd(this, executionInfo, exception); setFinalError(executionInfo, exception); return null; } recordError(node, exception); - trackNodeError(exception, executionInfo, NANOTIME_NOT_MEASURED_YET); + trackReprepareStatementEnd( + reprepareRequest, this, exception, reprepareStartNanos, logPrefix); + ExecutionInfo executionInfo = defaultExecutionInfo(exception).build(); + trackNodeEnd(this, executionInfo, exception); + setFinalError(executionInfo, exception); LOG.trace("[{}] Reprepare failed, trying next node", logPrefix); sendRequest(statement, null, queryPlan, execution, retryCount, false); } else { @@ -719,11 +714,18 @@ private void processErrorResponse(Error errorMessage) { + "the statement was prepared.", Bytes.toHexString(idToReprepare), Bytes.toHexString(repreparedId))); - trackNodeError( - illegalStateException, executionInfo, NANOTIME_NOT_MEASURED_YET); + // notify error in initial statement execution + ExecutionInfo executionInfo = + defaultExecutionInfo(illegalStateException).build(); + trackNodeEnd(this, executionInfo, illegalStateException); setFinalError(executionInfo, illegalStateException); } - LOG.trace("[{}] Reprepare sucessful, retrying", logPrefix); + LOG.trace("[{}] Reprepare successful, retrying", logPrefix); + // notify statement preparation as successful + trackReprepareStatementEnd( + reprepareRequest, this, null, reprepareStartNanos, logPrefix); + // do not report to onRequestStart(), because we already did during first + // attempt sendRequest(statement, node, queryPlan, execution, retryCount, false); } return null; @@ -734,17 +736,17 @@ private void processErrorResponse(Error errorMessage) { NodeMetricUpdater metricUpdater = ((DefaultNode) node).getMetricUpdater(); if (error instanceof BootstrappingException) { LOG.trace("[{}] {} is bootstrapping, trying next node", logPrefix, node); - ExecutionInfo executionInfo = defaultExecutionInfo().build(); + ExecutionInfo executionInfo = defaultExecutionInfo(error).build(); recordError(node, error); - trackNodeError(error, executionInfo, NANOTIME_NOT_MEASURED_YET); + trackNodeEnd(this, executionInfo, error); sendRequest(statement, null, queryPlan, execution, retryCount, false); } else if (error instanceof QueryValidationException || error instanceof FunctionFailureException || error instanceof ProtocolError) { LOG.trace("[{}] Unrecoverable error, rethrowing", logPrefix); metricUpdater.incrementCounter(DefaultNodeMetric.OTHER_ERRORS, executionProfile.getName()); - ExecutionInfo executionInfo = defaultExecutionInfo().build(); - trackNodeError(error, executionInfo, NANOTIME_NOT_MEASURED_YET); + ExecutionInfo executionInfo = defaultExecutionInfo(error).build(); + trackNodeEnd(this, executionInfo, error); setFinalError(executionInfo, error); } else { RetryPolicy retryPolicy = Conversions.resolveRetryPolicy(context, executionProfile); @@ -816,11 +818,11 @@ private void processErrorResponse(Error errorMessage) { private void processRetryVerdict(RetryVerdict verdict, Throwable error) { LOG.trace("[{}] Processing retry decision {}", logPrefix, verdict); - ExecutionInfo executionInfo = defaultExecutionInfo().build(); + ExecutionInfo executionInfo = defaultExecutionInfo(error).build(); switch (verdict.getRetryDecision()) { case RETRY_SAME: recordError(node, error); - trackNodeError(error, executionInfo, NANOTIME_NOT_MEASURED_YET); + trackNodeEnd(this, executionInfo, error); sendRequest( verdict.getRetryRequest(statement), node, @@ -831,7 +833,7 @@ private void processRetryVerdict(RetryVerdict verdict, Throwable error) { break; case RETRY_NEXT: recordError(node, error); - trackNodeError(error, executionInfo, NANOTIME_NOT_MEASURED_YET); + trackNodeEnd(this, executionInfo, error); sendRequest( verdict.getRetryRequest(statement), null, @@ -841,7 +843,7 @@ private void processRetryVerdict(RetryVerdict verdict, Throwable error) { false); break; case RETHROW: - trackNodeError(error, executionInfo, NANOTIME_NOT_MEASURED_YET); + trackNodeEnd(this, executionInfo, error); setFinalError(executionInfo, error); break; case IGNORE: @@ -878,7 +880,7 @@ public void onFailure(Throwable error) { if (result.isDone()) { return; } - LOG.trace("[{}] Request failure, processing: {}", logPrefix, error); + LOG.trace("[{}] Request failure, processing: {}", logPrefix, error.getMessage(), error); RetryVerdict verdict; if (!Conversions.resolveIdempotence(statement, executionProfile) || error instanceof FrameTooLongException) { @@ -888,10 +890,10 @@ public void onFailure(Throwable error) { RetryPolicy retryPolicy = Conversions.resolveRetryPolicy(context, executionProfile); verdict = retryPolicy.onRequestAbortedVerdict(statement, error, retryCount); } catch (Throwable cause) { - ExecutionInfo executionInfo = defaultExecutionInfo().build(); - setFinalError( - executionInfo, - new IllegalStateException("Unexpected error while invoking the retry policy", cause)); + IllegalStateException driverError = + new IllegalStateException("Unexpected error while invoking the retry policy", cause); + ExecutionInfo executionInfo = defaultExecutionInfo(driverError).build(); + setFinalError(executionInfo, driverError); return; } } @@ -914,32 +916,8 @@ public void cancel() { } } - /** - * @param nodeResponseTimeNanos the time we received the response, if it's already been - * measured. If {@link #NANOTIME_NOT_MEASURED_YET}, it hasn't and we need to measure it now - * (this is to avoid unnecessary calls to System.nanoTime) - */ - private void trackNodeError( - Throwable error, ExecutionInfo executionInfo, long nodeResponseTimeNanos) { - if (requestTracker instanceof NoopRequestTracker) { - return; - } - if (nodeResponseTimeNanos == NANOTIME_NOT_MEASURED_YET) { - nodeResponseTimeNanos = System.nanoTime(); - } - long latencyNanos = nodeResponseTimeNanos - this.nodeStartTimeNanos; - requestTracker.onNodeError( - statement, - error, - latencyNanos, - executionProfile, - executionInfo.getCoordinator(), - executionInfo, - logPrefix); - } - - private DefaultExecutionInfo.Builder defaultExecutionInfo() { - return CqlRequestHandler.this.defaultExecutionInfo(this, execution); + private DefaultExecutionInfo.Builder defaultExecutionInfo(Throwable error) { + return CqlRequestHandler.this.defaultExecutionInfo(this, execution, error); } @Override @@ -948,36 +926,189 @@ public String toString() { } } - private DefaultExecutionInfo.Builder defaultExecutionInfo(NodeResponseCallback callback) { - return defaultExecutionInfo(callback, callback.execution); + private DefaultExecutionInfo.Builder defaultExecutionInfo( + NodeResponseCallback callback, Throwable error) { + return defaultExecutionInfo(callback, callback.execution, error); } private DefaultExecutionInfo.Builder defaultExecutionInfo( - NodeResponseCallback callback, int execution) { + NodeResponseCallback callback, int execution, Throwable error) { return new DefaultExecutionInfo.Builder( callback.statement, callback.node, startedSpeculativeExecutionsCount.get(), execution, + error, errors, session, context, executionProfile); } - private DefaultExecutionInfo.Builder failedExecutionInfoNoRequestSent() { - return failedExecutionInfoNoRequestSent(initialStatement); + private DefaultExecutionInfo.Builder failedExecutionInfoNoRequestSent(Throwable error) { + return failedExecutionInfoNoRequestSent(initialStatement, error); } - private DefaultExecutionInfo.Builder failedExecutionInfoNoRequestSent(Statement statement) { + private DefaultExecutionInfo.Builder failedExecutionInfoNoRequestSent( + Statement statement, Throwable error) { return new DefaultExecutionInfo.Builder( statement, null, startedSpeculativeExecutionsCount.get(), -1, + error, errors, session, context, executionProfile); } + + /** Notify request tracker that processing of initial statement starts. */ + private void trackStart() { + trackStart(initialStatement, logPrefix); + } + + /** Notify request tracker that processing of given statement starts. */ + private void trackStart(Request request, String logPrefix) { + if (requestTracker instanceof NoopRequestTracker) { + return; + } + requestTracker.onRequestCreated(request, executionProfile, logPrefix); + } + + /** Notify request tracker that processing of given statement starts at a certain node. */ + private void trackNodeStart(Request request, Node node, String logPrefix) { + if (requestTracker instanceof NoopRequestTracker) { + return; + } + requestTracker.onRequestCreatedForNode(request, executionProfile, node, logPrefix); + } + + /** Utility method to trigger {@link RequestTracker} based on {@link NodeResponseCallback}. */ + private long trackNodeEnd( + NodeResponseCallback callback, ExecutionInfo executionInfo, Throwable error) { + callback.nodeEndTimeNanos = + trackNodeEndInternal( + executionInfo.getRequest(), + executionInfo.getCoordinator(), + executionInfo, + error, + callback.nodeStartTimeNanos, + callback.nodeEndTimeNanos, + callback.logPrefix); + return callback.nodeEndTimeNanos; + } + + /** + * Notify request tracker that processing of initial statement has been completed (successfully or + * with error). + */ + private void trackEnd(ExecutionInfo executionInfo, Throwable error) { + endTimeNanos = + trackEndInternal( + initialStatement, + executionInfo.getCoordinator(), + executionInfo, + error, + startTimeNanos, + endTimeNanos, + logPrefix); + } + + /** + * Notify request tracker that processing of statement has been completed by a given node. To + * minimalize number of calls to {@code System#nanoTime()} caller may pass end timestamp. If + * passed timestamp equals {@code NANOTIME_NOT_MEASURED_YET}, method returns current end timestamp + * for further reuse. + */ + private long trackNodeEndInternal( + Request request, + Node node, + ExecutionInfo executionInfo, + Throwable error, + long startTimeNanos, + long endTimeNanos, + String logPrefix) { + if (requestTracker instanceof NoopRequestTracker) { + return NANOTIME_NOT_MEASURED_YET; + } + endTimeNanos = endTimeNanos == -1 ? System.nanoTime() : endTimeNanos; + long latencyNanos = endTimeNanos - startTimeNanos; + if (error == null) { + requestTracker.onNodeSuccess( + request, latencyNanos, executionProfile, node, executionInfo, logPrefix); + } else { + requestTracker.onNodeError( + request, error, latencyNanos, executionProfile, node, executionInfo, logPrefix); + } + return endTimeNanos; + } + + /** + * Notify request tracker that processing of given statement has been completed (successfully or + * with error). + */ + private long trackEndInternal( + Request request, + Node node, + ExecutionInfo executionInfo, + Throwable error, + long startTimeNanos, + long endTimeNanos, + String logPrefix) { + if (requestTracker instanceof NoopRequestTracker) { + return NANOTIME_NOT_MEASURED_YET; + } + endTimeNanos = endTimeNanos == NANOTIME_NOT_MEASURED_YET ? System.nanoTime() : endTimeNanos; + long latencyNanos = endTimeNanos - startTimeNanos; + if (error == null) { + requestTracker.onSuccess( + request, latencyNanos, executionProfile, node, executionInfo, logPrefix); + } else { + requestTracker.onError( + request, error, latencyNanos, executionProfile, node, executionInfo, logPrefix); + } + return endTimeNanos; + } + + /** + * Utility method to notify request tracker about start execution of re-prepating prepared + * statement. + */ + private void trackReprepareStatementStart( + Request reprepareRequest, NodeResponseCallback callback, String logPrefix) { + trackStart(reprepareRequest, logPrefix); + trackNodeStart(reprepareRequest, callback.node, logPrefix); + } + + /** + * Utility method to notify request tracker about completed execution of re-prepating prepared + * statement. + */ + private void trackReprepareStatementEnd( + Request statement, + NodeResponseCallback callback, + Throwable error, + long startTimeNanos, + String logPrefix) { + ExecutionInfo executionInfo = + defaultReprepareExecutionInfo(statement, callback.node, error).build(); + long endTimeNanos = + trackNodeEndInternal( + statement, + callback.node, + executionInfo, + error, + startTimeNanos, + NANOTIME_NOT_MEASURED_YET, + logPrefix); + trackEndInternal( + statement, callback.node, executionInfo, error, startTimeNanos, endTimeNanos, logPrefix); + } + + private DefaultExecutionInfo.Builder defaultReprepareExecutionInfo( + Request statement, Node node, Throwable error) { + return new DefaultExecutionInfo.Builder( + statement, node, -1, 0, error, null, session, context, executionProfile); + } } diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/DefaultExecutionInfo.java b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/DefaultExecutionInfo.java index 1dd4354d6e6..1be9f1dbd49 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/DefaultExecutionInfo.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/DefaultExecutionInfo.java @@ -47,6 +47,7 @@ public class DefaultExecutionInfo implements ExecutionInfo { private final Node coordinator; private final int speculativeExecutionCount; private final int successfulExecutionIndex; + private final Throwable driverError; private final List> errors; private final ByteBuffer pagingState; private final UUID tracingId; @@ -64,6 +65,7 @@ private DefaultExecutionInfo( Node coordinator, int speculativeExecutionCount, int successfulExecutionIndex, + Throwable driverError, List> errors, ByteBuffer pagingState, Frame frame, @@ -76,6 +78,7 @@ private DefaultExecutionInfo( this.coordinator = coordinator; this.speculativeExecutionCount = speculativeExecutionCount; this.successfulExecutionIndex = successfulExecutionIndex; + this.driverError = driverError; this.errors = errors; this.pagingState = pagingState; @@ -125,6 +128,12 @@ public int getSuccessfulExecutionIndex() { return successfulExecutionIndex; } + @Nullable + @Override + public Throwable getDriverError() { + return driverError; + } + @NonNull @Override public List> getErrors() { @@ -202,6 +211,7 @@ public static Builder builder( Node coordinator, int speculativeExecutionCount, int successfulExecutionIndex, + Throwable driverError, List> errors, DefaultSession session, InternalDriverContext context, @@ -211,6 +221,7 @@ public static Builder builder( coordinator, speculativeExecutionCount, successfulExecutionIndex, + driverError, errors, session, context, @@ -222,6 +233,7 @@ public static class Builder { private final Node coordinator; private final int speculativeExecutionCount; private final int successfulExecutionIndex; + private final Throwable driverError; private final List> errors; private final DefaultSession session; private final InternalDriverContext context; @@ -236,6 +248,7 @@ public Builder( Node coordinator, int speculativeExecutionCount, int successfulExecutionIndex, + Throwable driverError, List> errors, DefaultSession session, InternalDriverContext context, @@ -244,6 +257,7 @@ public Builder( this.coordinator = coordinator; this.speculativeExecutionCount = speculativeExecutionCount; this.successfulExecutionIndex = successfulExecutionIndex; + this.driverError = driverError; this.errors = errors; this.session = session; this.context = context; @@ -274,6 +288,7 @@ public DefaultExecutionInfo build() { coordinator, speculativeExecutionCount, successfulExecutionIndex, + driverError, errors, pagingState, frame, diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTracker.java b/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTracker.java index 3173a56b1df..26015833360 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTracker.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTracker.java @@ -77,6 +77,30 @@ public void register(@NonNull RequestTracker tracker) { addTracker(tracker); } + @Override + public void onRequestCreated( + @NonNull Request request, + @NonNull DriverExecutionProfile executionProfile, + @NonNull String requestLogPrefix) { + invokeTrackers( + tracker -> tracker.onRequestCreated(request, executionProfile, requestLogPrefix), + requestLogPrefix, + "onRequestStart"); + } + + @Override + public void onRequestCreatedForNode( + @NonNull Request request, + @NonNull DriverExecutionProfile executionProfile, + @NonNull Node node, + @NonNull String requestLogPrefix) { + invokeTrackers( + tracker -> + tracker.onRequestCreatedForNode(request, executionProfile, node, requestLogPrefix), + requestLogPrefix, + "onRequestNodeStart"); + } + @Override public void onSuccess( @NonNull Request request, @@ -133,7 +157,7 @@ public void onNodeError( long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, - ExecutionInfo executionInfo, + @Nullable ExecutionInfo executionInfo, @NonNull String logPrefix) { invokeTrackers( tracker -> diff --git a/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandlerTest.java b/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandlerTest.java index 1924ef5a9af..9d3a7fd249f 100644 --- a/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandlerTest.java +++ b/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandlerTest.java @@ -31,7 +31,6 @@ import com.datastax.oss.driver.api.core.NodeUnavailableException; import com.datastax.oss.driver.api.core.config.DefaultDriverOption; import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; -import com.datastax.oss.driver.api.core.cql.ColumnDefinitions; import com.datastax.oss.driver.api.core.cql.PreparedStatement; import com.datastax.oss.driver.api.core.cql.SimpleStatement; import com.datastax.oss.driver.api.core.metadata.Node; @@ -39,42 +38,15 @@ import com.datastax.oss.driver.api.core.retry.RetryVerdict; import com.datastax.oss.driver.api.core.servererrors.OverloadedException; import com.datastax.oss.driver.internal.core.channel.ResponseCallback; -import com.datastax.oss.driver.shaded.guava.common.collect.ImmutableList; -import com.datastax.oss.driver.shaded.guava.common.collect.ImmutableMap; -import com.datastax.oss.protocol.internal.Message; import com.datastax.oss.protocol.internal.ProtocolConstants; import com.datastax.oss.protocol.internal.request.Prepare; import com.datastax.oss.protocol.internal.response.Error; -import com.datastax.oss.protocol.internal.response.result.ColumnSpec; -import com.datastax.oss.protocol.internal.response.result.Prepared; -import com.datastax.oss.protocol.internal.response.result.RawType; -import com.datastax.oss.protocol.internal.response.result.RowsMetadata; -import com.datastax.oss.protocol.internal.util.Bytes; -import java.nio.ByteBuffer; import java.util.List; import java.util.Map; import java.util.concurrent.CompletionStage; -import org.junit.Before; import org.junit.Test; -import org.mockito.Mock; -import org.mockito.MockitoAnnotations; -public class CqlPrepareHandlerTest { - - private static final DefaultPrepareRequest PREPARE_REQUEST = - new DefaultPrepareRequest("mock query"); - - @Mock private Node node1; - @Mock private Node node2; - @Mock private Node node3; - - private final Map payload = - ImmutableMap.of("key1", ByteBuffer.wrap(new byte[] {1, 2, 3, 4})); - - @Before - public void setup() { - MockitoAnnotations.initMocks(this); - } +public class CqlPrepareHandlerTest extends CqlPrepareHandlerTestBase { @Test public void should_prepare_on_first_node_and_reprepare_on_others() { @@ -355,45 +327,4 @@ public void should_propagate_custom_payload_on_all_nodes() { assertThatStage(prepareFuture).isSuccess(CqlPrepareHandlerTest::assertMatchesSimplePrepared); } } - - private static Message simplePrepared() { - RowsMetadata variablesMetadata = - new RowsMetadata( - ImmutableList.of( - new ColumnSpec( - "ks", - "table", - "key", - 0, - RawType.PRIMITIVES.get(ProtocolConstants.DataType.VARCHAR))), - null, - new int[] {0}, - null); - RowsMetadata resultMetadata = - new RowsMetadata( - ImmutableList.of( - new ColumnSpec( - "ks", - "table", - "message", - 0, - RawType.PRIMITIVES.get(ProtocolConstants.DataType.VARCHAR))), - null, - new int[] {}, - null); - return new Prepared( - Bytes.fromHexString("0xffff").array(), null, variablesMetadata, resultMetadata); - } - - private static void assertMatchesSimplePrepared(PreparedStatement statement) { - assertThat(Bytes.toHexString(statement.getId())).isEqualTo("0xffff"); - - ColumnDefinitions variableDefinitions = statement.getVariableDefinitions(); - assertThat(variableDefinitions).hasSize(1); - assertThat(variableDefinitions.get(0).getName().asInternal()).isEqualTo("key"); - - ColumnDefinitions resultSetDefinitions = statement.getResultSetDefinitions(); - assertThat(resultSetDefinitions).hasSize(1); - assertThat(resultSetDefinitions.get(0).getName().asInternal()).isEqualTo("message"); - } } diff --git a/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandlerTestBase.java b/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandlerTestBase.java new file mode 100644 index 00000000000..cf824ed0a10 --- /dev/null +++ b/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandlerTestBase.java @@ -0,0 +1,97 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package com.datastax.oss.driver.internal.core.cql; + +import static com.datastax.oss.driver.Assertions.assertThat; + +import com.datastax.oss.driver.api.core.cql.ColumnDefinitions; +import com.datastax.oss.driver.api.core.cql.PreparedStatement; +import com.datastax.oss.driver.api.core.metadata.Node; +import com.datastax.oss.driver.shaded.guava.common.collect.ImmutableList; +import com.datastax.oss.driver.shaded.guava.common.collect.ImmutableMap; +import com.datastax.oss.protocol.internal.Message; +import com.datastax.oss.protocol.internal.ProtocolConstants; +import com.datastax.oss.protocol.internal.response.result.ColumnSpec; +import com.datastax.oss.protocol.internal.response.result.Prepared; +import com.datastax.oss.protocol.internal.response.result.RawType; +import com.datastax.oss.protocol.internal.response.result.RowsMetadata; +import com.datastax.oss.protocol.internal.util.Bytes; +import java.nio.ByteBuffer; +import java.util.Map; +import org.junit.Before; +import org.mockito.Mock; +import org.mockito.MockitoAnnotations; + +public abstract class CqlPrepareHandlerTestBase { + + protected static final DefaultPrepareRequest PREPARE_REQUEST = + new DefaultPrepareRequest("mock query"); + + @Mock protected Node node1; + @Mock protected Node node2; + @Mock protected Node node3; + + protected final Map payload = + ImmutableMap.of("key1", ByteBuffer.wrap(new byte[] {1, 2, 3, 4})); + + @Before + public void setup() { + MockitoAnnotations.initMocks(this); + } + + protected static Message simplePrepared() { + RowsMetadata variablesMetadata = + new RowsMetadata( + ImmutableList.of( + new ColumnSpec( + "ks", + "table", + "key", + 0, + RawType.PRIMITIVES.get(ProtocolConstants.DataType.VARCHAR))), + null, + new int[] {0}, + null); + RowsMetadata resultMetadata = + new RowsMetadata( + ImmutableList.of( + new ColumnSpec( + "ks", + "table", + "message", + 0, + RawType.PRIMITIVES.get(ProtocolConstants.DataType.VARCHAR))), + null, + new int[] {}, + null); + return new Prepared( + Bytes.fromHexString("0xffff").array(), null, variablesMetadata, resultMetadata); + } + + protected static void assertMatchesSimplePrepared(PreparedStatement statement) { + assertThat(Bytes.toHexString(statement.getId())).isEqualTo("0xffff"); + + ColumnDefinitions variableDefinitions = statement.getVariableDefinitions(); + assertThat(variableDefinitions).hasSize(1); + assertThat(variableDefinitions.get(0).getName().asInternal()).isEqualTo("key"); + + ColumnDefinitions resultSetDefinitions = statement.getResultSetDefinitions(); + assertThat(resultSetDefinitions).hasSize(1); + assertThat(resultSetDefinitions.get(0).getName().asInternal()).isEqualTo("message"); + } +} diff --git a/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandlerTrackerTest.java b/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandlerTrackerTest.java new file mode 100644 index 00000000000..035bf116f92 --- /dev/null +++ b/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandlerTrackerTest.java @@ -0,0 +1,134 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package com.datastax.oss.driver.internal.core.cql; + +import static com.datastax.oss.driver.Assertions.assertThatStage; +import static com.datastax.oss.driver.internal.core.cql.CqlRequestHandlerTestBase.defaultFrameOf; +import static org.mockito.Mockito.any; +import static org.mockito.Mockito.anyLong; +import static org.mockito.Mockito.eq; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.spy; +import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.verifyNoMoreInteractions; +import static org.mockito.Mockito.when; + +import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; +import com.datastax.oss.driver.api.core.cql.ExecutionInfo; +import com.datastax.oss.driver.api.core.cql.PreparedStatement; +import com.datastax.oss.driver.api.core.servererrors.BootstrappingException; +import com.datastax.oss.driver.api.core.tracker.RequestTracker; +import com.datastax.oss.driver.internal.core.tracker.NoopRequestTracker; +import com.datastax.oss.protocol.internal.ProtocolConstants; +import com.datastax.oss.protocol.internal.response.Error; +import java.util.concurrent.CompletionStage; +import org.junit.Test; + +public class CqlPrepareHandlerTrackerTest extends CqlPrepareHandlerTestBase { + + @Test + public void should_invoke_request_tracker() { + try (RequestHandlerTestHarness harness = + RequestHandlerTestHarness.builder() + .withDefaultIdempotence(true) + .withResponse( + node1, + defaultFrameOf( + new Error(ProtocolConstants.ErrorCode.IS_BOOTSTRAPPING, "mock message"))) + .withResponse(node2, defaultFrameOf(CqlPrepareHandlerTest.simplePrepared())) + .build()) { + + RequestTracker requestTracker = mock(RequestTracker.class); + when(harness.getContext().getRequestTracker()).thenReturn(requestTracker); + + CompletionStage resultSetFuture = + new CqlPrepareHandler(PREPARE_REQUEST, harness.getSession(), harness.getContext(), "test") + .handle(); + + assertThatStage(resultSetFuture) + .isSuccess( + resultSet -> { + verify(requestTracker) + .onRequestCreated( + eq(PREPARE_REQUEST), any(DriverExecutionProfile.class), any(String.class)); + verify(requestTracker) + .onRequestCreatedForNode( + eq(PREPARE_REQUEST), + any(DriverExecutionProfile.class), + eq(node1), + any(String.class)); + verify(requestTracker) + .onNodeError( + eq(PREPARE_REQUEST), + any(BootstrappingException.class), + anyLong(), + any(DriverExecutionProfile.class), + eq(node1), + any(ExecutionInfo.class), + any(String.class)); + verify(requestTracker) + .onRequestCreatedForNode( + eq(PREPARE_REQUEST), + any(DriverExecutionProfile.class), + eq(node2), + any(String.class)); + verify(requestTracker) + .onNodeSuccess( + eq(PREPARE_REQUEST), + anyLong(), + any(DriverExecutionProfile.class), + eq(node2), + any(ExecutionInfo.class), + any(String.class)); + verify(requestTracker) + .onSuccess( + eq(PREPARE_REQUEST), + anyLong(), + any(DriverExecutionProfile.class), + eq(node2), + any(ExecutionInfo.class), + any(String.class)); + verifyNoMoreInteractions(requestTracker); + }); + } + } + + @Test + public void should_not_invoke_noop_request_tracker() { + try (RequestHandlerTestHarness harness = + RequestHandlerTestHarness.builder() + .withDefaultIdempotence(true) + .withResponse( + node1, + defaultFrameOf( + new Error(ProtocolConstants.ErrorCode.IS_BOOTSTRAPPING, "mock message"))) + .withResponse(node2, defaultFrameOf(CqlPrepareHandlerTest.simplePrepared())) + .build()) { + + RequestTracker requestTracker = spy(new NoopRequestTracker(harness.getContext())); + when(harness.getContext().getRequestTracker()).thenReturn(requestTracker); + + CompletionStage resultSetFuture = + new CqlPrepareHandler(PREPARE_REQUEST, harness.getSession(), harness.getContext(), "test") + .handle(); + + assertThatStage(resultSetFuture) + .isSuccess(resultSet -> verifyNoMoreInteractions(requestTracker)); + } + } +} diff --git a/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandlerTrackerTest.java b/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandlerTrackerTest.java index 533fe3be87a..e331c68092d 100644 --- a/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandlerTrackerTest.java +++ b/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandlerTrackerTest.java @@ -32,21 +32,44 @@ import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; import com.datastax.oss.driver.api.core.cql.AsyncResultSet; +import com.datastax.oss.driver.api.core.cql.BoundStatement; +import com.datastax.oss.driver.api.core.cql.ColumnDefinitions; import com.datastax.oss.driver.api.core.cql.ExecutionInfo; +import com.datastax.oss.driver.api.core.cql.PreparedStatement; +import com.datastax.oss.driver.api.core.cql.Statement; import com.datastax.oss.driver.api.core.metadata.Node; import com.datastax.oss.driver.api.core.servererrors.BootstrappingException; import com.datastax.oss.driver.api.core.session.Request; import com.datastax.oss.driver.api.core.tracker.RequestTracker; +import com.datastax.oss.driver.internal.core.session.RepreparePayload; import com.datastax.oss.driver.internal.core.tracker.NoopRequestTracker; import com.datastax.oss.protocol.internal.ProtocolConstants; +import com.datastax.oss.protocol.internal.request.Prepare; import com.datastax.oss.protocol.internal.response.Error; +import com.datastax.oss.protocol.internal.response.error.Unprepared; +import com.datastax.oss.protocol.internal.response.result.Prepared; +import com.datastax.oss.protocol.internal.util.Bytes; +import java.nio.ByteBuffer; import java.util.ArrayList; +import java.util.Collections; import java.util.List; import java.util.concurrent.CompletionStage; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.ConcurrentMap; +import java.util.regex.Pattern; import org.junit.Test; import org.mockito.invocation.Invocation; public class CqlRequestHandlerTrackerTest extends CqlRequestHandlerTestBase { + private static final String ON_REQUEST_CREATED = "onRequestCreated"; + private static final String ON_REQUEST_CREATED_FOR_NODE = "onRequestCreatedForNode"; + private static final String ON_NODE_SUCCESS = "onNodeSuccess"; + private static final String ON_NODE_ERROR = "onNodeError"; + private static final String ON_SUCCESS = "onSuccess"; + private static final Pattern LOG_PREFIX_PER_REQUEST = Pattern.compile("(test)\\|\\d*"); + private static final Pattern LOG_PREFIX_WITH_EXECUTION_NUMBER = + Pattern.compile("(test)\\|\\d*\\|\\d*"); + @Test public void should_invoke_request_tracker() { try (RequestHandlerTestHarness harness = @@ -73,6 +96,17 @@ public void should_invoke_request_tracker() { assertThatStage(resultSetFuture) .isSuccess( resultSet -> { + verify(requestTracker) + .onRequestCreated( + eq(UNDEFINED_IDEMPOTENCE_STATEMENT), + any(DriverExecutionProfile.class), + any(String.class)); + verify(requestTracker) + .onRequestCreatedForNode( + eq(UNDEFINED_IDEMPOTENCE_STATEMENT), + any(DriverExecutionProfile.class), + eq(node1), + any(String.class)); verify(requestTracker) .onNodeError( eq(UNDEFINED_IDEMPOTENCE_STATEMENT), @@ -90,6 +124,12 @@ public void should_invoke_request_tracker() { eq(node2), any(ExecutionInfo.class), any(String.class)); + verify(requestTracker) + .onRequestCreatedForNode( + eq(UNDEFINED_IDEMPOTENCE_STATEMENT), + any(DriverExecutionProfile.class), + eq(node2), + any(String.class)); verify(requestTracker) .onSuccess( eq(UNDEFINED_IDEMPOTENCE_STATEMENT), @@ -105,15 +145,15 @@ public void should_invoke_request_tracker() { List invocations = new ArrayList<>(mockingDetails(requestTracker).getInvocations()); checkExecutionInfo( - (ExecutionInfo) invocations.get(0).getRawArguments()[5], + (ExecutionInfo) invocations.get(2).getRawArguments()[5], UNDEFINED_IDEMPOTENCE_STATEMENT, node1); checkExecutionInfo( - (ExecutionInfo) invocations.get(1).getRawArguments()[4], + (ExecutionInfo) invocations.get(4).getRawArguments()[4], UNDEFINED_IDEMPOTENCE_STATEMENT, node2); checkExecutionInfo( - (ExecutionInfo) invocations.get(2).getRawArguments()[4], + (ExecutionInfo) invocations.get(5).getRawArguments()[4], UNDEFINED_IDEMPOTENCE_STATEMENT, node2); } @@ -153,4 +193,122 @@ public void should_not_invoke_noop_request_tracker() { .isSuccess(resultSet -> verifyNoMoreInteractions(requestTracker)); } } + + @Test + public void should_invoke_implicit_prepare_request_tracker() { + ByteBuffer mockId = Bytes.fromHexString("0xffff"); + + PreparedStatement preparedStatement = mock(PreparedStatement.class); + when(preparedStatement.getId()).thenReturn(mockId); + ColumnDefinitions columnDefinitions = mock(ColumnDefinitions.class); + when(columnDefinitions.size()).thenReturn(0); + when(preparedStatement.getResultSetDefinitions()).thenReturn(columnDefinitions); + BoundStatement boundStatement = mock(BoundStatement.class); + when(boundStatement.getPreparedStatement()).thenReturn(preparedStatement); + when(boundStatement.getValues()).thenReturn(Collections.emptyList()); + when(boundStatement.getNowInSeconds()).thenReturn(Statement.NO_NOW_IN_SECONDS); + + RequestHandlerTestHarness.Builder harnessBuilder = RequestHandlerTestHarness.builder(); + // For the first attempt that gets the UNPREPARED response + PoolBehavior node1Behavior = harnessBuilder.customBehavior(node1); + // For the second attempt that succeeds + harnessBuilder.withResponse(node1, defaultFrameOf(singleRow())); + + try (RequestHandlerTestHarness harness = harnessBuilder.build()) { + RequestTracker requestTracker = mock(RequestTracker.class); + when(harness.getContext().getRequestTracker()).thenReturn(requestTracker); + + // The handler will look for the info to reprepare in the session's cache, put it there + ConcurrentMap repreparePayloads = new ConcurrentHashMap<>(); + repreparePayloads.put( + mockId, new RepreparePayload(mockId, "mock query", null, Collections.emptyMap())); + when(harness.getSession().getRepreparePayloads()).thenReturn(repreparePayloads); + + CompletionStage resultSetFuture = + new CqlRequestHandler( + UNDEFINED_IDEMPOTENCE_STATEMENT, + harness.getSession(), + harness.getContext(), + "test") + .handle(); + + // Before we proceed, mock the PREPARE exchange that will occur as soon as we complete the + // first response. + node1Behavior.mockFollowupRequest( + Prepare.class, defaultFrameOf(new Prepared(Bytes.getArray(mockId), null, null, null))); + + node1Behavior.setWriteSuccess(); + node1Behavior.setResponseSuccess( + defaultFrameOf(new Unprepared("mock message", Bytes.getArray(mockId)))); + + assertThatStage(resultSetFuture) + .isSuccess( + resultSet -> { + List invocations = + (List) mockingDetails(requestTracker).getInvocations(); + assertThat(invocations).hasSize(10); + // start processing CQL statement + checkInvocation( + invocations.get(0), + ON_REQUEST_CREATED, + DefaultSimpleStatement.class, + LOG_PREFIX_PER_REQUEST); + checkInvocation( + invocations.get(1), + ON_REQUEST_CREATED_FOR_NODE, + DefaultSimpleStatement.class, + LOG_PREFIX_WITH_EXECUTION_NUMBER); + checkInvocation( + invocations.get(2), + ON_NODE_ERROR, + DefaultSimpleStatement.class, + LOG_PREFIX_WITH_EXECUTION_NUMBER); + // implicit reprepare statement + checkInvocation( + invocations.get(3), + ON_REQUEST_CREATED, + DefaultPrepareRequest.class, + LOG_PREFIX_WITH_EXECUTION_NUMBER); + checkInvocation( + invocations.get(4), + ON_REQUEST_CREATED_FOR_NODE, + DefaultPrepareRequest.class, + LOG_PREFIX_WITH_EXECUTION_NUMBER); + checkInvocation( + invocations.get(5), + ON_NODE_SUCCESS, + DefaultPrepareRequest.class, + LOG_PREFIX_WITH_EXECUTION_NUMBER); + checkInvocation( + invocations.get(6), + ON_SUCCESS, + DefaultPrepareRequest.class, + LOG_PREFIX_WITH_EXECUTION_NUMBER); + // send new statement and process it + checkInvocation( + invocations.get(7), + ON_REQUEST_CREATED_FOR_NODE, + DefaultSimpleStatement.class, + LOG_PREFIX_WITH_EXECUTION_NUMBER); + checkInvocation( + invocations.get(8), + ON_NODE_SUCCESS, + DefaultSimpleStatement.class, + LOG_PREFIX_WITH_EXECUTION_NUMBER); + checkInvocation( + invocations.get(9), + ON_SUCCESS, + DefaultSimpleStatement.class, + LOG_PREFIX_PER_REQUEST); + }); + } + } + + private void checkInvocation( + Invocation invocation, String methodName, Class firstParameter, Pattern logPrefixPattern) { + assertThat(invocation.getMethod().getName()).isEqualTo(methodName); + assertThat(invocation.getArguments()[0]).isInstanceOf(firstParameter); + String logPrefix = invocation.getArguments()[invocation.getArguments().length - 1].toString(); + assertThat(logPrefix).matches(logPrefixPattern); + } } diff --git a/integration-tests/src/test/java/com/datastax/oss/driver/core/cql/PagingIterableSpliteratorIT.java b/integration-tests/src/test/java/com/datastax/oss/driver/core/cql/PagingIterableSpliteratorIT.java index 02078b683db..403b42febd4 100644 --- a/integration-tests/src/test/java/com/datastax/oss/driver/core/cql/PagingIterableSpliteratorIT.java +++ b/integration-tests/src/test/java/com/datastax/oss/driver/core/cql/PagingIterableSpliteratorIT.java @@ -22,24 +22,36 @@ import com.datastax.oss.driver.api.core.CqlSession; import com.datastax.oss.driver.api.core.config.DefaultDriverOption; import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; +import com.datastax.oss.driver.api.core.context.DriverContext; import com.datastax.oss.driver.api.core.cql.BatchStatement; import com.datastax.oss.driver.api.core.cql.BatchStatementBuilder; import com.datastax.oss.driver.api.core.cql.DefaultBatchType; +import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.cql.PreparedStatement; import com.datastax.oss.driver.api.core.cql.ResultSet; import com.datastax.oss.driver.api.core.cql.Row; import com.datastax.oss.driver.api.core.cql.SimpleStatement; +import com.datastax.oss.driver.api.core.metadata.Node; +import com.datastax.oss.driver.api.core.session.Request; +import com.datastax.oss.driver.api.core.tracker.RequestTracker; import com.datastax.oss.driver.api.testinfra.ccm.CcmRule; import com.datastax.oss.driver.api.testinfra.session.SessionRule; +import com.datastax.oss.driver.api.testinfra.session.SessionUtils; import com.datastax.oss.driver.categories.ParallelizableTests; +import com.datastax.oss.driver.internal.core.tracker.RequestLogFormatter; import com.datastax.oss.driver.shaded.guava.common.collect.Lists; import com.tngtech.java.junit.dataprovider.DataProvider; import com.tngtech.java.junit.dataprovider.DataProviderRunner; import com.tngtech.java.junit.dataprovider.UseDataProvider; +import edu.umd.cs.findbugs.annotations.NonNull; +import edu.umd.cs.findbugs.annotations.Nullable; import java.util.ArrayList; +import java.util.Collections; +import java.util.Iterator; import java.util.List; import java.util.Spliterator; import java.util.stream.StreamSupport; +import org.apache.commons.lang3.tuple.Pair; import org.junit.BeforeClass; import org.junit.ClassRule; import org.junit.Test; @@ -54,7 +66,15 @@ public class PagingIterableSpliteratorIT { private static final CcmRule CCM_RULE = CcmRule.getInstance(); - private static final SessionRule SESSION_RULE = SessionRule.builder(CCM_RULE).build(); + private static final SessionRule SESSION_RULE = + SessionRule.builder(CCM_RULE) + .withConfigLoader( + SessionUtils.configLoaderBuilder() + .withClassList( + DefaultDriverOption.REQUEST_TRACKER_CLASSES, + Collections.singletonList(RecordingRequestTracker.class)) + .build()) + .build(); @ClassRule public static final TestRule CHAIN = RuleChain.outerRule(CCM_RULE).around(SESSION_RULE); @@ -78,6 +98,27 @@ public static void setupSchema() { } SESSION_RULE.session().execute(batch.setExecutionProfile(SESSION_RULE.slowProfile()).build()); } + RecordingRequestTracker.reset(); + } + + @Test + public void should_notify_request_tracker_during_pagination() throws Exception { + String query = "SELECT v FROM test where k0 = 0"; + RecordingRequestTracker.query = query; + CqlSession session = SESSION_RULE.session(); + ResultSet result = session.execute(SimpleStatement.newInstance(query)); + Iterator iterator = result.iterator(); + while (iterator.hasNext()) { + Row row = iterator.next(); + assertThat(row.getInt("v")).isGreaterThanOrEqualTo(0); + } + int expectedFetches = 20_000 / 5_000 + 1; // +1 to retrieve empty page + assertThat(RecordingRequestTracker.startedRequests).hasSize(expectedFetches); + assertThat(RecordingRequestTracker.startedRequestsAtNode).hasSize(expectedFetches); + assertThat(RecordingRequestTracker.successfulRequestsAtNode).hasSize(expectedFetches); + assertThat(RecordingRequestTracker.successfulRequests).hasSize(expectedFetches); + assertThat(RecordingRequestTracker.errorRequestsAtNode).hasSize(0); + assertThat(RecordingRequestTracker.errorRequests).hasSize(0); } @Test @@ -140,4 +181,120 @@ public static Iterable pageSizes() { arguments.add(Lists.newArrayList(19_995, true)); return arguments; } + + public static class RecordingRequestTracker implements RequestTracker { + + private static volatile String query = "none"; + private static final List startedRequests = new ArrayList<>(); + private static final List> startedRequestsAtNode = new ArrayList<>(); + private static final List> successfulRequestsAtNode = new ArrayList<>(); + private static final List successfulRequests = new ArrayList<>(); + private static final List> errorRequestsAtNode = new ArrayList<>(); + private static final List errorRequests = new ArrayList<>(); + + private final RequestLogFormatter formatter; + + public RecordingRequestTracker(DriverContext context) { + formatter = new RequestLogFormatter(context); + } + + @Override + public synchronized void onRequestCreated( + @NonNull Request request, + @NonNull DriverExecutionProfile executionProfile, + @NonNull String requestLogPrefix) { + if (shouldRecord(request)) { + startedRequests.add(request); + } + } + + @Override + public synchronized void onRequestCreatedForNode( + @NonNull Request request, + @NonNull DriverExecutionProfile executionProfile, + @NonNull Node node, + @NonNull String requestLogPrefix) { + if (shouldRecord(request)) { + startedRequestsAtNode.add(Pair.of(request, node)); + } + } + + @Override + public synchronized void onNodeSuccess( + @NonNull Request request, + long latencyNanos, + @NonNull DriverExecutionProfile executionProfile, + @NonNull Node node, + @Nullable ExecutionInfo executionInfo, + @NonNull String requestLogPrefix) { + if (shouldRecord(request)) { + successfulRequestsAtNode.add(Pair.of(request, node)); + } + } + + @Override + public synchronized void onSuccess( + @NonNull Request request, + long latencyNanos, + @NonNull DriverExecutionProfile executionProfile, + @NonNull Node node, + @Nullable ExecutionInfo executionInfo, + @NonNull String requestLogPrefix) { + if (shouldRecord(request)) { + successfulRequests.add(request); + } + } + + @Override + public synchronized void onNodeError( + @NonNull Request request, + @NonNull Throwable error, + long latencyNanos, + @NonNull DriverExecutionProfile executionProfile, + @NonNull Node node, + @Nullable ExecutionInfo executionInfo, + @NonNull String requestLogPrefix) { + if (shouldRecord(request)) { + errorRequestsAtNode.add(Pair.of(request, node)); + } + } + + @Override + public synchronized void onError( + @NonNull Request request, + @NonNull Throwable error, + long latencyNanos, + @NonNull DriverExecutionProfile executionProfile, + @Nullable Node node, + @Nullable ExecutionInfo executionInfo, + @NonNull String requestLogPrefix) { + if (shouldRecord(request)) { + errorRequests.add(request); + } + } + + private boolean shouldRecord(Request request) { + if (query == null) { + return true; + } + StringBuilder builder = new StringBuilder(); + formatter.appendRequest(request, 1000, true, 1000, 1000, builder); + return builder.toString().contains(query); + } + + @Override + public void close() throws Exception { + reset(); + } + + public static void reset() { + query = "none"; + startedRequests.clear(); + startedRequestsAtNode.clear(); + successfulRequestsAtNode.clear(); + successfulRequests.clear(); + errorRequestsAtNode.clear(); + errorRequests.clear(); + } + } } diff --git a/integration-tests/src/test/java/com/datastax/oss/driver/core/tracker/RequestLoggerIT.java b/integration-tests/src/test/java/com/datastax/oss/driver/core/tracker/RequestLoggerIT.java index ae2c46fe4a0..a53d558cb38 100644 --- a/integration-tests/src/test/java/com/datastax/oss/driver/core/tracker/RequestLoggerIT.java +++ b/integration-tests/src/test/java/com/datastax/oss/driver/core/tracker/RequestLoggerIT.java @@ -369,7 +369,7 @@ public void should_log_failed_nodes_on_successful_request() { .matches(WITH_EXECUTION_PREFIX); assertThat(events.get(1).getFormattedMessage()) .contains("Success", "[0 values]", QUERY) - .matches(WITH_PER_REQUEST_PREFIX); + .matches(WITH_EXECUTION_PREFIX); assertThat(events.get(2).getFormattedMessage()) .contains("Success", "[0 values]", QUERY) .matches(WITH_PER_REQUEST_PREFIX); @@ -399,7 +399,7 @@ public void should_log_successful_nodes_on_successful_request() { List events = loggingEventCaptor.getAllValues(); assertThat(events.get(0).getFormattedMessage()) .contains("Success", "[0 values]", QUERY) - .matches(WITH_PER_REQUEST_PREFIX); + .matches(WITH_EXECUTION_PREFIX); assertThat(events.get(1).getFormattedMessage()) .contains("Success", "[0 values]", QUERY) .matches(WITH_PER_REQUEST_PREFIX); From b45569f8c98b38ef7cb1d990c7295cffe427326a Mon Sep 17 00:00:00 2001 From: Lukasz Antoniak Date: Wed, 25 Sep 2024 15:33:59 +0200 Subject: [PATCH 4/4] Remove duplicated request tracker callback arguments --- .../api/core/graph/GraphExecutionInfo.java | 6 + .../ContinuousRequestHandlerBase.java | 46 ++---- .../graph/GraphExecutionInfoConverter.java | 11 ++ .../core/graph/GraphRequestHandler.java | 63 ++++---- .../driver/api/core/cql/ExecutionInfo.java | 1 + .../api/core/tracker/RequestTracker.java | 94 +++++------- .../internal/core/cql/CqlPrepareHandler.java | 12 +- .../internal/core/cql/CqlRequestHandler.java | 145 +++++++----------- .../core/cql/DefaultExecutionInfo.java | 28 ++-- .../DefaultLoadBalancingPolicy.java | 20 +-- .../tracker/MultiplexingRequestTracker.java | 49 +----- .../core/tracker/NoopRequestTracker.java | 34 +--- .../internal/core/tracker/RequestLogger.java | 43 ++---- .../ContinuousCqlRequestHandlerTest.java | 24 +-- .../core/graph/GraphRequestHandlerTest.java | 13 +- .../cql/CqlPrepareHandlerTrackerTest.java | 20 +-- .../cql/CqlRequestHandlerTrackerTest.java | 96 ++++++------ ...LoadBalancingPolicyRequestTrackerTest.java | 30 ++-- .../MultiplexingRequestTrackerTest.java | 73 +++++---- .../core/cql/PagingIterableSpliteratorIT.java | 49 ++---- .../tracker/RequestNodeLoggerExample.java | 30 ++-- 21 files changed, 362 insertions(+), 525 deletions(-) diff --git a/core/src/main/java/com/datastax/dse/driver/api/core/graph/GraphExecutionInfo.java b/core/src/main/java/com/datastax/dse/driver/api/core/graph/GraphExecutionInfo.java index c10fdf1ce3c..6c7c39ff5dc 100644 --- a/core/src/main/java/com/datastax/dse/driver/api/core/graph/GraphExecutionInfo.java +++ b/core/src/main/java/com/datastax/dse/driver/api/core/graph/GraphExecutionInfo.java @@ -69,6 +69,12 @@ default DriverExecutionProfile getExecutionProfile() { */ int getSuccessfulExecutionIndex(); + /** @return Exception raised by the driver to the application. */ + @Nullable + default Throwable getDriverError() { + return null; + } + /** * The errors encountered on previous coordinators, if any. * diff --git a/core/src/main/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousRequestHandlerBase.java b/core/src/main/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousRequestHandlerBase.java index 530e59b5a32..e2f7ffe02b6 100644 --- a/core/src/main/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousRequestHandlerBase.java +++ b/core/src/main/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousRequestHandlerBase.java @@ -629,7 +629,7 @@ public void operationComplete(@NonNull Future future) { Throwable error = future.cause(); if (error instanceof EncoderException && error.getCause() instanceof FrameTooLongException) { - trackNodeError(node, error.getCause(), null); + trackNodeError(error.getCause(), null); lock.lock(); try { abort(error.getCause(), false); @@ -646,7 +646,7 @@ public void operationComplete(@NonNull Future future) { .getMetricUpdater() .incrementCounter(DefaultNodeMetric.UNSENT_REQUESTS, executionProfile.getName()); recordError(node, error); - trackNodeError(node, error.getCause(), null); + trackNodeError(error.getCause(), null); sendRequest(statement, null, executionIndex, retryCount, scheduleSpeculativeExecution); } } else { @@ -767,11 +767,11 @@ public void onResponse(@NonNull Frame response) { } else { IllegalStateException error = new IllegalStateException("Unexpected response " + responseMessage); - trackNodeError(node, error, response); + trackNodeError(error, response); abort(error, false); } } catch (Throwable t) { - trackNodeError(node, t, response); + trackNodeError(t, response); abort(t, false); } } finally { @@ -915,7 +915,7 @@ private void processErrorResponse(@NonNull Error errorMessage, @NonNull Frame fr if (error instanceof BootstrappingException) { LOG.trace("[{}] {} is bootstrapping, trying next node", logPrefix, node); recordError(node, error); - trackNodeError(node, error, frame); + trackNodeError(error, frame); sendRequest(statement, null, executionIndex, retryCount, false); } else if (error instanceof QueryValidationException || error instanceof FunctionFailureException @@ -927,7 +927,7 @@ private void processErrorResponse(@NonNull Error errorMessage, @NonNull Frame fr NodeMetricUpdater metricUpdater = ((DefaultNode) node).getMetricUpdater(); metricUpdater.incrementCounter( DefaultNodeMetric.OTHER_ERRORS, executionProfile.getName()); - trackNodeError(node, error, frame); + trackNodeError(error, frame); abort(error, true); } else { try { @@ -1066,7 +1066,7 @@ private void processUnprepared(@NonNull Unprepared errorMessage) { + "This usually happens when you run a 'USE...' query after " + "the statement was prepared.", Bytes.toHexString(idToReprepare), Bytes.toHexString(repreparedId))); - trackNodeError(node, illegalStateException, null); + trackNodeError(illegalStateException, null); fatalError = illegalStateException; } else { LOG.trace( @@ -1085,18 +1085,18 @@ private void processUnprepared(@NonNull Unprepared errorMessage) { || prepareError instanceof FunctionFailureException || prepareError instanceof ProtocolError) { LOG.trace("[{}] Unrecoverable error on re-prepare, rethrowing", logPrefix); - trackNodeError(node, prepareError, null); + trackNodeError(prepareError, null); fatalError = prepareError; } } } else if (exception instanceof RequestThrottlingException) { - trackNodeError(node, exception, null); + trackNodeError(exception, null); fatalError = exception; } if (fatalError == null) { LOG.trace("[{}] Re-prepare failed, trying next node", logPrefix); recordError(node, exception); - trackNodeError(node, exception, null); + trackNodeError(exception, null); sendRequest(statement, null, executionIndex, retryCount, false); } } @@ -1124,18 +1124,18 @@ private void processRetryVerdict(@NonNull RetryVerdict verdict, @NonNull Throwab switch (verdict.getRetryDecision()) { case RETRY_SAME: recordError(node, error); - trackNodeError(node, error, null); + trackNodeError(error, null); sendRequest( verdict.getRetryRequest(statement), node, executionIndex, retryCount + 1, false); break; case RETRY_NEXT: recordError(node, error); - trackNodeError(node, error, null); + trackNodeError(error, null); sendRequest( verdict.getRetryRequest(statement), null, executionIndex, retryCount + 1, false); break; case RETHROW: - trackNodeError(node, error, null); + trackNodeError(error, null); abort(error, true); break; case IGNORE: @@ -1448,18 +1448,13 @@ private void reenableAutoReadIfNeeded() { // ERROR HANDLING - private void trackNodeError( - @NonNull Node node, @NonNull Throwable error, @Nullable Frame frame) { + private void trackNodeError(@NonNull Throwable error, @Nullable Frame frame) { if (nodeErrorReported.compareAndSet(false, true)) { long latencyNanos = System.nanoTime() - this.messageStartTimeNanos; context .getRequestTracker() .onNodeError( - this.statement, - error, latencyNanos, - executionProfile, - node, createExecutionInfo(error).withServerResponse(frame).build(), logPrefix); } @@ -1584,23 +1579,16 @@ private void completeResultSetFuture( } if (nodeSuccessReported.compareAndSet(false, true)) { - context - .getRequestTracker() - .onNodeSuccess( - statement, nodeLatencyNanos, executionProfile, node, executionInfo, logPrefix); + context.getRequestTracker().onNodeSuccess(nodeLatencyNanos, executionInfo, logPrefix); } - context - .getRequestTracker() - .onSuccess( - statement, totalLatencyNanos, executionProfile, node, executionInfo, logPrefix); + context.getRequestTracker().onSuccess(totalLatencyNanos, executionInfo, logPrefix); } } else { Throwable error = (Throwable) pageOrError; if (future.completeExceptionally(error)) { context .getRequestTracker() - .onError( - statement, error, totalLatencyNanos, executionProfile, node, null, logPrefix); + .onError(totalLatencyNanos, createExecutionInfo(error).build(), logPrefix); if (error instanceof DriverTimeoutException) { throttler.signalTimeout(ContinuousRequestHandlerBase.this); session diff --git a/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphExecutionInfoConverter.java b/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphExecutionInfoConverter.java index 7500c26d691..0c35b302577 100644 --- a/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphExecutionInfoConverter.java +++ b/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphExecutionInfoConverter.java @@ -84,6 +84,12 @@ public int getSuccessfulExecutionIndex() { return graphExecutionInfo.getSuccessfulExecutionIndex(); } + @Nullable + @Override + public Throwable getDriverError() { + return graphExecutionInfo.getDriverError(); + } + @NonNull @Override public List> getErrors() { @@ -172,6 +178,11 @@ public int getSuccessfulExecutionIndex() { return executionInfo.getSuccessfulExecutionIndex(); } + @Override + public Throwable getDriverError() { + return executionInfo.getDriverError(); + } + @Override public List> getErrors() { return executionInfo.getErrors(); diff --git a/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandler.java b/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandler.java index ad57604726f..5bb5fee8ad4 100644 --- a/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandler.java +++ b/core/src/main/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandler.java @@ -372,20 +372,8 @@ private void setFinalResult( completionTimeNanos = System.nanoTime(); totalLatencyNanos = completionTimeNanos - startTimeNanos; long nodeLatencyNanos = completionTimeNanos - callback.nodeStartTimeNanos; - requestTracker.onNodeSuccess( - callback.statement, - nodeLatencyNanos, - executionProfile, - callback.node, - executionInfo, - logPrefix); - requestTracker.onSuccess( - callback.statement, - totalLatencyNanos, - executionProfile, - callback.node, - executionInfo, - logPrefix); + requestTracker.onNodeSuccess(nodeLatencyNanos, executionInfo, logPrefix); + requestTracker.onSuccess(totalLatencyNanos, executionInfo, logPrefix); } if (sessionMetricUpdater.isEnabled( DseSessionMetric.GRAPH_REQUESTS, executionProfile.getName())) { @@ -471,8 +459,7 @@ private void setFinalError( cancelScheduledTasks(); if (!(requestTracker instanceof NoopRequestTracker)) { long latencyNanos = System.nanoTime() - startTimeNanos; - requestTracker.onError( - statement, error, latencyNanos, executionProfile, node, executionInfo, logPrefix); + requestTracker.onError(latencyNanos, executionInfo, logPrefix); } if (error instanceof DriverTimeoutException) { throttler.signalTimeout(this); @@ -534,7 +521,7 @@ public void operationComplete(Future future) { Throwable error = future.cause(); if (error instanceof EncoderException && error.getCause() instanceof FrameTooLongException) { - trackNodeError(node, error.getCause(), NANOTIME_NOT_MEASURED_YET); + trackNodeError(this, error.getCause(), NANOTIME_NOT_MEASURED_YET, null); setFinalError(statement, error.getCause(), node, execution); } else { LOG.trace( @@ -543,7 +530,7 @@ public void operationComplete(Future future) { channel, error); recordError(node, error); - trackNodeError(node, error, NANOTIME_NOT_MEASURED_YET); + trackNodeError(this, error, NANOTIME_NOT_MEASURED_YET, null); ((DefaultNode) node) .getMetricUpdater() .incrementCounter(DefaultNodeMetric.UNSENT_REQUESTS, executionProfile.getName()); @@ -651,12 +638,13 @@ public void onResponse(Frame responseFrame) { setFinalResult((Result) responseMessage, responseFrame, this); } else if (responseMessage instanceof Error) { LOG.trace("[{}] Got error response, processing", logPrefix); - processErrorResponse((Error) responseMessage); + processErrorResponse((Error) responseMessage, responseFrame); } else { trackNodeError( - node, + this, new IllegalStateException("Unexpected response " + responseMessage), - nodeResponseTimeNanos); + nodeResponseTimeNanos, + responseFrame); setFinalError( statement, new IllegalStateException("Unexpected response " + responseMessage), @@ -664,25 +652,25 @@ public void onResponse(Frame responseFrame) { execution); } } catch (Throwable t) { - trackNodeError(node, t, nodeResponseTimeNanos); + trackNodeError(this, t, nodeResponseTimeNanos, responseFrame); setFinalError(statement, t, node, execution); } } - private void processErrorResponse(Error errorMessage) { + private void processErrorResponse(Error errorMessage, Frame responseFrame) { CoordinatorException error = Conversions.toThrowable(node, errorMessage, context); NodeMetricUpdater metricUpdater = ((DefaultNode) node).getMetricUpdater(); if (error instanceof BootstrappingException) { LOG.trace("[{}] {} is bootstrapping, trying next node", logPrefix, node); recordError(node, error); - trackNodeError(node, error, NANOTIME_NOT_MEASURED_YET); + trackNodeError(this, error, NANOTIME_NOT_MEASURED_YET, responseFrame); sendRequest(statement, null, queryPlan, execution, retryCount, false); } else if (error instanceof QueryValidationException || error instanceof FunctionFailureException || error instanceof ProtocolError) { LOG.trace("[{}] Unrecoverable error, rethrowing", logPrefix); metricUpdater.incrementCounter(DefaultNodeMetric.OTHER_ERRORS, executionProfile.getName()); - trackNodeError(node, error, NANOTIME_NOT_MEASURED_YET); + trackNodeError(this, error, NANOTIME_NOT_MEASURED_YET, responseFrame); setFinalError(statement, error, node, execution); } else { RetryPolicy retryPolicy = Conversions.resolveRetryPolicy(context, executionProfile); @@ -757,7 +745,7 @@ private void processRetryVerdict(RetryVerdict verdict, Throwable error) { switch (verdict.getRetryDecision()) { case RETRY_SAME: recordError(node, error); - trackNodeError(node, error, NANOTIME_NOT_MEASURED_YET); + trackNodeError(this, error, NANOTIME_NOT_MEASURED_YET, null); sendRequest( verdict.getRetryRequest(statement), node, @@ -768,7 +756,7 @@ private void processRetryVerdict(RetryVerdict verdict, Throwable error) { break; case RETRY_NEXT: recordError(node, error); - trackNodeError(node, error, NANOTIME_NOT_MEASURED_YET); + trackNodeError(this, error, NANOTIME_NOT_MEASURED_YET, null); sendRequest( verdict.getRetryRequest(statement), null, @@ -778,7 +766,7 @@ private void processRetryVerdict(RetryVerdict verdict, Throwable error) { false); break; case RETHROW: - trackNodeError(node, error, NANOTIME_NOT_MEASURED_YET); + trackNodeError(this, error, NANOTIME_NOT_MEASURED_YET, null); setFinalError(statement, error, node, execution); break; case IGNORE: @@ -857,16 +845,29 @@ void cancel() { * measured. If {@link #NANOTIME_NOT_MEASURED_YET}, it hasn't and we need to measure it now * (this is to avoid unnecessary calls to System.nanoTime) */ - private void trackNodeError(Node node, Throwable error, long nodeResponseTimeNanos) { + private void trackNodeError( + NodeResponseCallback callback, Throwable error, long nodeResponseTimeNanos, Frame frame) { if (requestTracker instanceof NoopRequestTracker) { return; } if (nodeResponseTimeNanos == NANOTIME_NOT_MEASURED_YET) { nodeResponseTimeNanos = System.nanoTime(); } + ExecutionInfo executionInfo = + DefaultExecutionInfo.builder( + callback.statement, + callback.node, + startedSpeculativeExecutionsCount.get(), + callback.execution, + error, + errors, + session, + context, + callback.executionProfile) + .withServerResponse(null, frame) + .build(); long latencyNanos = nodeResponseTimeNanos - this.nodeStartTimeNanos; - requestTracker.onNodeError( - statement, error, latencyNanos, executionProfile, node, null, logPrefix); + requestTracker.onNodeError(latencyNanos, executionInfo, logPrefix); } @Override diff --git a/core/src/main/java/com/datastax/oss/driver/api/core/cql/ExecutionInfo.java b/core/src/main/java/com/datastax/oss/driver/api/core/cql/ExecutionInfo.java index b38183b84fb..a6ac06ca230 100644 --- a/core/src/main/java/com/datastax/oss/driver/api/core/cql/ExecutionInfo.java +++ b/core/src/main/java/com/datastax/oss/driver/api/core/cql/ExecutionInfo.java @@ -120,6 +120,7 @@ default DriverExecutionProfile getExecutionProfile() { @NonNull List> getErrors(); + /** @return Exception raised by the driver to the application. */ @Nullable default Throwable getDriverError() { return null; diff --git a/core/src/main/java/com/datastax/oss/driver/api/core/tracker/RequestTracker.java b/core/src/main/java/com/datastax/oss/driver/api/core/tracker/RequestTracker.java index 2964539f29c..de95edd151f 100644 --- a/core/src/main/java/com/datastax/oss/driver/api/core/tracker/RequestTracker.java +++ b/core/src/main/java/com/datastax/oss/driver/api/core/tracker/RequestTracker.java @@ -68,20 +68,18 @@ default void onRequestCreatedForNode( * * @param latencyNanos the overall execution time (from the {@link Session#execute(Request, * GenericType) session.execute} call until the result is made available to the client). - * @param executionProfile the execution profile of this request. - * @param node the node that returned the successful response. * @param executionInfo the execution info containing the results of this request * @param requestLogPrefix the dedicated log prefix for this request */ default void onSuccess( - @NonNull Request request, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @NonNull ExecutionInfo executionInfo, - @NonNull String requestLogPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { // delegate call to the old method - onSuccess(request, latencyNanos, executionProfile, node, requestLogPrefix); + onSuccess( + executionInfo.getRequest(), + latencyNanos, + executionInfo.getExecutionProfile(), + executionInfo.getCoordinator(), + requestLogPrefix); } /** @@ -89,23 +87,21 @@ default void onSuccess( * * @param latencyNanos the overall execution time (from the {@link Session#execute(Request, * GenericType) session.execute} call until the error is propagated to the client). - * @param executionProfile the execution profile of this request. - * @param node the node that returned the error response, or {@code null} if the error occurred * @param executionInfo the execution info being returned to the client for this request if * available * @param requestLogPrefix the dedicated log prefix for this request */ default void onError( - @NonNull Request request, - @NonNull Throwable error, // TODO: Shall we expose start and end timestamp so that users do not need to call nanoTime()? - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @Nullable Node node, - @Nullable ExecutionInfo executionInfo, - @NonNull String requestLogPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { // delegate call to the old method - onError(request, error, latencyNanos, executionProfile, node, requestLogPrefix); + onError( + executionInfo.getRequest(), + executionInfo.getDriverError(), + latencyNanos, + executionInfo.getExecutionProfile(), + executionInfo.getCoordinator(), + requestLogPrefix); } /** @@ -114,20 +110,18 @@ default void onError( * * @param latencyNanos the overall execution time (from the {@link Session#execute(Request, * GenericType) session.execute} call until the result is made available to the client). - * @param executionProfile the execution profile of this request. - * @param node the node that returned the successful response. * @param executionInfo the execution info containing the results of this request * @param requestLogPrefix the dedicated log prefix for this request */ default void onNodeSuccess( - @NonNull Request request, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @NonNull ExecutionInfo executionInfo, - @NonNull String requestLogPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { // delegate call to the old method - onNodeSuccess(request, latencyNanos, executionProfile, node, requestLogPrefix); + onNodeSuccess( + executionInfo.getRequest(), + latencyNanos, + executionInfo.getExecutionProfile(), + executionInfo.getCoordinator(), + requestLogPrefix); } /** @@ -136,21 +130,19 @@ default void onNodeSuccess( * * @param latencyNanos the overall execution time (from the {@link Session#execute(Request, * GenericType) session.execute} call until the error is propagated to the client). - * @param executionProfile the execution profile of this request. - * @param node the node that returned the error response. * @param executionInfo the execution info containing the results of this request if available * @param requestLogPrefix the dedicated log prefix for this request */ default void onNodeError( - @NonNull Request request, - @NonNull Throwable error, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @Nullable ExecutionInfo executionInfo, - @NonNull String requestLogPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { // delegate call to the old method - onNodeError(request, error, latencyNanos, executionProfile, node, requestLogPrefix); + onNodeError( + executionInfo.getRequest(), + executionInfo.getDriverError(), + latencyNanos, + executionInfo.getExecutionProfile(), + executionInfo.getCoordinator(), + requestLogPrefix); } /** @@ -178,7 +170,7 @@ default void onSessionReady(@NonNull Session session) {} /** * @deprecated This method only exists for backward compatibility. Override {@link - * #onSuccess(Request, long, DriverExecutionProfile, Node, ExecutionInfo, String)} instead. + * #onSuccess(long, ExecutionInfo, String)} instead. */ @Deprecated default void onSuccess( @@ -189,7 +181,7 @@ default void onSuccess( /** * @deprecated This method only exists for backward compatibility. Override {@link - * #onSuccess(Request, long, DriverExecutionProfile, Node, ExecutionInfo, String)} instead. + * #onSuccess(long, ExecutionInfo, String)} instead. */ @Deprecated default void onSuccess( @@ -203,9 +195,8 @@ default void onSuccess( } /** - * @deprecated This method only exists for backward compatibility. Override {@link - * #onError(Request, Throwable, long, DriverExecutionProfile, Node, ExecutionInfo, String)} - * instead. + * @deprecated This method only exists for backward compatibility. Override {@link #onError(long, + * ExecutionInfo, String)} instead. */ @Deprecated default void onError( @@ -216,9 +207,8 @@ default void onError( @Nullable Node node) {} /** - * @deprecated This method only exists for backward compatibility. Override {@link - * #onError(Request, Throwable, long, DriverExecutionProfile, Node, ExecutionInfo, String)} - * instead. + * @deprecated This method only exists for backward compatibility. Override {@link #onError(long, + * ExecutionInfo, String)} instead. */ @Deprecated default void onError( @@ -234,8 +224,7 @@ default void onError( /** * @deprecated This method only exists for backward compatibility. Override {@link - * #onNodeError(Request, Throwable, long, DriverExecutionProfile, Node, ExecutionInfo, - * String)} instead. + * #onNodeError(long, ExecutionInfo, String)} instead. */ @Deprecated default void onNodeError( @@ -247,8 +236,7 @@ default void onNodeError( /** * @deprecated This method only exists for backward compatibility. Override {@link - * #onNodeError(Request, Throwable, long, DriverExecutionProfile, Node, ExecutionInfo, - * String)} instead. + * #onNodeError(long, ExecutionInfo, String)} instead. */ @Deprecated default void onNodeError( @@ -264,8 +252,7 @@ default void onNodeError( /** * @deprecated This method only exists for backward compatibility. Override {@link - * #onNodeSuccess(Request, long, DriverExecutionProfile, Node, ExecutionInfo, String)} - * instead. + * #onNodeSuccess(long, ExecutionInfo, String)} instead. */ @Deprecated default void onNodeSuccess( @@ -276,8 +263,7 @@ default void onNodeSuccess( /** * @deprecated This method only exists for backward compatibility. Override {@link - * #onNodeSuccess(Request, long, DriverExecutionProfile, Node, ExecutionInfo, String)} - * instead. + * #onNodeSuccess(long, ExecutionInfo, String)} instead. */ @Deprecated default void onNodeSuccess( diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandler.java b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandler.java index 44f6490d594..6204c65abfe 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandler.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandler.java @@ -537,11 +537,9 @@ private void trackNodeEnd(Request request, Node node, Throwable error, long star long latencyNanos = System.nanoTime() - startTimeNanos; ExecutionInfo executionInfo = defaultExecutionInfo(request, node, error).build(); if (error == null) { - requestTracker.onNodeSuccess( - request, latencyNanos, executionProfile, node, executionInfo, logPrefix); + requestTracker.onNodeSuccess(latencyNanos, executionInfo, logPrefix); } else { - requestTracker.onNodeError( - request, error, latencyNanos, executionProfile, node, executionInfo, logPrefix); + requestTracker.onNodeError(latencyNanos, executionInfo, logPrefix); } } @@ -556,11 +554,9 @@ private void trackEnd(Node node, Throwable error) { long latencyNanos = System.nanoTime() - this.startTimeNanos; ExecutionInfo executionInfo = defaultExecutionInfo(initialRequest, node, error).build(); if (error == null) { - requestTracker.onSuccess( - initialRequest, latencyNanos, executionProfile, node, executionInfo, logPrefix); + requestTracker.onSuccess(latencyNanos, executionInfo, logPrefix); } else { - requestTracker.onError( - initialRequest, error, latencyNanos, executionProfile, node, executionInfo, logPrefix); + requestTracker.onError(latencyNanos, executionInfo, logPrefix); } } diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandler.java b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandler.java index ae218a31033..b56eecc898e 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandler.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandler.java @@ -214,7 +214,7 @@ private Timeout scheduleTimeout(Duration timeoutDuration) { new DriverTimeoutException("Query timed out after " + timeoutDuration); ExecutionInfo executionInfo = failedExecutionInfoNoRequestSent(timeoutException).build(); - setFinalError(executionInfo, timeoutException); + setFinalError(executionInfo); }, timeoutDuration.toNanos(), TimeUnit.NANOSECONDS); @@ -268,8 +268,11 @@ private void sendRequest( // We've reached the end of the query plan without finding any node to write to if (!result.isDone() && activeExecutionsCount.decrementAndGet() == 0) { // We're the last execution so fail the result - ExecutionInfo executionInfo = failedExecutionInfoNoRequestSent(statement, null).build(); - setFinalError(executionInfo, AllNodesFailedException.fromErrors(this.errors)); + ExecutionInfo executionInfo = + failedExecutionInfoNoRequestSent( + statement, AllNodesFailedException.fromErrors(this.errors)) + .build(); + setFinalError(executionInfo); } } else { NodeResponseCallback nodeResponseCallback = @@ -335,8 +338,8 @@ private void setFinalResult( cancelScheduledTasks(); throttler.signalSuccess(this); - long endTimeNanos = trackNodeEnd(callback, executionInfo, null); - trackEnd(executionInfo, null); + long endTimeNanos = trackNodeEnd(callback, executionInfo); + trackEnd(executionInfo); if (sessionMetricUpdater.isEnabled( DefaultSessionMetric.CQL_REQUESTS, executionProfile.getName())) { // Only call nanoTime() if we're actually going to use it @@ -360,7 +363,7 @@ private void setFinalResult( } catch (Throwable error) { // something unpredictable unexpected happened here that we can't blame on the request itself ExecutionInfo executionInfo = defaultExecutionInfo(callback, -1, error).build(); - setFinalError(executionInfo, error); + setFinalError(executionInfo); } } @@ -396,16 +399,18 @@ public void onThrottleFailure(@NonNull RequestThrottlingException error) { sessionMetricUpdater.incrementCounter( DefaultSessionMetric.THROTTLING_ERRORS, executionProfile.getName()); ExecutionInfo executionInfo = failedExecutionInfoNoRequestSent(error).build(); - setFinalError(executionInfo, error); + setFinalError(executionInfo); } - private void setFinalError(ExecutionInfo executionInfo, Throwable error) { - if (error instanceof DriverException) { - ((DriverException) error).setExecutionInfo(executionInfo); + private void setFinalError(ExecutionInfo executionInfo) { + Throwable error = executionInfo.getDriverError(); + if (executionInfo.getDriverError() instanceof DriverException) { + // ExecutionInfo is not exposed for retried errors + ((DriverException) executionInfo.getDriverError()).setExecutionInfo(executionInfo); } if (result.completeExceptionally(error)) { cancelScheduledTasks(); - trackEnd(executionInfo, error); + trackEnd(executionInfo); if (error instanceof DriverTimeoutException) { throttler.signalTimeout(this); sessionMetricUpdater.incrementCounter( @@ -464,12 +469,12 @@ private NodeResponseCallback( public void operationComplete(Future future) throws Exception { if (!future.isSuccess()) { Throwable error = future.cause(); - ExecutionInfo executionInfo = - CqlRequestHandler.this.defaultExecutionInfo(this, error).build(); if (error instanceof EncoderException && error.getCause() instanceof FrameTooLongException) { - trackNodeEnd(this, executionInfo, error.getCause()); - setFinalError(executionInfo, error.getCause()); + ExecutionInfo executionInfo = + CqlRequestHandler.this.defaultExecutionInfo(this, error.getCause()).build(); + trackNodeEnd(this, executionInfo); + setFinalError(executionInfo); } else { LOG.trace( "[{}] Failed to send request on {}, trying next node (cause: {})", @@ -477,8 +482,10 @@ public void operationComplete(Future future) throws Exception { channel, error.getMessage(), error); + ExecutionInfo executionInfo = + CqlRequestHandler.this.defaultExecutionInfo(this, error).build(); recordError(node, error); - trackNodeEnd(this, executionInfo, error); + trackNodeEnd(this, executionInfo); ((DefaultNode) node) .getMetricUpdater() .incrementCounter(DefaultNodeMetric.UNSENT_REQUESTS, executionProfile.getName()); @@ -617,13 +624,13 @@ public void onResponse(Frame responseFrame) { IllegalStateException error = new IllegalStateException("Unexpected response " + responseMessage); ExecutionInfo executionInfo = defaultExecutionInfo(error).build(); - trackNodeEnd(this, executionInfo, error); - setFinalError(executionInfo, error); + trackNodeEnd(this, executionInfo); + setFinalError(executionInfo); } } catch (Throwable t) { ExecutionInfo executionInfo = defaultExecutionInfo(t).build(); - trackNodeEnd(this, executionInfo, t); - setFinalError(executionInfo, t); + trackNodeEnd(this, executionInfo); + setFinalError(executionInfo); } } @@ -658,9 +665,7 @@ private void processErrorResponse(Error errorMessage, Frame errorFrame) { IllegalStateException driverError = new IllegalStateException("Unexpected response " + errorMessage); trackNodeEnd( - this, - defaultExecutionInfo(driverError).withServerResponse(errorFrame).build(), - driverError); + this, defaultExecutionInfo(driverError).withServerResponse(errorFrame).build()); // TODO: Shall we have different logPrefix? trackReprepareStatementStart(reprepareRequest, this, logPrefix); reprepareHandler @@ -682,8 +687,8 @@ private void processErrorResponse(Error errorMessage, Frame errorFrame) { trackReprepareStatementEnd( reprepareRequest, this, prepareError, reprepareStartNanos, logPrefix); ExecutionInfo executionInfo = defaultExecutionInfo(prepareError).build(); - trackNodeEnd(this, executionInfo, prepareError); - setFinalError(executionInfo, prepareError); + trackNodeEnd(this, executionInfo); + setFinalError(executionInfo); return null; } } @@ -691,16 +696,16 @@ private void processErrorResponse(Error errorMessage, Frame errorFrame) { trackReprepareStatementEnd( reprepareRequest, this, exception, reprepareStartNanos, logPrefix); ExecutionInfo executionInfo = defaultExecutionInfo(exception).build(); - trackNodeEnd(this, executionInfo, exception); - setFinalError(executionInfo, exception); + trackNodeEnd(this, executionInfo); + setFinalError(executionInfo); return null; } recordError(node, exception); trackReprepareStatementEnd( reprepareRequest, this, exception, reprepareStartNanos, logPrefix); ExecutionInfo executionInfo = defaultExecutionInfo(exception).build(); - trackNodeEnd(this, executionInfo, exception); - setFinalError(executionInfo, exception); + trackNodeEnd(this, executionInfo); + setFinalError(executionInfo); LOG.trace("[{}] Reprepare failed, trying next node", logPrefix); sendRequest(statement, null, queryPlan, execution, retryCount, false); } else { @@ -717,8 +722,8 @@ private void processErrorResponse(Error errorMessage, Frame errorFrame) { // notify error in initial statement execution ExecutionInfo executionInfo = defaultExecutionInfo(illegalStateException).build(); - trackNodeEnd(this, executionInfo, illegalStateException); - setFinalError(executionInfo, illegalStateException); + trackNodeEnd(this, executionInfo); + setFinalError(executionInfo); } LOG.trace("[{}] Reprepare successful, retrying", logPrefix); // notify statement preparation as successful @@ -738,7 +743,7 @@ private void processErrorResponse(Error errorMessage, Frame errorFrame) { LOG.trace("[{}] {} is bootstrapping, trying next node", logPrefix, node); ExecutionInfo executionInfo = defaultExecutionInfo(error).build(); recordError(node, error); - trackNodeEnd(this, executionInfo, error); + trackNodeEnd(this, executionInfo); sendRequest(statement, null, queryPlan, execution, retryCount, false); } else if (error instanceof QueryValidationException || error instanceof FunctionFailureException @@ -746,8 +751,8 @@ private void processErrorResponse(Error errorMessage, Frame errorFrame) { LOG.trace("[{}] Unrecoverable error, rethrowing", logPrefix); metricUpdater.incrementCounter(DefaultNodeMetric.OTHER_ERRORS, executionProfile.getName()); ExecutionInfo executionInfo = defaultExecutionInfo(error).build(); - trackNodeEnd(this, executionInfo, error); - setFinalError(executionInfo, error); + trackNodeEnd(this, executionInfo); + setFinalError(executionInfo); } else { RetryPolicy retryPolicy = Conversions.resolveRetryPolicy(context, executionProfile); RetryVerdict verdict; @@ -822,7 +827,7 @@ private void processRetryVerdict(RetryVerdict verdict, Throwable error) { switch (verdict.getRetryDecision()) { case RETRY_SAME: recordError(node, error); - trackNodeEnd(this, executionInfo, error); + trackNodeEnd(this, executionInfo); sendRequest( verdict.getRetryRequest(statement), node, @@ -833,7 +838,7 @@ private void processRetryVerdict(RetryVerdict verdict, Throwable error) { break; case RETRY_NEXT: recordError(node, error); - trackNodeEnd(this, executionInfo, error); + trackNodeEnd(this, executionInfo); sendRequest( verdict.getRetryRequest(statement), null, @@ -843,8 +848,8 @@ private void processRetryVerdict(RetryVerdict verdict, Throwable error) { false); break; case RETHROW: - trackNodeEnd(this, executionInfo, error); - setFinalError(executionInfo, error); + trackNodeEnd(this, executionInfo); + setFinalError(executionInfo); break; case IGNORE: setFinalResult(Void.INSTANCE, null, true, this); @@ -893,7 +898,7 @@ public void onFailure(Throwable error) { IllegalStateException driverError = new IllegalStateException("Unexpected error while invoking the retry policy", cause); ExecutionInfo executionInfo = defaultExecutionInfo(driverError).build(); - setFinalError(executionInfo, driverError); + setFinalError(executionInfo); return; } } @@ -985,14 +990,10 @@ private void trackNodeStart(Request request, Node node, String logPrefix) { } /** Utility method to trigger {@link RequestTracker} based on {@link NodeResponseCallback}. */ - private long trackNodeEnd( - NodeResponseCallback callback, ExecutionInfo executionInfo, Throwable error) { + private long trackNodeEnd(NodeResponseCallback callback, ExecutionInfo executionInfo) { callback.nodeEndTimeNanos = trackNodeEndInternal( - executionInfo.getRequest(), - executionInfo.getCoordinator(), executionInfo, - error, callback.nodeStartTimeNanos, callback.nodeEndTimeNanos, callback.logPrefix); @@ -1003,16 +1004,8 @@ private long trackNodeEnd( * Notify request tracker that processing of initial statement has been completed (successfully or * with error). */ - private void trackEnd(ExecutionInfo executionInfo, Throwable error) { - endTimeNanos = - trackEndInternal( - initialStatement, - executionInfo.getCoordinator(), - executionInfo, - error, - startTimeNanos, - endTimeNanos, - logPrefix); + private void trackEnd(ExecutionInfo executionInfo) { + endTimeNanos = trackEndInternal(executionInfo, startTimeNanos, endTimeNanos, logPrefix); } /** @@ -1022,24 +1015,16 @@ private void trackEnd(ExecutionInfo executionInfo, Throwable error) { * for further reuse. */ private long trackNodeEndInternal( - Request request, - Node node, - ExecutionInfo executionInfo, - Throwable error, - long startTimeNanos, - long endTimeNanos, - String logPrefix) { + ExecutionInfo executionInfo, long startTimeNanos, long endTimeNanos, String logPrefix) { if (requestTracker instanceof NoopRequestTracker) { return NANOTIME_NOT_MEASURED_YET; } endTimeNanos = endTimeNanos == -1 ? System.nanoTime() : endTimeNanos; long latencyNanos = endTimeNanos - startTimeNanos; - if (error == null) { - requestTracker.onNodeSuccess( - request, latencyNanos, executionProfile, node, executionInfo, logPrefix); + if (executionInfo.getDriverError() == null) { + requestTracker.onNodeSuccess(latencyNanos, executionInfo, logPrefix); } else { - requestTracker.onNodeError( - request, error, latencyNanos, executionProfile, node, executionInfo, logPrefix); + requestTracker.onNodeError(latencyNanos, executionInfo, logPrefix); } return endTimeNanos; } @@ -1049,24 +1034,16 @@ private long trackNodeEndInternal( * with error). */ private long trackEndInternal( - Request request, - Node node, - ExecutionInfo executionInfo, - Throwable error, - long startTimeNanos, - long endTimeNanos, - String logPrefix) { + ExecutionInfo executionInfo, long startTimeNanos, long endTimeNanos, String logPrefix) { if (requestTracker instanceof NoopRequestTracker) { return NANOTIME_NOT_MEASURED_YET; } endTimeNanos = endTimeNanos == NANOTIME_NOT_MEASURED_YET ? System.nanoTime() : endTimeNanos; long latencyNanos = endTimeNanos - startTimeNanos; - if (error == null) { - requestTracker.onSuccess( - request, latencyNanos, executionProfile, node, executionInfo, logPrefix); + if (executionInfo.getDriverError() == null) { + requestTracker.onSuccess(latencyNanos, executionInfo, logPrefix); } else { - requestTracker.onError( - request, error, latencyNanos, executionProfile, node, executionInfo, logPrefix); + requestTracker.onError(latencyNanos, executionInfo, logPrefix); } return endTimeNanos; } @@ -1094,16 +1071,8 @@ private void trackReprepareStatementEnd( ExecutionInfo executionInfo = defaultReprepareExecutionInfo(statement, callback.node, error).build(); long endTimeNanos = - trackNodeEndInternal( - statement, - callback.node, - executionInfo, - error, - startTimeNanos, - NANOTIME_NOT_MEASURED_YET, - logPrefix); - trackEndInternal( - statement, callback.node, executionInfo, error, startTimeNanos, endTimeNanos, logPrefix); + trackNodeEndInternal(executionInfo, startTimeNanos, NANOTIME_NOT_MEASURED_YET, logPrefix); + trackEndInternal(executionInfo, startTimeNanos, endTimeNanos, logPrefix); } private DefaultExecutionInfo.Builder defaultReprepareExecutionInfo( diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/DefaultExecutionInfo.java b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/DefaultExecutionInfo.java index 1be9f1dbd49..fed8cf8e8b8 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/cql/DefaultExecutionInfo.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/cql/DefaultExecutionInfo.java @@ -283,19 +283,21 @@ public Builder withSchemaInAgreement(boolean schemaInAgreement) { public DefaultExecutionInfo build() { final ByteBuffer pagingState = (response instanceof Rows) ? ((Rows) response).getMetadata().pagingState : null; - return new DefaultExecutionInfo( - request, - coordinator, - speculativeExecutionCount, - successfulExecutionIndex, - driverError, - errors, - pagingState, - frame, - schemaInAgreement, - session, - context, - executionProfile); + DefaultExecutionInfo executionInfo = + new DefaultExecutionInfo( + request, + coordinator, + speculativeExecutionCount, + successfulExecutionIndex, + driverError, + errors, + pagingState, + frame, + schemaInAgreement, + session, + context, + executionProfile); + return executionInfo; } } } diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/loadbalancing/DefaultLoadBalancingPolicy.java b/core/src/main/java/com/datastax/oss/driver/internal/core/loadbalancing/DefaultLoadBalancingPolicy.java index cb0d20214fa..7c2210ee1d5 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/loadbalancing/DefaultLoadBalancingPolicy.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/loadbalancing/DefaultLoadBalancingPolicy.java @@ -21,7 +21,6 @@ import static java.util.concurrent.TimeUnit.MINUTES; import com.datastax.oss.driver.api.core.config.DefaultDriverOption; -import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; import com.datastax.oss.driver.api.core.context.DriverContext; import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.metadata.Node; @@ -242,25 +241,14 @@ > getInFlight((Node) currentNodes[1], session)) { @Override public void onNodeSuccess( - @NonNull Request request, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @NonNull ExecutionInfo executionInfo, - @NonNull String logPrefix) { - updateResponseTimes(node); + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { + updateResponseTimes(executionInfo.getCoordinator()); } @Override public void onNodeError( - @NonNull Request request, - @NonNull Throwable error, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @Nullable ExecutionInfo executionInfo, - @NonNull String logPrefix) { - updateResponseTimes(node); + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { + updateResponseTimes(executionInfo.getCoordinator()); } /** Exposed as a protected method so that it can be accessed by tests */ diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTracker.java b/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTracker.java index 26015833360..cfa212b6c48 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTracker.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTracker.java @@ -25,7 +25,6 @@ import com.datastax.oss.driver.api.core.tracker.RequestTracker; import com.datastax.oss.driver.internal.core.util.Loggers; import edu.umd.cs.findbugs.annotations.NonNull; -import edu.umd.cs.findbugs.annotations.Nullable; import java.util.Arrays; import java.util.Collection; import java.util.List; @@ -103,66 +102,34 @@ public void onRequestCreatedForNode( @Override public void onSuccess( - @NonNull Request request, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @NonNull ExecutionInfo executionInfo, - @NonNull String logPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { invokeTrackers( - tracker -> - tracker.onSuccess( - request, latencyNanos, executionProfile, node, executionInfo, logPrefix), + tracker -> tracker.onSuccess(latencyNanos, executionInfo, logPrefix), logPrefix, "onSuccess"); } @Override public void onError( - @NonNull Request request, - @NonNull Throwable error, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @Nullable Node node, - @Nullable ExecutionInfo executionInfo, - @NonNull String logPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { invokeTrackers( - tracker -> - tracker.onError( - request, error, latencyNanos, executionProfile, node, executionInfo, logPrefix), - logPrefix, - "onError"); + tracker -> tracker.onError(latencyNanos, executionInfo, logPrefix), logPrefix, "onError"); } @Override public void onNodeSuccess( - @NonNull Request request, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @NonNull ExecutionInfo executionInfo, - @NonNull String logPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { invokeTrackers( - tracker -> - tracker.onNodeSuccess( - request, latencyNanos, executionProfile, node, executionInfo, logPrefix), + tracker -> tracker.onNodeSuccess(latencyNanos, executionInfo, logPrefix), logPrefix, "onNodeSuccess"); } @Override public void onNodeError( - @NonNull Request request, - @NonNull Throwable error, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @Nullable ExecutionInfo executionInfo, - @NonNull String logPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { invokeTrackers( - tracker -> - tracker.onNodeError( - request, error, latencyNanos, executionProfile, node, executionInfo, logPrefix), + tracker -> tracker.onNodeError(latencyNanos, executionInfo, logPrefix), logPrefix, "onNodeError"); } diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/NoopRequestTracker.java b/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/NoopRequestTracker.java index 921a1135c03..09b7dec4b47 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/NoopRequestTracker.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/NoopRequestTracker.java @@ -17,14 +17,10 @@ */ package com.datastax.oss.driver.internal.core.tracker; -import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; import com.datastax.oss.driver.api.core.context.DriverContext; import com.datastax.oss.driver.api.core.cql.ExecutionInfo; -import com.datastax.oss.driver.api.core.metadata.Node; -import com.datastax.oss.driver.api.core.session.Request; import com.datastax.oss.driver.api.core.tracker.RequestTracker; import edu.umd.cs.findbugs.annotations.NonNull; -import edu.umd.cs.findbugs.annotations.Nullable; import net.jcip.annotations.ThreadSafe; /** @@ -40,47 +36,25 @@ public NoopRequestTracker(@SuppressWarnings("unused") DriverContext context) { @Override public void onSuccess( - @NonNull Request request, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @NonNull ExecutionInfo executionInfo, - @NonNull String requestPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestPrefix) { // nothing to do } @Override public void onError( - @NonNull Request request, - @NonNull Throwable error, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - Node node, - @Nullable ExecutionInfo executionInfo, - @NonNull String requestPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestPrefix) { // nothing to do } @Override public void onNodeError( - @NonNull Request request, - @NonNull Throwable error, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @Nullable ExecutionInfo executionInfo, - @NonNull String requestPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestPrefix) { // nothing to do } @Override public void onNodeSuccess( - @NonNull Request request, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @NonNull ExecutionInfo executionInfo, - @NonNull String requestPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestPrefix) { // nothing to do } diff --git a/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/RequestLogger.java b/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/RequestLogger.java index fa51e281071..635407049fd 100644 --- a/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/RequestLogger.java +++ b/core/src/main/java/com/datastax/oss/driver/internal/core/tracker/RequestLogger.java @@ -26,7 +26,6 @@ import com.datastax.oss.driver.api.core.session.SessionBuilder; import com.datastax.oss.driver.api.core.tracker.RequestTracker; import edu.umd.cs.findbugs.annotations.NonNull; -import edu.umd.cs.findbugs.annotations.Nullable; import java.time.Duration; import net.jcip.annotations.ThreadSafe; import org.slf4j.Logger; @@ -84,13 +83,9 @@ protected RequestLogger(RequestLogFormatter formatter) { @Override public void onSuccess( - @NonNull Request request, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @NonNull ExecutionInfo executionInfo, - @NonNull String logPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { + DriverExecutionProfile executionProfile = executionInfo.getExecutionProfile(); boolean successEnabled = executionProfile.getBoolean(DefaultDriverOption.REQUEST_LOGGER_SUCCESS_ENABLED, false); boolean slowEnabled = @@ -124,10 +119,10 @@ public void onSuccess( DEFAULT_REQUEST_LOGGER_MAX_VALUE_LENGTH); logSuccess( - request, + executionInfo.getRequest(), latencyNanos, isSlow, - node, + executionInfo.getCoordinator(), maxQueryLength, showValues, maxValues, @@ -137,14 +132,9 @@ public void onSuccess( @Override public void onError( - @NonNull Request request, - @NonNull Throwable error, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - Node node, - @NonNull ExecutionInfo executionInfo, - @NonNull String logPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { + DriverExecutionProfile executionProfile = executionInfo.getExecutionProfile(); if (!executionProfile.getBoolean(DefaultDriverOption.REQUEST_LOGGER_ERROR_ENABLED, false)) { return; } @@ -168,10 +158,10 @@ public void onError( executionProfile.getBoolean(DefaultDriverOption.REQUEST_LOGGER_STACK_TRACES, false); logError( - request, - error, + executionInfo.getRequest(), + executionInfo.getDriverError(), latencyNanos, - node, + executionInfo.getCoordinator(), maxQueryLength, showValues, maxValues, @@ -182,24 +172,13 @@ public void onError( @Override public void onNodeError( - @NonNull Request request, - @NonNull Throwable error, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @Nullable ExecutionInfo executionInfo, - @NonNull String logPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { // Nothing to do } @Override public void onNodeSuccess( - @NonNull Request request, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @NonNull ExecutionInfo executionInfo, - @NonNull String logPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { // Nothing to do } diff --git a/core/src/test/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousCqlRequestHandlerTest.java b/core/src/test/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousCqlRequestHandlerTest.java index 29709e0b11d..2c9ed24e0cf 100644 --- a/core/src/test/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousCqlRequestHandlerTest.java +++ b/core/src/test/java/com/datastax/dse/driver/internal/core/cql/continuous/ContinuousCqlRequestHandlerTest.java @@ -23,15 +23,14 @@ import static com.datastax.dse.protocol.internal.DseProtocolConstants.RevisionType.MORE_CONTINUOUS_PAGES; import static com.datastax.oss.driver.Assertions.assertThat; import static com.datastax.oss.driver.Assertions.assertThatStage; +import static com.datastax.oss.driver.internal.core.cql.CqlRequestHandlerTrackerTest.execInfoMatcher; import static org.assertj.core.api.Assertions.assertThatThrownBy; import static org.mockito.ArgumentMatchers.any; import static org.mockito.ArgumentMatchers.anyBoolean; import static org.mockito.ArgumentMatchers.anyLong; import static org.mockito.ArgumentMatchers.anyMap; import static org.mockito.ArgumentMatchers.argThat; -import static org.mockito.ArgumentMatchers.eq; import static org.mockito.ArgumentMatchers.matches; -import static org.mockito.ArgumentMatchers.nullable; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.never; import static org.mockito.Mockito.verify; @@ -47,7 +46,6 @@ import com.datastax.oss.driver.api.core.DriverTimeoutException; import com.datastax.oss.driver.api.core.NoNodeAvailableException; import com.datastax.oss.driver.api.core.ProtocolVersion; -import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.cql.Row; import com.datastax.oss.driver.api.core.servererrors.BootstrappingException; @@ -494,28 +492,22 @@ public void should_invoke_request_tracker(DseProtocolVersion version) { verify(requestTracker) .onNodeError( - eq(UNDEFINED_IDEMPOTENCE_STATEMENT), - any(BootstrappingException.class), anyLong(), - any(DriverExecutionProfile.class), - eq(node1), - nullable(ExecutionInfo.class), + argThat( + execInfoMatcher( + node1, + UNDEFINED_IDEMPOTENCE_STATEMENT, + BootstrappingException.class)), matches(LOG_PREFIX_PER_REQUEST)); verify(requestTracker) .onNodeSuccess( - eq(UNDEFINED_IDEMPOTENCE_STATEMENT), anyLong(), - any(DriverExecutionProfile.class), - eq(node2), - any(ExecutionInfo.class), + argThat(execInfoMatcher(node2, UNDEFINED_IDEMPOTENCE_STATEMENT, null)), matches(LOG_PREFIX_PER_REQUEST)); verify(requestTracker) .onSuccess( - eq(UNDEFINED_IDEMPOTENCE_STATEMENT), anyLong(), - any(DriverExecutionProfile.class), - eq(node2), - any(ExecutionInfo.class), + argThat(execInfoMatcher(node2, UNDEFINED_IDEMPOTENCE_STATEMENT, null)), matches(LOG_PREFIX_PER_REQUEST)); verifyNoMoreInteractions(requestTracker); }); diff --git a/core/src/test/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandlerTest.java b/core/src/test/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandlerTest.java index 09713b4ac6e..1989477561d 100644 --- a/core/src/test/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandlerTest.java +++ b/core/src/test/java/com/datastax/dse/driver/internal/core/graph/GraphRequestHandlerTest.java @@ -26,9 +26,11 @@ import static com.datastax.dse.driver.internal.core.graph.GraphTestUtils.singleGraphRow; import static com.datastax.oss.driver.api.core.type.codec.TypeCodecs.BIGINT; import static com.datastax.oss.driver.api.core.type.codec.TypeCodecs.TEXT; +import static com.datastax.oss.driver.internal.core.cql.CqlRequestHandlerTrackerTest.execInfoMatcher; import static org.assertj.core.api.Assertions.assertThat; import static org.mockito.ArgumentMatchers.any; import static org.mockito.ArgumentMatchers.anyLong; +import static org.mockito.ArgumentMatchers.argThat; import static org.mockito.ArgumentMatchers.eq; import static org.mockito.ArgumentMatchers.matches; import static org.mockito.Mockito.mock; @@ -56,7 +58,6 @@ import com.datastax.oss.driver.api.core.Version; import com.datastax.oss.driver.api.core.config.DefaultDriverOption; import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; -import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.tracker.RequestTracker; import com.datastax.oss.driver.api.core.uuid.Uuids; import com.datastax.oss.driver.internal.core.cql.Conversions; @@ -518,19 +519,13 @@ public void should_invoke_request_tracker_and_update_metrics( verify(requestTracker) .onSuccess( - eq(graphStatement), anyLong(), - any(DriverExecutionProfile.class), - eq(node), - any(ExecutionInfo.class), + argThat(execInfoMatcher(node, graphStatement, null)), matches(LOG_PREFIX_PER_REQUEST)); verify(requestTracker) .onNodeSuccess( - eq(graphStatement), anyLong(), - any(DriverExecutionProfile.class), - eq(node), - any(ExecutionInfo.class), + argThat(execInfoMatcher(node, graphStatement, null)), matches(LOG_PREFIX_PER_REQUEST)); verifyNoMoreInteractions(requestTracker); diff --git a/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandlerTrackerTest.java b/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandlerTrackerTest.java index 035bf116f92..48833ab9534 100644 --- a/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandlerTrackerTest.java +++ b/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlPrepareHandlerTrackerTest.java @@ -19,6 +19,8 @@ import static com.datastax.oss.driver.Assertions.assertThatStage; import static com.datastax.oss.driver.internal.core.cql.CqlRequestHandlerTestBase.defaultFrameOf; +import static com.datastax.oss.driver.internal.core.cql.CqlRequestHandlerTrackerTest.execInfoMatcher; +import static org.mockito.ArgumentMatchers.argThat; import static org.mockito.Mockito.any; import static org.mockito.Mockito.anyLong; import static org.mockito.Mockito.eq; @@ -29,7 +31,6 @@ import static org.mockito.Mockito.when; import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; -import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.cql.PreparedStatement; import com.datastax.oss.driver.api.core.servererrors.BootstrappingException; import com.datastax.oss.driver.api.core.tracker.RequestTracker; @@ -74,12 +75,9 @@ public void should_invoke_request_tracker() { any(String.class)); verify(requestTracker) .onNodeError( - eq(PREPARE_REQUEST), - any(BootstrappingException.class), anyLong(), - any(DriverExecutionProfile.class), - eq(node1), - any(ExecutionInfo.class), + argThat( + execInfoMatcher(node1, PREPARE_REQUEST, BootstrappingException.class)), any(String.class)); verify(requestTracker) .onRequestCreatedForNode( @@ -89,19 +87,13 @@ public void should_invoke_request_tracker() { any(String.class)); verify(requestTracker) .onNodeSuccess( - eq(PREPARE_REQUEST), anyLong(), - any(DriverExecutionProfile.class), - eq(node2), - any(ExecutionInfo.class), + argThat(execInfoMatcher(node2, PREPARE_REQUEST, null)), any(String.class)); verify(requestTracker) .onSuccess( - eq(PREPARE_REQUEST), anyLong(), - any(DriverExecutionProfile.class), - eq(node2), - any(ExecutionInfo.class), + argThat(execInfoMatcher(node2, PREPARE_REQUEST, null)), any(String.class)); verifyNoMoreInteractions(requestTracker); }); diff --git a/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandlerTrackerTest.java b/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandlerTrackerTest.java index e331c68092d..e25726e8e4b 100644 --- a/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandlerTrackerTest.java +++ b/core/src/test/java/com/datastax/oss/driver/internal/core/cql/CqlRequestHandlerTrackerTest.java @@ -21,8 +21,8 @@ import static org.assertj.core.api.Assertions.assertThat; import static org.mockito.ArgumentMatchers.any; import static org.mockito.ArgumentMatchers.anyLong; +import static org.mockito.ArgumentMatchers.argThat; import static org.mockito.ArgumentMatchers.eq; -import static org.mockito.ArgumentMatchers.nullable; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.mockingDetails; import static org.mockito.Mockito.spy; @@ -50,7 +50,6 @@ import com.datastax.oss.protocol.internal.response.result.Prepared; import com.datastax.oss.protocol.internal.util.Bytes; import java.nio.ByteBuffer; -import java.util.ArrayList; import java.util.Collections; import java.util.List; import java.util.concurrent.CompletionStage; @@ -58,6 +57,7 @@ import java.util.concurrent.ConcurrentMap; import java.util.regex.Pattern; import org.junit.Test; +import org.mockito.ArgumentMatcher; import org.mockito.invocation.Invocation; public class CqlRequestHandlerTrackerTest extends CqlRequestHandlerTestBase { @@ -109,63 +109,34 @@ public void should_invoke_request_tracker() { any(String.class)); verify(requestTracker) .onNodeError( - eq(UNDEFINED_IDEMPOTENCE_STATEMENT), - any(BootstrappingException.class), anyLong(), - any(DriverExecutionProfile.class), - eq(node1), - nullable(ExecutionInfo.class), + argThat( + execInfoMatcher( + node1, + UNDEFINED_IDEMPOTENCE_STATEMENT, + BootstrappingException.class)), any(String.class)); verify(requestTracker) - .onNodeSuccess( + .onRequestCreatedForNode( eq(UNDEFINED_IDEMPOTENCE_STATEMENT), - anyLong(), any(DriverExecutionProfile.class), eq(node2), - any(ExecutionInfo.class), any(String.class)); verify(requestTracker) - .onRequestCreatedForNode( - eq(UNDEFINED_IDEMPOTENCE_STATEMENT), - any(DriverExecutionProfile.class), - eq(node2), + .onNodeSuccess( + anyLong(), + argThat(execInfoMatcher(node2, UNDEFINED_IDEMPOTENCE_STATEMENT, null)), any(String.class)); verify(requestTracker) .onSuccess( - eq(UNDEFINED_IDEMPOTENCE_STATEMENT), anyLong(), - any(DriverExecutionProfile.class), - eq(node2), - any(ExecutionInfo.class), + argThat(execInfoMatcher(node2, UNDEFINED_IDEMPOTENCE_STATEMENT, null)), any(String.class)); verifyNoMoreInteractions(requestTracker); }); - - // verify that passed ExecutionInfo object had correct details - List invocations = - new ArrayList<>(mockingDetails(requestTracker).getInvocations()); - checkExecutionInfo( - (ExecutionInfo) invocations.get(2).getRawArguments()[5], - UNDEFINED_IDEMPOTENCE_STATEMENT, - node1); - checkExecutionInfo( - (ExecutionInfo) invocations.get(4).getRawArguments()[4], - UNDEFINED_IDEMPOTENCE_STATEMENT, - node2); - checkExecutionInfo( - (ExecutionInfo) invocations.get(5).getRawArguments()[4], - UNDEFINED_IDEMPOTENCE_STATEMENT, - node2); } } - private void checkExecutionInfo( - ExecutionInfo executionInfo, Request expectedRequest, Node expectedNode) { - assertThat(executionInfo.getRequest()).isEqualTo(expectedRequest); - assertThat(executionInfo.getExecutionProfile()).isNotNull(); - assertThat(executionInfo.getCoordinator()).isEqualTo(expectedNode); - } - @Test public void should_not_invoke_noop_request_tracker() { try (RequestHandlerTestHarness harness = @@ -248,54 +219,54 @@ public void should_invoke_implicit_prepare_request_tracker() { (List) mockingDetails(requestTracker).getInvocations(); assertThat(invocations).hasSize(10); // start processing CQL statement - checkInvocation( + checkOnCreateInvocation( invocations.get(0), ON_REQUEST_CREATED, DefaultSimpleStatement.class, LOG_PREFIX_PER_REQUEST); - checkInvocation( + checkOnCreateInvocation( invocations.get(1), ON_REQUEST_CREATED_FOR_NODE, DefaultSimpleStatement.class, LOG_PREFIX_WITH_EXECUTION_NUMBER); - checkInvocation( + checkOnEndInvocation( invocations.get(2), ON_NODE_ERROR, DefaultSimpleStatement.class, LOG_PREFIX_WITH_EXECUTION_NUMBER); // implicit reprepare statement - checkInvocation( + checkOnCreateInvocation( invocations.get(3), ON_REQUEST_CREATED, DefaultPrepareRequest.class, LOG_PREFIX_WITH_EXECUTION_NUMBER); - checkInvocation( + checkOnCreateInvocation( invocations.get(4), ON_REQUEST_CREATED_FOR_NODE, DefaultPrepareRequest.class, LOG_PREFIX_WITH_EXECUTION_NUMBER); - checkInvocation( + checkOnEndInvocation( invocations.get(5), ON_NODE_SUCCESS, DefaultPrepareRequest.class, LOG_PREFIX_WITH_EXECUTION_NUMBER); - checkInvocation( + checkOnEndInvocation( invocations.get(6), ON_SUCCESS, DefaultPrepareRequest.class, LOG_PREFIX_WITH_EXECUTION_NUMBER); // send new statement and process it - checkInvocation( + checkOnCreateInvocation( invocations.get(7), ON_REQUEST_CREATED_FOR_NODE, DefaultSimpleStatement.class, LOG_PREFIX_WITH_EXECUTION_NUMBER); - checkInvocation( + checkOnEndInvocation( invocations.get(8), ON_NODE_SUCCESS, DefaultSimpleStatement.class, LOG_PREFIX_WITH_EXECUTION_NUMBER); - checkInvocation( + checkOnEndInvocation( invocations.get(9), ON_SUCCESS, DefaultSimpleStatement.class, @@ -304,11 +275,32 @@ public void should_invoke_implicit_prepare_request_tracker() { } } - private void checkInvocation( + private void checkOnCreateInvocation( Invocation invocation, String methodName, Class firstParameter, Pattern logPrefixPattern) { assertThat(invocation.getMethod().getName()).isEqualTo(methodName); assertThat(invocation.getArguments()[0]).isInstanceOf(firstParameter); String logPrefix = invocation.getArguments()[invocation.getArguments().length - 1].toString(); assertThat(logPrefix).matches(logPrefixPattern); } + + private void checkOnEndInvocation( + Invocation invocation, String methodName, Class firstParameter, Pattern logPrefixPattern) { + assertThat(invocation.getMethod().getName()).isEqualTo(methodName); + assertThat(((ExecutionInfo) invocation.getArguments()[1]).getRequest()) + .isInstanceOf(firstParameter); + String logPrefix = invocation.getArguments()[invocation.getArguments().length - 1].toString(); + assertThat(logPrefix).matches(logPrefixPattern); + } + + public static ArgumentMatcher execInfoMatcher( + Node node, Request request, Class errorClass) { + return executionInfo -> + node.equals(executionInfo.getCoordinator()) + && request.equals(executionInfo.getRequest()) + && (errorClass != null + ? executionInfo.getDriverError() != null + && executionInfo.getDriverError().getClass().isAssignableFrom(errorClass) + : executionInfo.getDriverError() == null) + && executionInfo.getExecutionProfile() != null; + } } diff --git a/core/src/test/java/com/datastax/oss/driver/internal/core/loadbalancing/DefaultLoadBalancingPolicyRequestTrackerTest.java b/core/src/test/java/com/datastax/oss/driver/internal/core/loadbalancing/DefaultLoadBalancingPolicyRequestTrackerTest.java index 468c92ba0a3..ebcb21faaf8 100644 --- a/core/src/test/java/com/datastax/oss/driver/internal/core/loadbalancing/DefaultLoadBalancingPolicyRequestTrackerTest.java +++ b/core/src/test/java/com/datastax/oss/driver/internal/core/loadbalancing/DefaultLoadBalancingPolicyRequestTrackerTest.java @@ -22,8 +22,11 @@ import static org.mockito.BDDMockito.given; import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; -import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.session.Request; +import com.datastax.oss.driver.internal.core.context.InternalDriverContext; +import com.datastax.oss.driver.internal.core.cql.DefaultExecutionInfo; +import com.datastax.oss.driver.internal.core.metadata.DefaultNode; +import com.datastax.oss.driver.internal.core.session.DefaultSession; import com.datastax.oss.driver.shaded.guava.common.collect.ImmutableMap; import com.datastax.oss.driver.shaded.guava.common.collect.ImmutableSet; import java.util.UUID; @@ -35,7 +38,8 @@ public class DefaultLoadBalancingPolicyRequestTrackerTest extends LoadBalancingP @Mock Request request; @Mock DriverExecutionProfile profile; - @Mock ExecutionInfo executionInfo; + @Mock DefaultSession session; + @Mock InternalDriverContext driverContext; final String logPrefix = "lbp-test-log-prefix"; private DefaultLoadBalancingPolicy policy; @@ -67,7 +71,7 @@ public void should_record_first_response_time_on_node_success() { nextNanoTime = 123; // When - policy.onNodeSuccess(request, 0, profile, node1, executionInfo, logPrefix); + policy.onNodeSuccess(0, createExecutionInfo(node1, null), logPrefix); // Then assertThat(policy.responseTimes) @@ -85,7 +89,7 @@ public void should_record_second_response_time_on_node_success() { nextNanoTime = 456; // When - policy.onNodeSuccess(request, 0, profile, node1, executionInfo, logPrefix); + policy.onNodeSuccess(0, createExecutionInfo(node1, null), logPrefix); // Then assertThat(policy.responseTimes) @@ -109,8 +113,8 @@ public void should_record_further_response_times_on_node_success() { nextNanoTime = 789; // When - policy.onNodeSuccess(request, 0, profile, node1, executionInfo, logPrefix); - policy.onNodeSuccess(request, 0, profile, node2, executionInfo, logPrefix); + policy.onNodeSuccess(0, createExecutionInfo(node1, null), logPrefix); + policy.onNodeSuccess(0, createExecutionInfo(node2, null), logPrefix); // Then assertThat(policy.responseTimes) @@ -135,7 +139,7 @@ public void should_record_first_response_time_on_node_error() { Throwable iae = new IllegalArgumentException(); // When - policy.onNodeError(request, iae, 0, profile, node1, executionInfo, logPrefix); + policy.onNodeError(0, createExecutionInfo(node1, iae), logPrefix); // Then assertThat(policy.responseTimes) @@ -154,7 +158,7 @@ public void should_record_second_response_time_on_node_error() { Throwable iae = new IllegalArgumentException(); // When - policy.onNodeError(request, iae, 0, profile, node1, executionInfo, logPrefix); + policy.onNodeError(0, createExecutionInfo(node1, iae), logPrefix); // Then assertThat(policy.responseTimes) @@ -179,8 +183,8 @@ public void should_record_further_response_times_on_node_error() { Throwable iae = new IllegalArgumentException(); // When - policy.onNodeError(request, iae, 0, profile, node1, executionInfo, logPrefix); - policy.onNodeError(request, iae, 0, profile, node2, executionInfo, logPrefix); + policy.onNodeError(0, createExecutionInfo(node1, iae), logPrefix); + policy.onNodeError(0, createExecutionInfo(node2, iae), logPrefix); // Then assertThat(policy.responseTimes) @@ -197,4 +201,10 @@ public void should_record_further_response_times_on_node_error() { assertThat(policy.isResponseRateInsufficient(node2, nextNanoTime)).isFalse(); assertThat(policy.isResponseRateInsufficient(node3, nextNanoTime)).isFalse(); } + + private DefaultExecutionInfo createExecutionInfo(DefaultNode node, Throwable error) { + return new DefaultExecutionInfo.Builder( + request, node, -1, 0, error, null, session, driverContext, profile) + .build(); + } } diff --git a/core/src/test/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTrackerTest.java b/core/src/test/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTrackerTest.java index adbad606712..0f262c8bd8b 100644 --- a/core/src/test/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTrackerTest.java +++ b/core/src/test/java/com/datastax/oss/driver/internal/core/tracker/MultiplexingRequestTrackerTest.java @@ -17,7 +17,11 @@ */ package com.datastax.oss.driver.internal.core.tracker; +import static com.datastax.oss.driver.internal.core.cql.CqlRequestHandlerTrackerTest.execInfoMatcher; import static org.assertj.core.api.Assertions.assertThat; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.ArgumentMatchers.argThat; +import static org.mockito.ArgumentMatchers.eq; import static org.mockito.BDDMockito.given; import static org.mockito.BDDMockito.willThrow; import static org.mockito.Mockito.verify; @@ -28,11 +32,12 @@ import ch.qos.logback.core.Appender; import com.datastax.oss.driver.api.core.DriverExecutionException; import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; -import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.metadata.Node; import com.datastax.oss.driver.api.core.session.Request; -import com.datastax.oss.driver.api.core.session.Session; import com.datastax.oss.driver.api.core.tracker.RequestTracker; +import com.datastax.oss.driver.internal.core.context.InternalDriverContext; +import com.datastax.oss.driver.internal.core.cql.DefaultExecutionInfo; +import com.datastax.oss.driver.internal.core.session.DefaultSession; import org.junit.After; import org.junit.Before; import org.junit.Test; @@ -51,8 +56,8 @@ public class MultiplexingRequestTrackerTest { @Mock private Request request; @Mock private DriverExecutionProfile profile; @Mock private Node node; - @Mock private Session session; - @Mock private ExecutionInfo executionInfo; + @Mock private DefaultSession session; + @Mock private InternalDriverContext driverContext; @Mock private Appender appender; @Captor private ArgumentCaptor loggingEventCaptor; @@ -111,14 +116,16 @@ public void should_flatten_child_multiplexing_tracker_via_register() { public void should_notify_onSuccess() { // given MultiplexingRequestTracker tracker = new MultiplexingRequestTracker(child1, child2); - willThrow(new NullPointerException()) - .given(child1) - .onSuccess(request, 123456L, profile, node, executionInfo, "test"); + willThrow(new NullPointerException()).given(child1).onSuccess(eq(123456L), any(), eq("test")); // when - tracker.onSuccess(request, 123456L, profile, node, executionInfo, "test"); + tracker.onSuccess(123456L, createExecutionInfo(), "test"); // then - verify(child1).onSuccess(request, 123456L, profile, node, executionInfo, "test"); - verify(child2).onSuccess(request, 123456L, profile, node, executionInfo, "test"); + verify(child1) + .onSuccess( + eq(123456L), argThat(execInfoMatcher(node, request, error.getClass())), eq("test")); + verify(child2) + .onSuccess( + eq(123456L), argThat(execInfoMatcher(node, request, error.getClass())), eq("test")); verify(appender).doAppend(loggingEventCaptor.capture()); assertThat(loggingEventCaptor.getAllValues().stream().map(ILoggingEvent::getFormattedMessage)) .contains( @@ -129,14 +136,16 @@ public void should_notify_onSuccess() { public void should_notify_onError() { // given MultiplexingRequestTracker tracker = new MultiplexingRequestTracker(child1, child2); - willThrow(new NullPointerException()) - .given(child1) - .onError(request, error, 123456L, profile, node, executionInfo, "test"); + willThrow(new NullPointerException()).given(child1).onError(eq(123456L), any(), eq("test")); // when - tracker.onError(request, error, 123456L, profile, node, executionInfo, "test"); + tracker.onError(123456L, createExecutionInfo(), "test"); // then - verify(child1).onError(request, error, 123456L, profile, node, executionInfo, "test"); - verify(child2).onError(request, error, 123456L, profile, node, executionInfo, "test"); + verify(child1) + .onError( + eq(123456L), argThat(execInfoMatcher(node, request, error.getClass())), eq("test")); + verify(child2) + .onError( + eq(123456L), argThat(execInfoMatcher(node, request, error.getClass())), eq("test")); verify(appender).doAppend(loggingEventCaptor.capture()); assertThat(loggingEventCaptor.getAllValues().stream().map(ILoggingEvent::getFormattedMessage)) .contains( @@ -149,12 +158,16 @@ public void should_notify_onNodeSuccess() { MultiplexingRequestTracker tracker = new MultiplexingRequestTracker(child1, child2); willThrow(new NullPointerException()) .given(child1) - .onNodeSuccess(request, 123456L, profile, node, executionInfo, "test"); + .onNodeSuccess(eq(123456L), any(), eq("test")); // when - tracker.onNodeSuccess(request, 123456L, profile, node, executionInfo, "test"); + tracker.onNodeSuccess(123456L, createExecutionInfo(), "test"); // then - verify(child1).onNodeSuccess(request, 123456L, profile, node, executionInfo, "test"); - verify(child2).onNodeSuccess(request, 123456L, profile, node, executionInfo, "test"); + verify(child1) + .onNodeSuccess( + eq(123456L), argThat(execInfoMatcher(node, request, error.getClass())), eq("test")); + verify(child2) + .onNodeSuccess( + eq(123456L), argThat(execInfoMatcher(node, request, error.getClass())), eq("test")); verify(appender).doAppend(loggingEventCaptor.capture()); assertThat(loggingEventCaptor.getAllValues().stream().map(ILoggingEvent::getFormattedMessage)) .contains( @@ -165,14 +178,16 @@ public void should_notify_onNodeSuccess() { public void should_notify_onNodeError() { // given MultiplexingRequestTracker tracker = new MultiplexingRequestTracker(child1, child2); - willThrow(new NullPointerException()) - .given(child1) - .onNodeError(request, error, 123456L, profile, node, executionInfo, "test"); + willThrow(new NullPointerException()).given(child1).onNodeError(eq(123456L), any(), eq("test")); // when - tracker.onNodeError(request, error, 123456L, profile, node, executionInfo, "test"); + tracker.onNodeError(123456L, createExecutionInfo(), "test"); // then - verify(child1).onNodeError(request, error, 123456L, profile, node, executionInfo, "test"); - verify(child2).onNodeError(request, error, 123456L, profile, node, executionInfo, "test"); + verify(child1) + .onNodeError( + eq(123456L), argThat(execInfoMatcher(node, request, error.getClass())), eq("test")); + verify(child2) + .onNodeError( + eq(123456L), argThat(execInfoMatcher(node, request, error.getClass())), eq("test")); verify(appender).doAppend(loggingEventCaptor.capture()); assertThat(loggingEventCaptor.getAllValues().stream().map(ILoggingEvent::getFormattedMessage)) .contains( @@ -212,4 +227,10 @@ public void should_notify_close() throws Exception { .contains( "Unexpected error while closing request tracker child1. (NullPointerException: null)"); } + + private DefaultExecutionInfo createExecutionInfo() { + return new DefaultExecutionInfo.Builder( + request, node, -1, 0, error, null, session, driverContext, profile) + .build(); + } } diff --git a/integration-tests/src/test/java/com/datastax/oss/driver/core/cql/PagingIterableSpliteratorIT.java b/integration-tests/src/test/java/com/datastax/oss/driver/core/cql/PagingIterableSpliteratorIT.java index 403b42febd4..fa2d201323a 100644 --- a/integration-tests/src/test/java/com/datastax/oss/driver/core/cql/PagingIterableSpliteratorIT.java +++ b/integration-tests/src/test/java/com/datastax/oss/driver/core/cql/PagingIterableSpliteratorIT.java @@ -44,7 +44,6 @@ import com.tngtech.java.junit.dataprovider.DataProviderRunner; import com.tngtech.java.junit.dataprovider.UseDataProvider; import edu.umd.cs.findbugs.annotations.NonNull; -import edu.umd.cs.findbugs.annotations.Nullable; import java.util.ArrayList; import java.util.Collections; import java.util.Iterator; @@ -221,55 +220,35 @@ public synchronized void onRequestCreatedForNode( @Override public synchronized void onNodeSuccess( - @NonNull Request request, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @Nullable ExecutionInfo executionInfo, - @NonNull String requestLogPrefix) { - if (shouldRecord(request)) { - successfulRequestsAtNode.add(Pair.of(request, node)); + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { + if (shouldRecord(executionInfo.getRequest())) { + successfulRequestsAtNode.add( + Pair.of(executionInfo.getRequest(), executionInfo.getCoordinator())); } } @Override public synchronized void onSuccess( - @NonNull Request request, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @Nullable ExecutionInfo executionInfo, - @NonNull String requestLogPrefix) { - if (shouldRecord(request)) { - successfulRequests.add(request); + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { + if (shouldRecord(executionInfo.getRequest())) { + successfulRequests.add(executionInfo.getRequest()); } } @Override public synchronized void onNodeError( - @NonNull Request request, - @NonNull Throwable error, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @Nullable ExecutionInfo executionInfo, - @NonNull String requestLogPrefix) { - if (shouldRecord(request)) { - errorRequestsAtNode.add(Pair.of(request, node)); + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { + if (shouldRecord(executionInfo.getRequest())) { + errorRequestsAtNode.add( + Pair.of(executionInfo.getRequest(), executionInfo.getCoordinator())); } } @Override public synchronized void onError( - @NonNull Request request, - @NonNull Throwable error, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @Nullable Node node, - @Nullable ExecutionInfo executionInfo, - @NonNull String requestLogPrefix) { - if (shouldRecord(request)) { - errorRequests.add(request); + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { + if (shouldRecord(executionInfo.getRequest())) { + errorRequests.add(executionInfo.getRequest()); } } diff --git a/integration-tests/src/test/java/com/datastax/oss/driver/core/tracker/RequestNodeLoggerExample.java b/integration-tests/src/test/java/com/datastax/oss/driver/core/tracker/RequestNodeLoggerExample.java index f22475b5aca..53393af278b 100644 --- a/integration-tests/src/test/java/com/datastax/oss/driver/core/tracker/RequestNodeLoggerExample.java +++ b/integration-tests/src/test/java/com/datastax/oss/driver/core/tracker/RequestNodeLoggerExample.java @@ -21,12 +21,9 @@ import com.datastax.oss.driver.api.core.config.DriverExecutionProfile; import com.datastax.oss.driver.api.core.context.DriverContext; import com.datastax.oss.driver.api.core.cql.ExecutionInfo; -import com.datastax.oss.driver.api.core.metadata.Node; -import com.datastax.oss.driver.api.core.session.Request; import com.datastax.oss.driver.internal.core.tracker.RequestLogFormatter; import com.datastax.oss.driver.internal.core.tracker.RequestLogger; import edu.umd.cs.findbugs.annotations.NonNull; -import edu.umd.cs.findbugs.annotations.Nullable; public class RequestNodeLoggerExample extends RequestLogger { @@ -36,13 +33,8 @@ public RequestNodeLoggerExample(DriverContext context) { @Override public void onNodeError( - @NonNull Request request, - @NonNull Throwable error, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @Nullable ExecutionInfo executionInfo, - @NonNull String logPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { + DriverExecutionProfile executionProfile = executionInfo.getExecutionProfile(); if (!executionProfile.getBoolean(DefaultDriverOption.REQUEST_LOGGER_ERROR_ENABLED)) { return; } @@ -60,10 +52,10 @@ public void onNodeError( executionProfile.getBoolean(DefaultDriverOption.REQUEST_LOGGER_STACK_TRACES); logError( - request, - error, + executionInfo.getRequest(), + executionInfo.getDriverError(), latencyNanos, - node, + executionInfo.getCoordinator(), maxQueryLength, showValues, maxValues, @@ -74,12 +66,8 @@ public void onNodeError( @Override public void onNodeSuccess( - @NonNull Request request, - long latencyNanos, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @NonNull ExecutionInfo executionInfo, - @NonNull String logPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String logPrefix) { + DriverExecutionProfile executionProfile = executionInfo.getExecutionProfile(); boolean successEnabled = executionProfile.getBoolean(DefaultDriverOption.REQUEST_LOGGER_SUCCESS_ENABLED); boolean slowEnabled = @@ -110,10 +98,10 @@ public void onNodeSuccess( : 0; logSuccess( - request, + executionInfo.getRequest(), latencyNanos, isSlow, - node, + executionInfo.getCoordinator(), maxQueryLength, showValues, maxValues,