Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

fix: improve information on CancellationException for LROs #2236

Merged
merged 22 commits into from
Nov 14, 2023
Merged
Show file tree
Hide file tree
Changes from 12 commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -43,6 +43,7 @@
import com.google.api.gax.rpc.StreamController;
import com.google.api.gax.rpc.UnaryCallSettings;
import com.google.api.gax.rpc.UnaryCallable;
import com.google.api.gax.util.FakeLogHandler;
import com.google.common.base.Preconditions;
import com.google.common.collect.ImmutableList;
import com.google.common.collect.Lists;
Expand All @@ -66,9 +67,6 @@
import java.util.concurrent.ScheduledFuture;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicInteger;
import java.util.logging.Handler;
import java.util.logging.LogRecord;
import java.util.stream.Collectors;
import org.junit.After;
import org.junit.Assert;
import org.junit.Test;
Expand Down Expand Up @@ -717,23 +715,4 @@ public void testDoubleRelease() throws Exception {
ChannelPool.LOG.removeHandler(logHandler);
}
}

private static class FakeLogHandler extends Handler {
List<LogRecord> records = new ArrayList<>();

@Override
public void publish(LogRecord record) {
records.add(record);
}

@Override
public void flush() {}

@Override
public void close() throws SecurityException {}

List<String> getAllMessages() {
return records.stream().map(LogRecord::getMessage).collect(Collectors.toList());
}
}
}
1 change: 1 addition & 0 deletions gax-java/gax/pom.xml
Original file line number Diff line number Diff line change
Expand Up @@ -76,6 +76,7 @@
<include>com/google/api/gax/core/**</include>
<include>com/google/api/gax/rpc/testing/**</include>
<include>com/google/api/gax/rpc/mtls/**</include>
<include>com/google/api/gax/util/**</include>
</includes>
</configuration>
</execution>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -35,14 +35,24 @@
import com.google.api.gax.retrying.ExponentialRetryAlgorithm;
import com.google.api.gax.retrying.RetrySettings;
import com.google.api.gax.retrying.TimedAttemptSettings;
import com.google.common.annotations.VisibleForTesting;
import java.util.concurrent.CancellationException;
import java.util.logging.Level;
import java.util.logging.Logger;

/**
* 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
Copy link
Contributor

Choose a reason for hiding this comment

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

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

public static Logger LOGGER = Logger.getLogger(OperationTimedPollAlgorithm.class.getName());
Copy link
Collaborator

Choose a reason for hiding this comment

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

Why the logger has to be public?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

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?

Copy link
Contributor

Choose a reason for hiding this comment

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

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.

Copy link
Collaborator

Choose a reason for hiding this comment

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


public static final String LRO_TROUBLESHOOTING_LINK =
"https://github.com/googleapis/google-cloud-java#lro-timeouts";

/**
* Creates the polling algorithm, using the default {@code NanoClock} for time computations.
*
Expand Down Expand Up @@ -77,6 +87,13 @@ public boolean shouldRetry(TimedAttemptSettings nextAttemptSettings)
if (super.shouldRetry(nextAttemptSettings)) {
return true;
}
if (LOGGER.isLoggable(Level.SEVERE)) {
Copy link
Contributor

Choose a reason for hiding this comment

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

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?).

Copy link
Contributor Author

Choose a reason for hiding this comment

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

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

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I decreased it to WARNING

LOGGER.log(
Level.SEVERE,
"The task has been cancelled. Please refer to "
+ LRO_TROUBLESHOOTING_LINK
+ " for more information");
}
throw new CancellationException();
}

Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,59 @@
/*
* Copyright 2017 Google LLC
diegomarquezp marked this conversation as resolved.
Show resolved Hide resolved
*
* Redistribution and use in source and binary forms, with or without
* modification, are permitted provided that the following conditions are
* met:
*
* * Redistributions of source code must retain the above copyright
* notice, this list of conditions and the following disclaimer.
* * Redistributions in binary form must reproduce the above
* copyright notice, this list of conditions and the following disclaimer
* in the documentation and/or other materials provided with the
* distribution.
* * Neither the name of Google LLC nor the names of its
* contributors may be used to endorse or promote products derived from
* this software without specific prior written permission.
*
* THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
* "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
* LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
* A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
* OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
* SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
* LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
* DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
* THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
* (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
* OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
*/
package com.google.api.gax.util;

import java.util.ArrayList;
import java.util.List;
import java.util.logging.Handler;
import java.util.logging.LogRecord;
import java.util.stream.Collectors;

/*
* Convenience class that stores the log entries produced by any logger
* It can then be inspected - its entries are a list log records
*/
public class FakeLogHandler extends Handler {
List<LogRecord> records = new ArrayList<>();

@Override
public void publish(LogRecord record) {
records.add(record);
}

@Override
public void flush() {}

@Override
public void close() throws SecurityException {}

public List<String> getAllMessages() {
return records.stream().map(LogRecord::getMessage).collect(Collectors.toList());
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -16,10 +16,13 @@
package com.google.showcase.v1beta1.it;

import static com.google.common.truth.Truth.assertThat;
import static org.junit.Assert.assertEquals;
import static org.junit.Assert.assertThrows;

import com.google.api.gax.longrunning.OperationFuture;
import com.google.api.gax.longrunning.OperationTimedPollAlgorithm;
import com.google.api.gax.retrying.RetrySettings;
import com.google.api.gax.util.FakeLogHandler;
import com.google.protobuf.Timestamp;
import com.google.showcase.v1beta1.EchoClient;
import com.google.showcase.v1beta1.WaitMetadata;
Expand Down Expand Up @@ -121,6 +124,8 @@ public void testHttpJson_LROSuccessfulResponse_doesNotExceedTotalTimeout() throw
@Test
public void testGRPC_LROUnsuccessfulResponse_exceedsTotalTimeout_throwsDeadlineExceededException()
throws Exception {
FakeLogHandler logHandler = new FakeLogHandler();
Copy link
Contributor

@lqiu96 lqiu96 Nov 13, 2023

Choose a reason for hiding this comment

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

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

Copy link
Contributor Author

Choose a reason for hiding this comment

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

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

OperationTimedPollAlgorithm.LOGGER.addHandler(logHandler);
RetrySettings initialUnaryRetrySettings =
RetrySettings.newBuilder()
.setInitialRpcTimeout(Duration.ofMillis(5000L))
Expand Down Expand Up @@ -149,6 +154,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))
Copy link
Collaborator

Choose a reason for hiding this comment

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

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

Copy link
Contributor Author

Choose a reason for hiding this comment

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

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?

Copy link
Collaborator

Choose a reason for hiding this comment

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

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

I think this maybe better.

.contains(OperationTimedPollAlgorithm.LRO_TROUBLESHOOTING_LINK);
} finally {
grpcClient.close();
grpcClient.awaitTermination(
Expand All @@ -160,6 +168,8 @@ public void testGRPC_LROUnsuccessfulResponse_exceedsTotalTimeout_throwsDeadlineE
public void
testHttpJson_LROUnsuccessfulResponse_exceedsTotalTimeout_throwsDeadlineExceededException()
throws Exception {
FakeLogHandler logHandler = new FakeLogHandler();
OperationTimedPollAlgorithm.LOGGER.addHandler(logHandler);
Copy link
Contributor

Choose a reason for hiding this comment

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

Same here

RetrySettings initialUnaryRetrySettings =
RetrySettings.newBuilder()
.setInitialRpcTimeout(Duration.ofMillis(5000L))
Expand Down Expand Up @@ -188,6 +198,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))
.contains(OperationTimedPollAlgorithm.LRO_TROUBLESHOOTING_LINK);
} finally {
httpjsonClient.close();
httpjsonClient.awaitTermination(
Expand Down