fix: improve information on CancellationException for LROs #2236

diegomarquezp · 2023-11-10T20:19:48Z

Fixes #1858
When a LRO runs out of retries/time, it throws a CancellationException that is then swallowed by guava's AbstractFuture, meaning there is no simple way to bubble up a custom exception with message.

This approach uses a logger with a message that points to LRO documentation to ensure the user is informed on what they can do about this.

lqiu96 · 2023-11-13T16:46:15Z

gax-java/gax/src/main/java/com/google/api/gax/longrunning/OperationTimedPollAlgorithm.java

@@ -77,6 +87,13 @@ public boolean shouldRetry(TimedAttemptSettings nextAttemptSettings)
    if (super.shouldRetry(nextAttemptSettings)) {
      return true;
    }
+    if (LOGGER.isLoggable(Level.SEVERE)) {


QQ, is there a reason SEVERE logging level was picked? It seems like that is meant for more fatal application issues (and less for an RPC timeout), but I also am not sure if there is a better level (Info? Warning?).

That makes sense. My reasoning was more like "exception=severe", but in the context of a timeout on a request I agree something like WARNING is better

I decreased it to WARNING

lqiu96 · 2023-11-13T17:04:35Z

gax-java/gax/src/main/java/com/google/api/gax/longrunning/OperationTimedPollAlgorithm.java


 /**
 * Operation timed polling algorithm, which uses exponential backoff factor for determining when the
 * next polling operation should be executed. If the polling exceeds the total timeout this
 * algorithm cancels polling.
 */
 public class OperationTimedPollAlgorithm extends ExponentialRetryAlgorithm {
+
+  @VisibleForTesting


nit: I don't think the logger needs a VisibleForTesting annotation.

lqiu96 · 2023-11-13T17:05:29Z

...case/gapic-showcase/src/test/java/com/google/showcase/v1beta1/it/ITLongRunningOperation.java

@@ -121,6 +124,8 @@ public void testHttpJson_LROSuccessfulResponse_doesNotExceedTotalTimeout() throw
  @Test
  public void testGRPC_LROUnsuccessfulResponse_exceedsTotalTimeout_throwsDeadlineExceededException()
      throws Exception {
+    FakeLogHandler logHandler = new FakeLogHandler();


nit: Might be better to create field for FakeLogHandler that all tests can use without having to initialize in multiple tests, if possible

setUp() -> Creates it
clean() -> clears all the message so the next test can run

Makes sense, thanks! I only added a setUp() since creating a new handler wipes out the old handler with its maessages

lqiu96 · 2023-11-13T17:05:40Z

...case/gapic-showcase/src/test/java/com/google/showcase/v1beta1/it/ITLongRunningOperation.java

+    FakeLogHandler logHandler = new FakeLogHandler();
+    OperationTimedPollAlgorithm.LOGGER.addHandler(logHandler);


lqiu96

LGTM, added a few nits. Can you also have @burkedavison or @JoeWang1127 take a quick look? Thanks for this @diegomarquezp

JoeWang1127 · 2023-11-13T20:40:47Z

gax-java/gax/src/main/java/com/google/api/gax/longrunning/OperationTimedPollAlgorithm.java


 /**
 * Operation timed polling algorithm, which uses exponential backoff factor for determining when the
 * next polling operation should be executed. If the polling exceeds the total timeout this
 * algorithm cancels polling.
 */
 public class OperationTimedPollAlgorithm extends ExponentialRetryAlgorithm {
+
+  public static Logger LOGGER = Logger.getLogger(OperationTimedPollAlgorithm.class.getName());


Why the logger has to be public?

This is so it can be accessed by the test in order to add a log handler. @lqiu96, maybe we can fall back to @VisibleForTesting because it is... visible only for testing?

Ah, right. Let's try the the default package scope, which I believe should still be accessible. If not, then we can add the annotation.

There're some suggestions made by Quality Gate: https://sonarcloud.io/project/issues?id=googleapis_gapic-generator-java&pullRequest=2236&resolved=false&types=CODE_SMELL

JoeWang1127 · 2023-11-13T20:42:40Z

...case/gapic-showcase/src/test/java/com/google/showcase/v1beta1/it/ITLongRunningOperation.java

@@ -149,6 +161,9 @@ public void testGRPC_LROUnsuccessfulResponse_exceedsTotalTimeout_throwsDeadlineE
      assertThrows(CancellationException.class, operationFuture::get);
      int attemptCount = operationFuture.getPollingFuture().getAttemptSettings().getAttemptCount();
      assertThat(attemptCount).isGreaterThan(1);
+      assertEquals(1, logHandler.getAllMessages().size());
+      assertThat(logHandler.getAllMessages().get(0))


Is there a guarantee that the message is the first element of the list?

So far the implementation has only one case where the logger is used. I think the current assertions are a safe heuristic. Maybe I can assert that at least one message contains the entry I'm looking for?

Maybe I can assert that at least one message contains the entry I'm looking for?

I think this maybe better.

gax-java/gax/src/test/java/com/google/api/gax/util/FakeLogHandler.java

JoeWang1127 · 2023-11-13T20:46:35Z

I don't have a lot of context of this change so I provide some general suggestions.

burkedavison · 2023-11-13T21:41:20Z

...case/gapic-showcase/src/test/java/com/google/showcase/v1beta1/it/ITLongRunningOperation.java

@@ -39,6 +43,13 @@
 */
 public class ITLongRunningOperation {


Are we sure that this already-complex integration test the best place to add these new assertions? Rephrased: Is the showcase server needed to verify the client's logging behavior?

The changes we're making are in com.google.api.gax.longrunning.OperationTimedPollAlgorithm, but we don't yet have any unit tests for this class. Is it possible for us to write a direct unit test that focuses purely on the logging behavior of OperationTimedPollAlgorithm.shouldRetry()?

Without looking at this PR and only the logic we're trying to test, I would have expected to see a set of unit tests that were roughly:

// WARNING: This is all completely pseudocode... public void testTroubleshootingLinkProvided() { LOGGER.addHandler(handler); assertThrows(..., algorithm.shouldRetry(NEXT_ATTEMPT_SHOULD_NOT_RETRY)); assertThat(handler.getLogMessage().exists()) assertThat(handler.getLogMessage().contains(LRO_TROUBLESHOOTING_LINK)); } public void testTroubleshootingLinkNotProvided() { LOGGER.addHandler(handler); assertThat(algorithm.shouldRetry(NEXT_ATTEMPT_SHOULD_RETRY), is(true)); assertThat(handler.getLogMessage().doesNotExist()) }

Then the integration test can be kept clear of client-side-only implementation details, allowing the person debugging a problem to focus only on the relevant interactions.

@burkedavison thank you. At some point writing the test in this file helped me find that the exception thrown in OperationTimedPollAlgorithm does not bubble up to the client (hence the use of a logger), but maybe that's just part of finding out about the behavior of LROs. I will move the test case to a unit test in gax

burkedavison · 2023-11-14T14:27:18Z

gax-java/gax/src/test/java/com/google/api/gax/longrunning/OperationTimedPollAlgorithmTest.java

+    FakeApiClock clock = new FakeApiClock(System.nanoTime());
+    OperationTimedPollAlgorithm algorithm =
+        OperationTimedPollAlgorithm.create(FAST_RETRY_SETTINGS, clock);
+    TimedAttemptSettings settings =
+        TimedAttemptSettings.newBuilder()
+            .setGlobalSettings(FAST_RETRY_SETTINGS)
+            .setRetryDelay(Duration.ofMillis(1l))
+            .setRpcTimeout(Duration.ofMillis(1l))
+            .setRandomizedRetryDelay(Duration.ofMillis(1l))
+            .setAttemptCount(0)
+            .setFirstAttemptStartTimeNanos(clock.nanoTime())
+            .build();


Thank you for the improvement by moving this to a unit test!

At this point, I'm just nit-picking: you could choose to extract all three of these variables to class fields, and further reduce both of these tests to their essential checks.

burkedavison · 2023-11-14T14:29:01Z

gax-java/gax/src/test/java/com/google/api/gax/longrunning/OperationTimedPollAlgorithmTest.java

+            .setAttemptCount(0)
+            .setFirstAttemptStartTimeNanos(clock.nanoTime())
+            .build();
+    clock.incrementNanoTime(1 * 1000 * 1000 * 1000);


Consider a quick comment here to clarify what part of the logic this is triggering to force a no-retry.
For example (if this is accurate):

clock.incrementNanoTime(1 * 1000 * 1000 * 1000); // Force Rpc Timeout

good point. I added this comment

burkedavison · 2023-11-14T16:41:25Z

gax-java/gax/src/test/java/com/google/api/gax/longrunning/OperationTimedPollAlgorithmTest.java

+  private static TimedAttemptSettings timedAttemptSettings;
+  private static FakeApiClock clock;


By making these static and initializing them in an instance method (@Before), the test now becomes flaky if multithreading is ever enabled. One test may overwrite the reference during a different test.

Suggested change

private static TimedAttemptSettings timedAttemptSettings;

private static FakeApiClock clock;

private TimedAttemptSettings timedAttemptSettings;

private FakeApiClock clock;

ah, good catch. thanks. I didn't think through the need for static in this test class. I just switched them as instance variables

edit: I didn't notice this comment had a suggestion but I added the same change in another commit

sonarqubecloud · 2023-11-14T16:55:08Z

[gapic-generator-java-root] Kudos, SonarCloud Quality Gate passed!

0 Bugs
0 Vulnerabilities
0 Security Hotspots
0 Code Smells

80.0% Coverage
0.0% Duplication

sonarqubecloud · 2023-11-14T16:59:11Z

[java_showcase_integration_tests] Kudos, SonarCloud Quality Gate passed!

0 Bugs
0 Vulnerabilities
0 Security Hotspots
0 Code Smells

80.0% Coverage
0.0% Duplication

diegomarquezp added 9 commits November 10, 2023 18:47

fix: point to documentation on LRO CancelledException

624660c

mvn fmt:format

a4483ee

add test for http IT in LRO

fa781ea

format code

937e4e6

use final variable on LRO cancellation

9f17544

Wrap guava's CancellationException in our own Exception

27d2240

reset test and basic retry future

383b42d

use logging to inform of failed LRO

a9245ba

add license and comment to fake log handler

fa774a2

diegomarquezp requested a review from a team as a code owner November 10, 2023 20:19

product-auto-label bot added the size: m Pull request size is medium. label Nov 10, 2023

format code

f245e1f

diegomarquezp marked this pull request as draft November 10, 2023 20:22

diegomarquezp added 2 commits November 10, 2023 20:30

fix license

f4fd1c0

format souce

a899a89

diegomarquezp added the owlbot:run Add this label to trigger the Owlbot post processor. label Nov 13, 2023

gcf-owl-bot bot removed the owlbot:run Add this label to trigger the Owlbot post processor. label Nov 13, 2023

diegomarquezp marked this pull request as ready for review November 13, 2023 16:35

lqiu96 reviewed Nov 13, 2023

View reviewed changes

diegomarquezp added 2 commits November 13, 2023 16:50

decrease LRO timeout logging level to WARNING

e28c03f

fix logging threshold check

2328c01

diegomarquezp requested a review from lqiu96 November 13, 2023 17:02

lqiu96 reviewed Nov 13, 2023

View reviewed changes

lqiu96 approved these changes Nov 13, 2023

View reviewed changes

use common log handler setup for ITLongRunningOperation

7f0a751

JoeWang1127 reviewed Nov 13, 2023

View reviewed changes

fix license header year

e603ba7

format source

b8ad027

burkedavison reviewed Nov 13, 2023

View reviewed changes

diegomarquezp added 3 commits November 13, 2023 22:40

reset lro it

8f60925

change to unit tests

0e53559

reset testjar exports

2c33515

burkedavison approved these changes Nov 14, 2023

View reviewed changes

simplify unit test

152fc5b

burkedavison reviewed Nov 14, 2023

View reviewed changes

use instance variables in test

81a978c

diegomarquezp merged commit 741e40c into main Nov 14, 2023
35 checks passed

diegomarquezp deleted the longrunning-error-message-2 branch November 14, 2023 17:00

release-please bot mentioned this pull request Nov 13, 2023

chore(main): release 2.30.0 #2228

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix: improve information on CancellationException for LROs #2236

fix: improve information on CancellationException for LROs #2236

diegomarquezp commented Nov 10, 2023

lqiu96 Nov 13, 2023

diegomarquezp Nov 13, 2023

diegomarquezp Nov 13, 2023

lqiu96 Nov 13, 2023

lqiu96 Nov 13, 2023 •

edited

Loading

diegomarquezp Nov 13, 2023

lqiu96 Nov 13, 2023

lqiu96 left a comment

JoeWang1127 Nov 13, 2023

diegomarquezp Nov 13, 2023

lqiu96 Nov 13, 2023

JoeWang1127 Nov 13, 2023

JoeWang1127 Nov 13, 2023

diegomarquezp Nov 13, 2023

JoeWang1127 Nov 13, 2023

JoeWang1127 commented Nov 13, 2023

burkedavison Nov 13, 2023 •

edited

Loading

diegomarquezp Nov 13, 2023

burkedavison Nov 14, 2023

diegomarquezp Nov 14, 2023

burkedavison Nov 14, 2023

diegomarquezp Nov 14, 2023

burkedavison Nov 14, 2023

diegomarquezp Nov 14, 2023 •

edited

Loading

sonarqubecloud bot commented Nov 14, 2023

sonarqubecloud bot commented Nov 14, 2023

		FakeLogHandler logHandler = new FakeLogHandler();
		OperationTimedPollAlgorithm.LOGGER.addHandler(logHandler);

		private static TimedAttemptSettings timedAttemptSettings;
		private static FakeApiClock clock;

fix: improve information on CancellationException for LROs #2236

fix: improve information on CancellationException for LROs #2236

Conversation

diegomarquezp commented Nov 10, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lqiu96 Nov 13, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lqiu96 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

JoeWang1127 commented Nov 13, 2023

burkedavison Nov 13, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

diegomarquezp Nov 14, 2023 • edited Loading

Choose a reason for hiding this comment

sonarqubecloud bot commented Nov 14, 2023

sonarqubecloud bot commented Nov 14, 2023

lqiu96 Nov 13, 2023 •

edited

Loading

burkedavison Nov 13, 2023 •

edited

Loading

diegomarquezp Nov 14, 2023 •

edited

Loading