From 92b6eee2b5bcb839ca5694d40d81d36a2f269353 Mon Sep 17 00:00:00 2001 From: Andrew Weaver Date: Mon, 5 Jun 2023 14:54:04 -0500 Subject: [PATCH 01/13] 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 02/13] 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 03/13] 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 04/13] 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, From b4949a8d06461ccc6b8880be79a3442a7787e522 Mon Sep 17 00:00:00 2001 From: SiyaoIsHiding <113857408+SiyaoIsHiding@users.noreply.github.com> Date: Mon, 6 Jan 2025 13:17:01 +0800 Subject: [PATCH 05/13] adding another module? --- bom/pom.xml | 5 + open-telemetry/pom.xml | 138 ++++++++++++++++++ .../core/tracker/OtelRequestTracker.java | 58 ++++++++ pom.xml | 1 + 4 files changed, 202 insertions(+) create mode 100644 open-telemetry/pom.xml create mode 100644 open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java diff --git a/bom/pom.xml b/bom/pom.xml index 08f212f6157..8473228f63c 100644 --- a/bom/pom.xml +++ b/bom/pom.xml @@ -75,6 +75,11 @@ java-driver-metrics-microprofile 4.18.2-SNAPSHOT + + org.apache.cassandra + java-driver-open-telemetry + 4.18.2-SNAPSHOT + com.datastax.oss native-protocol diff --git a/open-telemetry/pom.xml b/open-telemetry/pom.xml new file mode 100644 index 00000000000..904675c3038 --- /dev/null +++ b/open-telemetry/pom.xml @@ -0,0 +1,138 @@ + + + + 4.0.0 + + org.apache.cassandra + java-driver-parent + 4.18.2-SNAPSHOT + ../ + + java-driver-open-telemetry + bundle + Apache Cassandra Java Driver - OpenTelemetry + + + + ${project.groupId} + java-driver-bom + ${project.version} + pom + import + + + + + + org.apache.cassandra + java-driver-core + + + com.github.stephenc.jcip + jcip-annotations + provided + + + com.github.spotbugs + spotbugs-annotations + provided + + + ch.qos.logback + logback-classic + test + + + junit + junit + test + + + com.tngtech.java + junit-dataprovider + test + + + org.assertj + assertj-core + test + + + org.mockito + mockito-core + test + + + org.apache.cassandra + java-driver-core + test + test-jar + + + + + + src/main/resources + + + ${project.basedir}/.. + + LICENSE + NOTICE_binary.txt + NOTICE.txt + + META-INF + + + + + maven-jar-plugin + + + + javadoc-jar + package + + jar + + + javadoc + + ** + + + + + + + org.revapi + revapi-maven-plugin + + + true + + + + + diff --git a/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java b/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java new file mode 100644 index 00000000000..f5038c55a1e --- /dev/null +++ b/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java @@ -0,0 +1,58 @@ +/* + * 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.tracker; + +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.session.Request; +import com.datastax.oss.driver.api.core.session.Session; +import com.datastax.oss.driver.api.core.tracker.RequestTracker; +import edu.umd.cs.findbugs.annotations.NonNull; +import edu.umd.cs.findbugs.annotations.Nullable; + +public class OtelRequestTracker implements RequestTracker { + @Override + public void close() throws Exception { + + } + + @Override + public void onSuccess(@NonNull Request request, long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, @NonNull String requestLogPrefix) { + RequestTracker.super.onSuccess(request, latencyNanos, executionProfile, node, requestLogPrefix); + } + + @Override + public void onError(@NonNull Request request, @NonNull Throwable error, long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @Nullable Node node, @NonNull String requestLogPrefix) { + RequestTracker.super.onError(request, error, latencyNanos, executionProfile, node, requestLogPrefix); + } + + @Override + public void onNodeError(@NonNull Request request, @NonNull Throwable error, long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, @NonNull String requestLogPrefix) { + RequestTracker.super.onNodeError(request, error, latencyNanos, executionProfile, node, requestLogPrefix); + } + + @Override + public void onNodeSuccess(@NonNull Request request, long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, @NonNull String requestLogPrefix) { + RequestTracker.super.onNodeSuccess(request, latencyNanos, executionProfile, node, requestLogPrefix); + } + + @Override + public void onSessionReady(@NonNull Session session) { + RequestTracker.super.onSessionReady(session); + } +} \ No newline at end of file diff --git a/pom.xml b/pom.xml index 620cf1db4bb..20bdab9875e 100644 --- a/pom.xml +++ b/pom.xml @@ -40,6 +40,7 @@ mapper-processor metrics/micrometer metrics/microprofile + open-telemetry guava-shaded test-infra integration-tests From dd1652d70d09f3b1aa891564006e9dc385a0f782 Mon Sep 17 00:00:00 2001 From: Jane He Date: Tue, 28 Jan 2025 01:10:54 +0800 Subject: [PATCH 06/13] Implemented OtelRequestTracker --- .../core/tracker/OtelRequestTracker.java | 213 ++++++++++++++++-- 1 file changed, 189 insertions(+), 24 deletions(-) diff --git a/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java b/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java index f5038c55a1e..227e2d7c812 100644 --- a/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java +++ b/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java @@ -18,41 +18,206 @@ 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.cql.Statement; 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.channel.DriverChannel; +import com.datastax.oss.driver.internal.core.context.DefaultDriverContext; +import com.google.common.util.concurrent.ThreadFactoryBuilder; import edu.umd.cs.findbugs.annotations.NonNull; -import edu.umd.cs.findbugs.annotations.Nullable; +import io.opentelemetry.api.OpenTelemetry; +import io.opentelemetry.api.trace.Span; +import io.opentelemetry.api.trace.StatusCode; +import io.opentelemetry.api.trace.Tracer; +import io.opentelemetry.context.Context; +import java.util.Map; +import java.util.Queue; +import java.util.concurrent.ArrayBlockingQueue; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.ThreadPoolExecutor; +import java.util.concurrent.TimeUnit; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +/** TODO: how do we access the context */ public class OtelRequestTracker implements RequestTracker { - @Override - public void close() throws Exception { + // private final OpenTelemetry openTelemetry; - } + private final Map logPrefixToTracingInfoMap = new ConcurrentHashMap<>(); - @Override - public void onSuccess(@NonNull Request request, long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, @NonNull String requestLogPrefix) { - RequestTracker.super.onSuccess(request, latencyNanos, executionProfile, node, requestLogPrefix); - } + private final Tracer tracer; - @Override - public void onError(@NonNull Request request, @NonNull Throwable error, long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @Nullable Node node, @NonNull String requestLogPrefix) { - RequestTracker.super.onError(request, error, latencyNanos, executionProfile, node, requestLogPrefix); - } + private final Logger LOG = LoggerFactory.getLogger(OtelRequestTracker.class); - @Override - public void onNodeError(@NonNull Request request, @NonNull Throwable error, long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, @NonNull String requestLogPrefix) { - RequestTracker.super.onNodeError(request, error, latencyNanos, executionProfile, node, requestLogPrefix); - } + private final ExecutorService threadPool; - @Override - public void onNodeSuccess(@NonNull Request request, long latencyNanos, @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, @NonNull String requestLogPrefix) { - RequestTracker.super.onNodeSuccess(request, latencyNanos, executionProfile, node, requestLogPrefix); - } + // private Session session; + private RequestLogFormatter formatter; + + public OtelRequestTracker(OpenTelemetry openTelemetry) { + // this.openTelemetry = openTelemetry; + this.tracer = + openTelemetry.getTracer("com.datastax.oss.driver.internal.core.tracker.OtelRequestTracker"); + this.threadPool = + new ThreadPoolExecutor( + 1, + Math.max(Runtime.getRuntime().availableProcessors(), 1), + 10, + TimeUnit.SECONDS, + new ArrayBlockingQueue<>(1000), + new ThreadFactoryBuilder().setNameFormat("otel-thread-%d").build(), + new ThreadPoolExecutor.AbortPolicy()); + } + + @Override + public void close() throws Exception { + threadPool.shutdown(); + threadPool.awaitTermination(10, TimeUnit.SECONDS); + logPrefixToTracingInfoMap.clear(); + } + + @Override + public void onRequestCreated( + @NonNull Request request, + @NonNull DriverExecutionProfile executionProfile, + @NonNull String requestLogPrefix) { + Span parentSpan = tracer.spanBuilder("Cassandra Java Driver").startSpan(); + TracingInfo tracingInfo = new TracingInfo(parentSpan); + logPrefixToTracingInfoMap.put(requestLogPrefix, tracingInfo); + addRequestAttributesToSpan(request, parentSpan); + LOG.debug("Request created: {}", requestLogPrefix); + } + + @Override + public void onRequestCreatedForNode( + @NonNull Request request, + @NonNull DriverExecutionProfile executionProfile, + @NonNull Node node, + @NonNull String requestLogPrefix) { + + logPrefixToTracingInfoMap.computeIfPresent( + nodePrefixToRequestPrefix(requestLogPrefix), + (k, v) -> { + Span parentSpan = v.parentSpan; + Span span = + tracer + .spanBuilder("Cassandra Java Driver") + .setParent(Context.current().with(parentSpan)) + .startSpan(); + addRequestAttributesToSpan(request, span); + return v; + }); + LOG.debug("Request created for node: {}", requestLogPrefix); + } - @Override - public void onSessionReady(@NonNull Session session) { - RequestTracker.super.onSessionReady(session); + @Override + public void onSuccess( + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { + logPrefixToTracingInfoMap.computeIfPresent( + requestLogPrefix, + (k, v) -> { + Span span = v.parentSpan; + span.setStatus(StatusCode.OK); + span.end(); + return null; + }); + } + + @Override + public void onError( + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { + logPrefixToTracingInfoMap.computeIfPresent( + requestLogPrefix, + (k, v) -> { + Span span = v.parentSpan; + if (!executionInfo.getErrors().isEmpty()) { + span.recordException(executionInfo.getErrors().get(0).getValue()); + } + span.setStatus(StatusCode.ERROR); + span.end(); + return null; + }); + } + + @Override + public void onNodeSuccess( + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { + logPrefixToTracingInfoMap.computeIfPresent( + nodePrefixToRequestPrefix(requestLogPrefix), + (k, v) -> { + Span span = v.parentSpan; + span.setStatus(StatusCode.OK); + span.end(); + return null; + }); + } + + @Override + public void onNodeError( + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { + logPrefixToTracingInfoMap.computeIfPresent( + nodePrefixToRequestPrefix(requestLogPrefix), + (k, v) -> { + Span span = v.parentSpan; + if (!executionInfo.getErrors().isEmpty()) { + span.recordException(executionInfo.getErrors().get(0).getValue()); + } + span.setStatus(StatusCode.ERROR); + span.end(); + return null; + }); + } + + @Override + public void onSessionReady(@NonNull Session session) { + // this.session = session; + this.formatter = ((DefaultDriverContext) session.getContext()).getRequestLogFormatter(); + } + + private static class TracingInfo { + private final Span parentSpan; + + private TracingInfo(Span parentSpan) { + this.parentSpan = parentSpan; } -} \ No newline at end of file + } + + private void addRequestAttributesToSpan(Request request, Span span) { + if (request.getKeyspace() != null) + span.setAttribute("db.cassandra.keyspace", request.getKeyspace().asCql(true)); + span.setAttribute("db.query.text", statementToString(request)); + if (request.isIdempotent() != null) + span.setAttribute("db.cassandra.idempotence", request.isIdempotent()); + } + + private String statementToString(Request request) { + StringBuilder builder = new StringBuilder(); + assert this.formatter != null; + this.formatter.appendQueryString( + request, RequestLogger.DEFAULT_REQUEST_LOGGER_MAX_QUERY_LENGTH, builder); + this.formatter.appendValues( + request, + RequestLogger.DEFAULT_REQUEST_LOGGER_MAX_VALUES, + RequestLogger.DEFAULT_REQUEST_LOGGER_MAX_VALUE_LENGTH, + true, + builder); + return builder.toString(); + } + + /** + * This depends on the implementation of {@link + * com.datastax.oss.driver.internal.core.cql.CqlRequestHandler.NodeResponseCallback#NodeResponseCallback(Statement, + * Node, Queue, DriverChannel, int, int, boolean, String) NodeResponseCallback} + * + * @param nodePrefix s0|1716164115|0 + * @return the request prefix, like s0|1716164115 + */ + private String nodePrefixToRequestPrefix(String nodePrefix) { + int lastSeparatorIndex = nodePrefix.lastIndexOf("|"); + return nodePrefix.substring(0, lastSeparatorIndex); + } +} From dfc05db73d072efc21a17fcf1e40190741627f89 Mon Sep 17 00:00:00 2001 From: janehe Date: Tue, 4 Feb 2025 02:19:35 -0800 Subject: [PATCH 07/13] can compile --- open-telemetry/pom.xml | 5 + .../core/tracker/OtelRequestTracker.java | 149 +++++++++--------- 2 files changed, 80 insertions(+), 74 deletions(-) diff --git a/open-telemetry/pom.xml b/open-telemetry/pom.xml index 904675c3038..86af50c7be5 100644 --- a/open-telemetry/pom.xml +++ b/open-telemetry/pom.xml @@ -65,6 +65,11 @@ junit test + + io.opentelemetry + opentelemetry-api + 1.36.0 + com.tngtech.java junit-dataprovider diff --git a/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java b/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java index 227e2d7c812..4844159b51b 100644 --- a/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java +++ b/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java @@ -26,7 +26,8 @@ import com.datastax.oss.driver.api.core.tracker.RequestTracker; import com.datastax.oss.driver.internal.core.channel.DriverChannel; import com.datastax.oss.driver.internal.core.context.DefaultDriverContext; -import com.google.common.util.concurrent.ThreadFactoryBuilder; +import com.datastax.oss.driver.internal.core.cql.CqlRequestHandler; +import com.datastax.oss.driver.shaded.guava.common.util.concurrent.ThreadFactoryBuilder; import edu.umd.cs.findbugs.annotations.NonNull; import io.opentelemetry.api.OpenTelemetry; import io.opentelemetry.api.trace.Span; @@ -61,16 +62,16 @@ public class OtelRequestTracker implements RequestTracker { public OtelRequestTracker(OpenTelemetry openTelemetry) { // this.openTelemetry = openTelemetry; this.tracer = - openTelemetry.getTracer("com.datastax.oss.driver.internal.core.tracker.OtelRequestTracker"); + openTelemetry.getTracer("com.datastax.oss.driver.internal.core.tracker.OtelRequestTracker"); this.threadPool = - new ThreadPoolExecutor( - 1, - Math.max(Runtime.getRuntime().availableProcessors(), 1), - 10, - TimeUnit.SECONDS, - new ArrayBlockingQueue<>(1000), - new ThreadFactoryBuilder().setNameFormat("otel-thread-%d").build(), - new ThreadPoolExecutor.AbortPolicy()); + new ThreadPoolExecutor( + 1, + Math.max(Runtime.getRuntime().availableProcessors(), 1), + 10, + TimeUnit.SECONDS, + new ArrayBlockingQueue<>(1000), + new ThreadFactoryBuilder().setNameFormat("otel-thread-%d").build(), + new ThreadPoolExecutor.AbortPolicy()); } @Override @@ -82,9 +83,9 @@ public void close() throws Exception { @Override public void onRequestCreated( - @NonNull Request request, - @NonNull DriverExecutionProfile executionProfile, - @NonNull String requestLogPrefix) { + @NonNull Request request, + @NonNull DriverExecutionProfile executionProfile, + @NonNull String requestLogPrefix) { Span parentSpan = tracer.spanBuilder("Cassandra Java Driver").startSpan(); TracingInfo tracingInfo = new TracingInfo(parentSpan); logPrefixToTracingInfoMap.put(requestLogPrefix, tracingInfo); @@ -94,82 +95,82 @@ public void onRequestCreated( @Override public void onRequestCreatedForNode( - @NonNull Request request, - @NonNull DriverExecutionProfile executionProfile, - @NonNull Node node, - @NonNull String requestLogPrefix) { + @NonNull Request request, + @NonNull DriverExecutionProfile executionProfile, + @NonNull Node node, + @NonNull String requestLogPrefix) { logPrefixToTracingInfoMap.computeIfPresent( - nodePrefixToRequestPrefix(requestLogPrefix), - (k, v) -> { - Span parentSpan = v.parentSpan; - Span span = - tracer - .spanBuilder("Cassandra Java Driver") - .setParent(Context.current().with(parentSpan)) - .startSpan(); - addRequestAttributesToSpan(request, span); - return v; - }); + nodePrefixToRequestPrefix(requestLogPrefix), + (k, v) -> { + Span parentSpan = v.parentSpan; + Span span = + tracer + .spanBuilder("Cassandra Java Driver") + .setParent(Context.current().with(parentSpan)) + .startSpan(); + addRequestAttributesToSpan(request, span); + return v; + }); LOG.debug("Request created for node: {}", requestLogPrefix); } @Override public void onSuccess( - long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { logPrefixToTracingInfoMap.computeIfPresent( - requestLogPrefix, - (k, v) -> { - Span span = v.parentSpan; - span.setStatus(StatusCode.OK); - span.end(); - return null; - }); + requestLogPrefix, + (k, v) -> { + Span span = v.parentSpan; + span.setStatus(StatusCode.OK); + span.end(); + return null; + }); } @Override public void onError( - long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { logPrefixToTracingInfoMap.computeIfPresent( - requestLogPrefix, - (k, v) -> { - Span span = v.parentSpan; - if (!executionInfo.getErrors().isEmpty()) { - span.recordException(executionInfo.getErrors().get(0).getValue()); - } - span.setStatus(StatusCode.ERROR); - span.end(); - return null; - }); + requestLogPrefix, + (k, v) -> { + Span span = v.parentSpan; + if (!executionInfo.getErrors().isEmpty()) { + span.recordException(executionInfo.getErrors().get(0).getValue()); + } + span.setStatus(StatusCode.ERROR); + span.end(); + return null; + }); } @Override public void onNodeSuccess( - long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { logPrefixToTracingInfoMap.computeIfPresent( - nodePrefixToRequestPrefix(requestLogPrefix), - (k, v) -> { - Span span = v.parentSpan; - span.setStatus(StatusCode.OK); - span.end(); - return null; - }); + nodePrefixToRequestPrefix(requestLogPrefix), + (k, v) -> { + Span span = v.parentSpan; + span.setStatus(StatusCode.OK); + span.end(); + return null; + }); } @Override public void onNodeError( - long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { + long latencyNanos, @NonNull ExecutionInfo executionInfo, @NonNull String requestLogPrefix) { logPrefixToTracingInfoMap.computeIfPresent( - nodePrefixToRequestPrefix(requestLogPrefix), - (k, v) -> { - Span span = v.parentSpan; - if (!executionInfo.getErrors().isEmpty()) { - span.recordException(executionInfo.getErrors().get(0).getValue()); - } - span.setStatus(StatusCode.ERROR); - span.end(); - return null; - }); + nodePrefixToRequestPrefix(requestLogPrefix), + (k, v) -> { + Span span = v.parentSpan; + if (!executionInfo.getErrors().isEmpty()) { + span.recordException(executionInfo.getErrors().get(0).getValue()); + } + span.setStatus(StatusCode.ERROR); + span.end(); + return null; + }); } @Override @@ -198,20 +199,20 @@ private String statementToString(Request request) { StringBuilder builder = new StringBuilder(); assert this.formatter != null; this.formatter.appendQueryString( - request, RequestLogger.DEFAULT_REQUEST_LOGGER_MAX_QUERY_LENGTH, builder); + request, RequestLogger.DEFAULT_REQUEST_LOGGER_MAX_QUERY_LENGTH, builder); this.formatter.appendValues( - request, - RequestLogger.DEFAULT_REQUEST_LOGGER_MAX_VALUES, - RequestLogger.DEFAULT_REQUEST_LOGGER_MAX_VALUE_LENGTH, - true, - builder); + request, + RequestLogger.DEFAULT_REQUEST_LOGGER_MAX_VALUES, + RequestLogger.DEFAULT_REQUEST_LOGGER_MAX_VALUE_LENGTH, + true, + builder); return builder.toString(); } /** * This depends on the implementation of {@link - * com.datastax.oss.driver.internal.core.cql.CqlRequestHandler.NodeResponseCallback#NodeResponseCallback(Statement, - * Node, Queue, DriverChannel, int, int, boolean, String) NodeResponseCallback} + * CqlRequestHandler.NodeResponseCallback#NodeResponseCallback(Statement, Node, Queue, + * DriverChannel, int, int, boolean, String) NodeResponseCallback} * * @param nodePrefix s0|1716164115|0 * @return the request prefix, like s0|1716164115 From e8847d4e5f57eadf2852e3b1153c158d7738c7d1 Mon Sep 17 00:00:00 2001 From: janehe Date: Wed, 5 Feb 2025 19:22:14 -0800 Subject: [PATCH 08/13] add attributes --- .../core/tracker/OtelRequestTracker.java | 171 +++++++++++++++++- 1 file changed, 161 insertions(+), 10 deletions(-) diff --git a/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java b/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java index 4844159b51b..d1039334a60 100644 --- a/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java +++ b/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java @@ -17,9 +17,12 @@ */ package com.datastax.oss.driver.internal.core.tracker; +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.BatchStatement; import com.datastax.oss.driver.api.core.cql.ExecutionInfo; import com.datastax.oss.driver.api.core.cql.Statement; +import com.datastax.oss.driver.api.core.metadata.EndPoint; 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; @@ -27,13 +30,19 @@ import com.datastax.oss.driver.internal.core.channel.DriverChannel; import com.datastax.oss.driver.internal.core.context.DefaultDriverContext; import com.datastax.oss.driver.internal.core.cql.CqlRequestHandler; +import com.datastax.oss.driver.internal.core.metadata.DefaultEndPoint; +import com.datastax.oss.driver.internal.core.metadata.SniEndPoint; import com.datastax.oss.driver.shaded.guava.common.util.concurrent.ThreadFactoryBuilder; import edu.umd.cs.findbugs.annotations.NonNull; import io.opentelemetry.api.OpenTelemetry; +import io.opentelemetry.api.common.AttributeKey; import io.opentelemetry.api.trace.Span; import io.opentelemetry.api.trace.StatusCode; import io.opentelemetry.api.trace.Tracer; import io.opentelemetry.context.Context; + +import java.lang.reflect.Field; +import java.net.InetSocketAddress; import java.util.Map; import java.util.Queue; import java.util.concurrent.ArrayBlockingQueue; @@ -44,9 +53,9 @@ import org.slf4j.Logger; import org.slf4j.LoggerFactory; -/** TODO: how do we access the context */ +import javax.annotation.Nullable; + public class OtelRequestTracker implements RequestTracker { - // private final OpenTelemetry openTelemetry; private final Map logPrefixToTracingInfoMap = new ConcurrentHashMap<>(); @@ -56,8 +65,39 @@ public class OtelRequestTracker implements RequestTracker { private final ExecutorService threadPool; - // private Session session; private RequestLogFormatter formatter; + private DefaultDriverContext context; + private final Field proxyAddressField = getProxyAddressField(); + + /** + * Attributes that are "conditionally required" or "recommended" but we cannot provide: 1. + * db.collection.name 2. db.response.status_code + */ + private static final AttributeKey DB_SYSTEM_NAME = + AttributeKey.stringKey("db.system.name"); + + private static final AttributeKey DB_NAMESPACE = AttributeKey.stringKey("db.namespace"); + private static final AttributeKey DB_OPERATION_NAME = + AttributeKey.stringKey("db.operation.name"); + private static final AttributeKey ERROR_TYPE = AttributeKey.stringKey("error.type"); + private static final AttributeKey SERVER_PORT = AttributeKey.longKey("server.port"); + private static final AttributeKey CASSANDRA_CONSISTENCY_LEVEL = + AttributeKey.stringKey("cassandra.consistency.level"); + private static final AttributeKey CASSANDRA_COORDINATOR_DC = + AttributeKey.stringKey("cassandra.coordinator.dc"); + private static final AttributeKey CASSANDRA_COORDINATOR_ID = + AttributeKey.stringKey("cassandra.coordinator.id"); + private static final AttributeKey CASSANDRA_PAGE_SIZE = + AttributeKey.longKey("cassandra.page.size"); + private static final AttributeKey CASSANDRA_QUERY_IDEMPOTENT = + AttributeKey.booleanKey("cassandra.query.idempotent"); + private static final AttributeKey CASSANDRA_SPECULATIVE_EXECUTION_COUNT = + AttributeKey.longKey("cassandra.speculative_execution.count"); + private static final AttributeKey DB_OPERATION_BATCH_SIZE = + AttributeKey.longKey("db.operation.batch.size"); + private static final AttributeKey DB_QUERY_TEXT = AttributeKey.stringKey("db.query.text"); + private static final AttributeKey SERVER_ADDRESS = + AttributeKey.stringKey("server.address"); public OtelRequestTracker(OpenTelemetry openTelemetry) { // this.openTelemetry = openTelemetry; @@ -99,7 +139,6 @@ public void onRequestCreatedForNode( @NonNull DriverExecutionProfile executionProfile, @NonNull Node node, @NonNull String requestLogPrefix) { - logPrefixToTracingInfoMap.computeIfPresent( nodePrefixToRequestPrefix(requestLogPrefix), (k, v) -> { @@ -123,6 +162,8 @@ public void onSuccess( (k, v) -> { Span span = v.parentSpan; span.setStatus(StatusCode.OK); + addRequestAttributesToSpan(executionInfo.getRequest(), span); + addExecutionInfoToSpan(executionInfo, span); span.end(); return null; }); @@ -139,6 +180,8 @@ public void onError( span.recordException(executionInfo.getErrors().get(0).getValue()); } span.setStatus(StatusCode.ERROR); + addRequestAttributesToSpan(executionInfo.getRequest(), span); + addExecutionInfoToSpan(executionInfo, span); span.end(); return null; }); @@ -152,6 +195,8 @@ public void onNodeSuccess( (k, v) -> { Span span = v.parentSpan; span.setStatus(StatusCode.OK); + addRequestAttributesToSpan(executionInfo.getRequest(), span); + addExecutionInfoToSpan(executionInfo, span); span.end(); return null; }); @@ -165,9 +210,26 @@ public void onNodeError( (k, v) -> { Span span = v.parentSpan; if (!executionInfo.getErrors().isEmpty()) { - span.recordException(executionInfo.getErrors().get(0).getValue()); + /* + Find the first error for this node. Because a node can appear twice in the errors list due + to retry policy, the error for this NodeRequest may not actually be the first error in + this list. In that scenario, the wrong error may be attached to this span, but this is the best we can do. + */ + executionInfo + .getErrors() + .forEach( + entry -> { + if (entry + .getKey() + .getHostId() + .equals(executionInfo.getCoordinator().getHostId())) { + span.recordException(entry.getValue()); + } + }); } span.setStatus(StatusCode.ERROR); + addRequestAttributesToSpan(executionInfo.getRequest(), span); + addExecutionInfoToSpan(executionInfo, span); span.end(); return null; }); @@ -175,8 +237,8 @@ public void onNodeError( @Override public void onSessionReady(@NonNull Session session) { - // this.session = session; - this.formatter = ((DefaultDriverContext) session.getContext()).getRequestLogFormatter(); + this.context = (DefaultDriverContext) session.getContext(); + this.formatter = this.context.getRequestLogFormatter(); } private static class TracingInfo { @@ -188,11 +250,66 @@ private TracingInfo(Span parentSpan) { } private void addRequestAttributesToSpan(Request request, Span span) { + assert request instanceof Statement; + span.setAttribute(DB_SYSTEM_NAME, "cassandra"); + span.setAttribute(DB_OPERATION_NAME, request.getClass().getSimpleName()); if (request.getKeyspace() != null) - span.setAttribute("db.cassandra.keyspace", request.getKeyspace().asCql(true)); - span.setAttribute("db.query.text", statementToString(request)); + span.setAttribute(DB_NAMESPACE, request.getKeyspace().asCql(true)); + + String consistencyLevel; + if (((Statement) request).getConsistencyLevel() != null) { + consistencyLevel = ((Statement) request).getConsistencyLevel().name(); + } else { + consistencyLevel = + context + .getConfig() + .getDefaultProfile() + .getString(DefaultDriverOption.REQUEST_CONSISTENCY); + } + span.setAttribute(CASSANDRA_CONSISTENCY_LEVEL, consistencyLevel); + + int pageSize; + if (((Statement) request).getPageSize() > 0) { + pageSize = ((Statement) request).getPageSize(); + } else { + pageSize = + context.getConfig().getDefaultProfile().getInt(DefaultDriverOption.REQUEST_PAGE_SIZE); + } + span.setAttribute(CASSANDRA_PAGE_SIZE, pageSize); + + span.setAttribute(DB_QUERY_TEXT, statementToString(request)); if (request.isIdempotent() != null) - span.setAttribute("db.cassandra.idempotence", request.isIdempotent()); + span.setAttribute(CASSANDRA_QUERY_IDEMPOTENT, request.isIdempotent()); + + if (request instanceof BatchStatement) { + span.setAttribute(DB_OPERATION_BATCH_SIZE, ((BatchStatement) request).size()); + } + } + + private void addExecutionInfoToSpan(ExecutionInfo executionInfo, Span span) { + Node node = executionInfo.getCoordinator(); + if (node != null) { + addServerAddressAndPortToSpan(span, node); + span.setAttribute(CASSANDRA_COORDINATOR_ID, node.getHostId().toString()); + span.setAttribute(CASSANDRA_COORDINATOR_DC, node.getDatacenter()); + } + + /* + Find the first error for this node. Because a node can appear twice in the errors list due + to retry policy, the error for this NodeRequest may not actually be the first error in + this list. In that scenario, the wrong error may be attached to this span, but this is the best we can do. + */ + executionInfo + .getErrors() + .forEach( + entry -> { + if (entry.getKey().getHostId().equals(node.getHostId())) { + span.setAttribute(ERROR_TYPE, entry.getValue().getClass().getSimpleName()); + } + }); + + span.setAttribute( + CASSANDRA_SPECULATIVE_EXECUTION_COUNT, executionInfo.getSpeculativeExecutionCount()); } private String statementToString(Request request) { @@ -209,6 +326,29 @@ private String statementToString(Request request) { return builder.toString(); } + private void addServerAddressAndPortToSpan(Span span, Node coordinator) { + EndPoint endPoint = coordinator.getEndPoint(); + if (endPoint instanceof DefaultEndPoint) { + InetSocketAddress address = ((DefaultEndPoint) endPoint).resolve(); + span.setAttribute(SERVER_ADDRESS, address.getHostString()); + span.setAttribute(SERVER_PORT, address.getPort()); + } else if (endPoint instanceof SniEndPoint && proxyAddressField != null) { + SniEndPoint sniEndPoint = (SniEndPoint) endPoint; + Object object = null; + try { + object = proxyAddressField.get(sniEndPoint); + } catch (Exception e) { + this.LOG.trace( + "Error when accessing the private field proxyAddress of SniEndPoint using reflection."); + } + if (object instanceof InetSocketAddress) { + InetSocketAddress address = (InetSocketAddress) object; + span.setAttribute(SERVER_ADDRESS, address.getHostString()); + span.setAttribute(SERVER_PORT, address.getPort()); + } + } + } + /** * This depends on the implementation of {@link * CqlRequestHandler.NodeResponseCallback#NodeResponseCallback(Statement, Node, Queue, @@ -221,4 +361,15 @@ private String nodePrefixToRequestPrefix(String nodePrefix) { int lastSeparatorIndex = nodePrefix.lastIndexOf("|"); return nodePrefix.substring(0, lastSeparatorIndex); } + + @Nullable + private Field getProxyAddressField() { + try { + Field field = SniEndPoint.class.getDeclaredField("proxyAddress"); + field.setAccessible(true); + return field; + } catch (Exception e) { + return null; + } + } } From d033d4d6c03415d94897d2cdb00e98cac845cb8b Mon Sep 17 00:00:00 2001 From: janehe Date: Wed, 5 Feb 2025 19:22:38 -0800 Subject: [PATCH 09/13] fmt --- .../oss/driver/internal/core/tracker/OtelRequestTracker.java | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java b/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java index d1039334a60..3c9a4965e31 100644 --- a/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java +++ b/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java @@ -40,7 +40,6 @@ import io.opentelemetry.api.trace.StatusCode; import io.opentelemetry.api.trace.Tracer; import io.opentelemetry.context.Context; - import java.lang.reflect.Field; import java.net.InetSocketAddress; import java.util.Map; @@ -50,11 +49,10 @@ import java.util.concurrent.ExecutorService; import java.util.concurrent.ThreadPoolExecutor; import java.util.concurrent.TimeUnit; +import javax.annotation.Nullable; import org.slf4j.Logger; import org.slf4j.LoggerFactory; -import javax.annotation.Nullable; - public class OtelRequestTracker implements RequestTracker { private final Map logPrefixToTracingInfoMap = new ConcurrentHashMap<>(); From fe3b949af0487d5d10e36941de9315fa9fd51a30 Mon Sep 17 00:00:00 2001 From: janehe Date: Thu, 6 Feb 2025 01:00:43 -0800 Subject: [PATCH 10/13] Add ending of child spans and attributes. TODO: db query parameters, documentation, test --- .../core/tracker/OtelRequestTracker.java | 88 +++++++++++-------- 1 file changed, 51 insertions(+), 37 deletions(-) diff --git a/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java b/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java index 3c9a4965e31..d9aba0e4297 100644 --- a/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java +++ b/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java @@ -98,7 +98,6 @@ public class OtelRequestTracker implements RequestTracker { AttributeKey.stringKey("server.address"); public OtelRequestTracker(OpenTelemetry openTelemetry) { - // this.openTelemetry = openTelemetry; this.tracer = openTelemetry.getTracer("com.datastax.oss.driver.internal.core.tracker.OtelRequestTracker"); this.threadPool = @@ -124,10 +123,10 @@ public void onRequestCreated( @NonNull Request request, @NonNull DriverExecutionProfile executionProfile, @NonNull String requestLogPrefix) { - Span parentSpan = tracer.spanBuilder("Cassandra Java Driver").startSpan(); + Span parentSpan = tracer.spanBuilder("Cassandra Java Driver Session Request").startSpan(); TracingInfo tracingInfo = new TracingInfo(parentSpan); logPrefixToTracingInfoMap.put(requestLogPrefix, tracingInfo); - addRequestAttributesToSpan(request, parentSpan); + addRequestAttributesToSpan(request, parentSpan, false); LOG.debug("Request created: {}", requestLogPrefix); } @@ -143,10 +142,11 @@ public void onRequestCreatedForNode( Span parentSpan = v.parentSpan; Span span = tracer - .spanBuilder("Cassandra Java Driver") + .spanBuilder("Cassandra Java Driver Node Request") .setParent(Context.current().with(parentSpan)) .startSpan(); - addRequestAttributesToSpan(request, span); + addRequestAttributesToSpan(request, span, true); + v.addNodeSpan(requestLogPrefix, span); return v; }); LOG.debug("Request created for node: {}", requestLogPrefix); @@ -160,7 +160,7 @@ public void onSuccess( (k, v) -> { Span span = v.parentSpan; span.setStatus(StatusCode.OK); - addRequestAttributesToSpan(executionInfo.getRequest(), span); + addRequestAttributesToSpan(executionInfo.getRequest(), span, false); addExecutionInfoToSpan(executionInfo, span); span.end(); return null; @@ -178,7 +178,7 @@ public void onError( span.recordException(executionInfo.getErrors().get(0).getValue()); } span.setStatus(StatusCode.ERROR); - addRequestAttributesToSpan(executionInfo.getRequest(), span); + addRequestAttributesToSpan(executionInfo.getRequest(), span, false); addExecutionInfoToSpan(executionInfo, span); span.end(); return null; @@ -191,12 +191,12 @@ public void onNodeSuccess( logPrefixToTracingInfoMap.computeIfPresent( nodePrefixToRequestPrefix(requestLogPrefix), (k, v) -> { - Span span = v.parentSpan; + Span span = v.getNodeSpan(requestLogPrefix); span.setStatus(StatusCode.OK); - addRequestAttributesToSpan(executionInfo.getRequest(), span); + addRequestAttributesToSpan(executionInfo.getRequest(), span, true); addExecutionInfoToSpan(executionInfo, span); span.end(); - return null; + return v; }); } @@ -206,7 +206,7 @@ public void onNodeError( logPrefixToTracingInfoMap.computeIfPresent( nodePrefixToRequestPrefix(requestLogPrefix), (k, v) -> { - Span span = v.parentSpan; + Span span = v.getNodeSpan(requestLogPrefix); if (!executionInfo.getErrors().isEmpty()) { /* Find the first error for this node. Because a node can appear twice in the errors list due @@ -226,10 +226,10 @@ public void onNodeError( }); } span.setStatus(StatusCode.ERROR); - addRequestAttributesToSpan(executionInfo.getRequest(), span); + addRequestAttributesToSpan(executionInfo.getRequest(), span, true); addExecutionInfoToSpan(executionInfo, span); span.end(); - return null; + return v; }); } @@ -241,41 +241,55 @@ public void onSessionReady(@NonNull Session session) { private static class TracingInfo { private final Span parentSpan; + private final Map nodeSpans = new ConcurrentHashMap<>(); // logPrefix -> span private TracingInfo(Span parentSpan) { this.parentSpan = parentSpan; } + + private void addNodeSpan(String logPrefix, Span span) { + nodeSpans.put(logPrefix, span); + } + + private Span getNodeSpan(String logPrefix) { + return nodeSpans.get(logPrefix); + } } - private void addRequestAttributesToSpan(Request request, Span span) { - assert request instanceof Statement; + private void addRequestAttributesToSpan(Request request, Span span, boolean isNodeRequest) { span.setAttribute(DB_SYSTEM_NAME, "cassandra"); - span.setAttribute(DB_OPERATION_NAME, request.getClass().getSimpleName()); + String operationName = + String.format( + "%s(%s)", + isNodeRequest ? "Node_Request" : "Session_Request", request.getClass().getSimpleName()); + span.setAttribute(DB_OPERATION_NAME, operationName); if (request.getKeyspace() != null) span.setAttribute(DB_NAMESPACE, request.getKeyspace().asCql(true)); - String consistencyLevel; - if (((Statement) request).getConsistencyLevel() != null) { - consistencyLevel = ((Statement) request).getConsistencyLevel().name(); - } else { - consistencyLevel = - context - .getConfig() - .getDefaultProfile() - .getString(DefaultDriverOption.REQUEST_CONSISTENCY); - } - span.setAttribute(CASSANDRA_CONSISTENCY_LEVEL, consistencyLevel); - - int pageSize; - if (((Statement) request).getPageSize() > 0) { - pageSize = ((Statement) request).getPageSize(); - } else { - pageSize = - context.getConfig().getDefaultProfile().getInt(DefaultDriverOption.REQUEST_PAGE_SIZE); + if (request instanceof Statement) { + String consistencyLevel; + if (((Statement) request).getConsistencyLevel() != null) { + consistencyLevel = ((Statement) request).getConsistencyLevel().name(); + } else { + consistencyLevel = + context + .getConfig() + .getDefaultProfile() + .getString(DefaultDriverOption.REQUEST_CONSISTENCY); + } + span.setAttribute(CASSANDRA_CONSISTENCY_LEVEL, consistencyLevel); + + int pageSize; + if (((Statement) request).getPageSize() > 0) { + pageSize = ((Statement) request).getPageSize(); + } else { + pageSize = + context.getConfig().getDefaultProfile().getInt(DefaultDriverOption.REQUEST_PAGE_SIZE); + } + span.setAttribute(CASSANDRA_PAGE_SIZE, pageSize); } - span.setAttribute(CASSANDRA_PAGE_SIZE, pageSize); - span.setAttribute(DB_QUERY_TEXT, statementToString(request)); + span.setAttribute(DB_QUERY_TEXT, requestToString(request)); if (request.isIdempotent() != null) span.setAttribute(CASSANDRA_QUERY_IDEMPOTENT, request.isIdempotent()); @@ -310,7 +324,7 @@ private void addExecutionInfoToSpan(ExecutionInfo executionInfo, Span span) { CASSANDRA_SPECULATIVE_EXECUTION_COUNT, executionInfo.getSpeculativeExecutionCount()); } - private String statementToString(Request request) { + private String requestToString(Request request) { StringBuilder builder = new StringBuilder(); assert this.formatter != null; this.formatter.appendQueryString( From 4982967d87a4f4980528e8aaab788a3bb4c01267 Mon Sep 17 00:00:00 2001 From: janehe Date: Wed, 19 Feb 2025 18:23:28 -0800 Subject: [PATCH 11/13] Add Cassandra Internal traces and parameters for BoundStatements --- .../core/tracker/OtelRequestTracker.java | 74 ++++++++++++++++++- 1 file changed, 73 insertions(+), 1 deletion(-) diff --git a/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java b/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java index d9aba0e4297..4fce8c2f480 100644 --- a/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java +++ b/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java @@ -20,13 +20,17 @@ 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.BatchStatement; +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.QueryTrace; import com.datastax.oss.driver.api.core.cql.Statement; import com.datastax.oss.driver.api.core.metadata.EndPoint; 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.api.core.type.DataType; import com.datastax.oss.driver.internal.core.channel.DriverChannel; import com.datastax.oss.driver.internal.core.context.DefaultDriverContext; import com.datastax.oss.driver.internal.core.cql.CqlRequestHandler; @@ -42,7 +46,11 @@ import io.opentelemetry.context.Context; import java.lang.reflect.Field; import java.net.InetSocketAddress; +import java.nio.ByteBuffer; +import java.time.Instant; +import java.util.List; import java.util.Map; +import java.util.Objects; import java.util.Queue; import java.util.concurrent.ArrayBlockingQueue; import java.util.concurrent.ConcurrentHashMap; @@ -89,6 +97,8 @@ public class OtelRequestTracker implements RequestTracker { AttributeKey.longKey("cassandra.page.size"); private static final AttributeKey CASSANDRA_QUERY_IDEMPOTENT = AttributeKey.booleanKey("cassandra.query.idempotent"); + private static final AttributeKey CASSANDRA_QUERY_ID = + AttributeKey.stringKey("cassandra.query.id"); private static final AttributeKey CASSANDRA_SPECULATIVE_EXECUTION_COUNT = AttributeKey.longKey("cassandra.speculative_execution.count"); private static final AttributeKey DB_OPERATION_BATCH_SIZE = @@ -159,6 +169,7 @@ public void onSuccess( requestLogPrefix, (k, v) -> { Span span = v.parentSpan; + span.setAttribute(CASSANDRA_QUERY_ID, requestLogPrefix); span.setStatus(StatusCode.OK); addRequestAttributesToSpan(executionInfo.getRequest(), span, false); addExecutionInfoToSpan(executionInfo, span); @@ -174,6 +185,7 @@ public void onError( requestLogPrefix, (k, v) -> { Span span = v.parentSpan; + span.setAttribute(CASSANDRA_QUERY_ID, requestLogPrefix); if (!executionInfo.getErrors().isEmpty()) { span.recordException(executionInfo.getErrors().get(0).getValue()); } @@ -192,10 +204,18 @@ public void onNodeSuccess( nodePrefixToRequestPrefix(requestLogPrefix), (k, v) -> { Span span = v.getNodeSpan(requestLogPrefix); + span.setAttribute(CASSANDRA_QUERY_ID, requestLogPrefix); span.setStatus(StatusCode.OK); addRequestAttributesToSpan(executionInfo.getRequest(), span, true); addExecutionInfoToSpan(executionInfo, span); span.end(); + if (executionInfo.getTracingId() != null) { + threadPool.submit( + () -> { + QueryTrace queryTrace = executionInfo.getQueryTrace(); + addCassandraQueryTraceToSpan(span, queryTrace); + }); + } return v; }); } @@ -207,6 +227,7 @@ public void onNodeError( nodePrefixToRequestPrefix(requestLogPrefix), (k, v) -> { Span span = v.getNodeSpan(requestLogPrefix); + span.setAttribute(CASSANDRA_QUERY_ID, requestLogPrefix); if (!executionInfo.getErrors().isEmpty()) { /* Find the first error for this node. Because a node can appear twice in the errors list due @@ -229,6 +250,13 @@ public void onNodeError( addRequestAttributesToSpan(executionInfo.getRequest(), span, true); addExecutionInfoToSpan(executionInfo, span); span.end(); + if (executionInfo.getTracingId() != null) { + threadPool.submit( + () -> { + QueryTrace queryTrace = executionInfo.getQueryTrace(); + addCassandraQueryTraceToSpan(span, queryTrace); + }); + } return v; }); } @@ -296,6 +324,10 @@ private void addRequestAttributesToSpan(Request request, Span span, boolean isNo if (request instanceof BatchStatement) { span.setAttribute(DB_OPERATION_BATCH_SIZE, ((BatchStatement) request).size()); } + + if (request instanceof BoundStatement) { + addParametersOfBoundStatementToSpan(span, (BoundStatement) request); + } } private void addExecutionInfoToSpan(ExecutionInfo executionInfo, Span span) { @@ -338,6 +370,25 @@ private String requestToString(Request request) { return builder.toString(); } + private void addParametersOfBoundStatementToSpan(Span span, BoundStatement statement) { + ColumnDefinitions definitions = statement.getPreparedStatement().getVariableDefinitions(); + List values = statement.getValues(); + assert definitions.size() == values.size(); + for (int i = 0; i < definitions.size(); i++) { + String key = "db.operation.parameter." + definitions.get(i).getName().asCql(true); + StringBuilder valueBuilder = new StringBuilder(); + if (!statement.isSet(i)) { + valueBuilder.append(""); + } else { + ByteBuffer value = values.get(i); + DataType type = definitions.get(i).getType(); + this.formatter.appendValue( + value, type, RequestLogger.DEFAULT_REQUEST_LOGGER_MAX_VALUE_LENGTH, valueBuilder); + } + span.setAttribute(key, valueBuilder.toString()); + } + } + private void addServerAddressAndPortToSpan(Span span, Node coordinator) { EndPoint endPoint = coordinator.getEndPoint(); if (endPoint instanceof DefaultEndPoint) { @@ -369,7 +420,7 @@ private void addServerAddressAndPortToSpan(Span span, Node coordinator) { * @param nodePrefix s0|1716164115|0 * @return the request prefix, like s0|1716164115 */ - private String nodePrefixToRequestPrefix(String nodePrefix) { + private static String nodePrefixToRequestPrefix(String nodePrefix) { int lastSeparatorIndex = nodePrefix.lastIndexOf("|"); return nodePrefix.substring(0, lastSeparatorIndex); } @@ -384,4 +435,25 @@ private Field getProxyAddressField() { return null; } } + + private void addCassandraQueryTraceToSpan(Span parentSpan, QueryTrace queryTrace) { + Span span = + this.tracer + .spanBuilder("Cassandra Internal") + .setStartTimestamp(Instant.ofEpochMilli(queryTrace.getStartedAt())) + .setParent(Context.current().with(parentSpan)) + .startSpan(); + queryTrace + .getEvents() + .forEach( + event -> { + span.addEvent( + Objects.requireNonNull(event.getActivity()), + // Why are these timestamps later than the span's end time? + Instant.ofEpochMilli(event.getTimestamp())); + }); + + span.end( + Instant.ofEpochMilli(queryTrace.getStartedAt() + queryTrace.getDurationMicros() / 1000)); + } } From 30bb1302dbf074f8d26af3834400b5b9269111f7 Mon Sep 17 00:00:00 2001 From: janehe Date: Thu, 20 Feb 2025 18:58:36 -0800 Subject: [PATCH 12/13] Lazy reference and doc --- manual/open_telemetry/README.md | 99 +++++++++++++++++++ .../core/tracker/OtelRequestTracker.java | 49 +++++---- 2 files changed, 127 insertions(+), 21 deletions(-) create mode 100644 manual/open_telemetry/README.md diff --git a/manual/open_telemetry/README.md b/manual/open_telemetry/README.md new file mode 100644 index 00000000000..7ed51c71372 --- /dev/null +++ b/manual/open_telemetry/README.md @@ -0,0 +1,99 @@ + + +# OpenTelemetry +The driver provides support for session and node level traces using OpenTelemetry. + +## Including OpenTelemetry instrumentation in your code + +You need to include the `java-driver-open-telemetry` module in your project's dependency. +```xml + + org.apache.cassandra + java-driver-open-telemetry + +``` + +You also need to instantiate an `OtelRequestTracker` and pass it to the `CqlSessionBuilder` when building the session. + +```java +CqlSession session = CqlSession.builder() + .addContactPoint(new InetSocketAddress("127.0.0.1", 9042)) + .withLocalDatacenter("datacenter1") + .withRequestTracker(new OtelRequestTracker(initOpenTelemetry())) + .build(); +``` + +The constructor of `OtelRequestTracker` needs an argument of `OpenTelemetry` instance. This instance will contain the configuration for the resource and the exporter. +This is an example of how to initialize the `OpenTelemetry` instance with Jaeger exporter. + +```java +static OpenTelemetry initOpenTelemetry() { + + ManagedChannel jaegerChannel = + ManagedChannelBuilder.forAddress("localhost", 14250).usePlaintext().build(); + + JaegerGrpcSpanExporter jaegerExporter = + JaegerGrpcSpanExporter.builder() + .setChannel(jaegerChannel) + .setTimeout(30, TimeUnit.SECONDS) + .build(); + + Resource serviceNameResource = + Resource.create(Attributes.of(ResourceAttributes.SERVICE_NAME, "Demo App")); + + SdkTracerProvider tracerProvider = + SdkTracerProvider.builder() + .addSpanProcessor(SimpleSpanProcessor.create(jaegerExporter)) + .setResource(Resource.getDefault().merge(serviceNameResource)) + .build(); + OpenTelemetrySdk openTelemetry = + OpenTelemetrySdk.builder().setTracerProvider(tracerProvider).build(); + + return openTelemetry; +} +``` + +You can also find an demo system [here](https://github.com/SiyaoIsHiding/java-driver-otel-example), which includes an Apache Cassandra database, a Spring server using the Apache Cassandra Java Driver, an HTTP client simulating browser behavior, and a Jaeger the Opentelemetry collector. +The example demonstrates how to use OpenTelemetry to trace the queries and achieve context propagation between distributed components. + +## Attributes + +| Attribute | Description | Output Values | +|---------------------------------------|-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|--------------------------------------------------------------| +| db.system.name | Always "cassandra" | "cassandra" | +| db.namespace | The keyspace associated with the session. | "mykeyspace" | +| db.operation.name | The name of the operation or command being executed. `Session_Request({RequestType})` for session level calls and Node_Request({RequestType}) for node level calls | "Node_Request(DefaultBoundStatement)" | +| error.type | Describes a class of error the operation ended with | "NodeUnavailableException" | +| server.port | Server port number. | 9042 | +| cassandra.consistency.level | The consistency level of the query. Based on consistency values from [CQL](https://docs.datastax.com/en/cassandra-oss/3.0/cassandra/dml/dmlConfigConsistency.html). | "QUORUM" | +| cassandra.coordinator.dc | The data center of the coordinating node for a query. | "datacenter1" | +| cassandra.coordinator.id | The ID of the coordinating node for a query. | "be13faa2-8574-4d71-926d-27f16cf8a7af" | +| cassandra.page.size | The fetch size used for paging, i.e. how many rows will be returned at once. | 5000 | +| cassandra.query.idempotent | Whether or not the query is idempotent. | true | +| cassandra.query.id | The query ID to correlate with logs. `{sessionId}\|{sessionRequestId}` for a session request and `{sessionId}\|{sessionRequestId}\|{nodeRequestCount}` for a node request | "s0\|229540037\|0" | +| cassandra.speculative_execution.count | The number of times a query was speculatively executed. Not set or 0 if the query was not executed speculatively. | 0 | +| db.operation.batch.size | The number of queries included in the case of a batch operation. | 2 | +| db.query.text | The database query being executed. | "SELECT * FROM ingredients WHERE id=? LIMIT 1 \[id='COTO'\]" | +| server.address | Name of the database host. | "127.0.0.1" | +| db.operation.parameter. | In the case of a `BoundStatement`, this is a database operation parameter, with being the parameter name, and the attribute value being a string representation of the parameter value. | "someval" | + +## Apache Cassandra Internal Traces +When using `OtelRequestTracker`, If the statement has `setTracing()` enabled to turn on Apache Cassandra built-in Query Trace feature, +the driver will retrieve the Query Trace information about the events happened in Apache Cassandra internally and export them to the OpenTelemetry collector, too. \ No newline at end of file diff --git a/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java b/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java index 4fce8c2f480..de531b6c1d3 100644 --- a/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java +++ b/open-telemetry/src/main/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTracker.java @@ -36,6 +36,7 @@ import com.datastax.oss.driver.internal.core.cql.CqlRequestHandler; import com.datastax.oss.driver.internal.core.metadata.DefaultEndPoint; import com.datastax.oss.driver.internal.core.metadata.SniEndPoint; +import com.datastax.oss.driver.internal.core.util.concurrent.LazyReference; import com.datastax.oss.driver.shaded.guava.common.util.concurrent.ThreadFactoryBuilder; import edu.umd.cs.findbugs.annotations.NonNull; import io.opentelemetry.api.OpenTelemetry; @@ -69,7 +70,7 @@ public class OtelRequestTracker implements RequestTracker { private final Logger LOG = LoggerFactory.getLogger(OtelRequestTracker.class); - private final ExecutorService threadPool; + private final LazyReference threadPool; private RequestLogFormatter formatter; private DefaultDriverContext context; @@ -111,20 +112,22 @@ public OtelRequestTracker(OpenTelemetry openTelemetry) { this.tracer = openTelemetry.getTracer("com.datastax.oss.driver.internal.core.tracker.OtelRequestTracker"); this.threadPool = - new ThreadPoolExecutor( - 1, - Math.max(Runtime.getRuntime().availableProcessors(), 1), - 10, - TimeUnit.SECONDS, - new ArrayBlockingQueue<>(1000), - new ThreadFactoryBuilder().setNameFormat("otel-thread-%d").build(), - new ThreadPoolExecutor.AbortPolicy()); + new LazyReference<>( + () -> + new ThreadPoolExecutor( + 1, + Math.max(Runtime.getRuntime().availableProcessors(), 1), + 10, + TimeUnit.SECONDS, + new ArrayBlockingQueue<>(1000), + new ThreadFactoryBuilder().setNameFormat("otel-thread-%d").build(), + new ThreadPoolExecutor.AbortPolicy())); } @Override public void close() throws Exception { - threadPool.shutdown(); - threadPool.awaitTermination(10, TimeUnit.SECONDS); + threadPool.get().shutdown(); + threadPool.get().awaitTermination(10, TimeUnit.SECONDS); logPrefixToTracingInfoMap.clear(); } @@ -210,11 +213,13 @@ public void onNodeSuccess( addExecutionInfoToSpan(executionInfo, span); span.end(); if (executionInfo.getTracingId() != null) { - threadPool.submit( - () -> { - QueryTrace queryTrace = executionInfo.getQueryTrace(); - addCassandraQueryTraceToSpan(span, queryTrace); - }); + threadPool + .get() + .submit( + () -> { + QueryTrace queryTrace = executionInfo.getQueryTrace(); + addCassandraQueryTraceToSpan(span, queryTrace); + }); } return v; }); @@ -251,11 +256,13 @@ public void onNodeError( addExecutionInfoToSpan(executionInfo, span); span.end(); if (executionInfo.getTracingId() != null) { - threadPool.submit( - () -> { - QueryTrace queryTrace = executionInfo.getQueryTrace(); - addCassandraQueryTraceToSpan(span, queryTrace); - }); + threadPool + .get() + .submit( + () -> { + QueryTrace queryTrace = executionInfo.getQueryTrace(); + addCassandraQueryTraceToSpan(span, queryTrace); + }); } return v; }); From 7b499231f32de3e80cd8230098c8c276d7cecb6e Mon Sep 17 00:00:00 2001 From: janehe Date: Fri, 21 Feb 2025 14:05:43 -0800 Subject: [PATCH 13/13] Add tests --- .../core/tracker/OtelRequestTrackerTest.java | 141 ++++++++++++++++++ 1 file changed, 141 insertions(+) create mode 100644 open-telemetry/src/test/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTrackerTest.java diff --git a/open-telemetry/src/test/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTrackerTest.java b/open-telemetry/src/test/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTrackerTest.java new file mode 100644 index 00000000000..70036827074 --- /dev/null +++ b/open-telemetry/src/test/java/com/datastax/oss/driver/internal/core/tracker/OtelRequestTrackerTest.java @@ -0,0 +1,141 @@ +/* + * 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.tracker; + +import static org.mockito.BDDMockito.given; +import static org.mockito.Mockito.times; +import static org.mockito.Mockito.verify; + +import com.datastax.oss.driver.api.core.CqlSession; +import com.datastax.oss.driver.api.core.config.DriverConfig; +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.SimpleStatement; +import com.datastax.oss.driver.api.core.metadata.Node; +import com.datastax.oss.driver.internal.core.config.typesafe.DefaultDriverConfigLoader; +import com.datastax.oss.driver.internal.core.config.typesafe.TypesafeDriverConfig; +import com.datastax.oss.driver.internal.core.context.DefaultDriverContext; +import io.opentelemetry.api.OpenTelemetry; +import io.opentelemetry.api.common.AttributeKey; +import io.opentelemetry.api.trace.Span; +import io.opentelemetry.api.trace.SpanBuilder; +import io.opentelemetry.api.trace.Tracer; +import io.opentelemetry.context.Context; +import org.junit.Before; +import org.junit.Test; +import org.junit.runner.RunWith; +import org.mockito.Mock; +import org.mockito.junit.MockitoJUnitRunner; + +@RunWith(MockitoJUnitRunner.Strict.class) +public class OtelRequestTrackerTest { + @Mock private OpenTelemetry openTelemetry; + @Mock private Tracer tracer; + @Mock private DriverExecutionProfile profile; + @Mock private SpanBuilder sessionSpanBuilder; + @Mock private SpanBuilder nodeSpanBuilder; + @Mock private Span sessionSpan; + @Mock private Span nodeSpan; + @Mock private CqlSession session; + @Mock private DefaultDriverContext context; + private DriverConfig config = + new TypesafeDriverConfig(DefaultDriverConfigLoader.DEFAULT_CONFIG_SUPPLIER.get()); + private RequestLogFormatter requestLogFormatter = new RequestLogFormatter(context); + private String sessionLogPrefix = "s0|229540037"; + private String nodeLogPrefix = "s0|229540037|0"; + @Mock private Node node1; + @Mock private ExecutionInfo executionInfo; + private SimpleStatement statement = SimpleStatement.newInstance("SELECT * FROM test"); + + @Before + public void setup() { + given( + openTelemetry.getTracer( + "com.datastax.oss.driver.internal.core.tracker.OtelRequestTracker")) + .willReturn(tracer); + given(tracer.spanBuilder("Cassandra Java Driver Session Request")) + .willReturn(sessionSpanBuilder); + given(tracer.spanBuilder("Cassandra Java Driver Node Request")).willReturn(nodeSpanBuilder); + given(sessionSpanBuilder.startSpan()).willReturn(sessionSpan); + given(nodeSpanBuilder.startSpan()).willReturn(nodeSpan); + given(nodeSpanBuilder.setParent(Context.current().with(sessionSpan))) + .willReturn(nodeSpanBuilder); + given(session.getContext()).willReturn(context); + given(context.getRequestLogFormatter()).willReturn(requestLogFormatter); + given(context.getConfig()).willReturn(config); + given(executionInfo.getRequest()).willReturn(statement); + } + + @Test + public void should_send_trace_on_request_created() { + // Given + OtelRequestTracker tracker = new OtelRequestTracker(openTelemetry); + tracker.onSessionReady(session); + // When + tracker.onRequestCreated(statement, profile, sessionLogPrefix); + // Then + verify(tracer).spanBuilder("Cassandra Java Driver Session Request"); + verify(sessionSpan).setAttribute(AttributeKey.stringKey("db.query.text"), "SELECT * FROM test"); + + // when + tracker.onRequestCreatedForNode(statement, profile, node1, nodeLogPrefix); + // Then + verify(tracer).spanBuilder("Cassandra Java Driver Node Request"); + verify(nodeSpan).setAttribute(AttributeKey.stringKey("db.query.text"), "SELECT * FROM test"); + } + + @Test + public void should_send_trace_on_success() { + // Given + OtelRequestTracker tracker = new OtelRequestTracker(openTelemetry); + tracker.onSessionReady(session); + tracker.onRequestCreated(statement, profile, sessionLogPrefix); + tracker.onRequestCreatedForNode(statement, profile, node1, nodeLogPrefix); + // When + tracker.onNodeSuccess(1L, executionInfo, nodeLogPrefix); + // Then + verify(nodeSpan).end(); + verify(nodeSpan, times(2)) + .setAttribute( + AttributeKey.stringKey("db.operation.name"), "Node_Request(DefaultSimpleStatement)"); + // When + tracker.onSuccess(1L, executionInfo, sessionLogPrefix); + // Then + verify(sessionSpan).end(); + verify(sessionSpan, times(2)) + .setAttribute( + AttributeKey.stringKey("db.operation.name"), "Session_Request(DefaultSimpleStatement)"); + } + + @Test + public void should_send_trace_on_error() { + // Given + OtelRequestTracker tracker = new OtelRequestTracker(openTelemetry); + tracker.onSessionReady(session); + tracker.onRequestCreated(statement, profile, sessionLogPrefix); + tracker.onRequestCreatedForNode(statement, profile, node1, nodeLogPrefix); + // When + tracker.onNodeError(1L, executionInfo, nodeLogPrefix); + // Then + verify(nodeSpan).end(); + // When + tracker.onError(1L, executionInfo, sessionLogPrefix); + // Then + verify(sessionSpan).end(); + } +}