fix: respect PDML timeout when using streaming RPC

[olavloite]

@thiagotnunes Would you mind trying the same test with this PR? I don't have a dataset that is big enough that it will run for more than one hour.

Fixes #336

[thiagotnunes]

@olavloite will do so on Monday and will let you know.

Digging in a little on the fix, it seems we just needed to fix the keepalive for the rpc calls, so am I right to assume that the thinking is that the streamWaitTimeout is the one being respected for this particular call?

Thanks for looking into this!

[thiagotnunes]

I got another exception when running the code. I think there is a bug on using the remainingTimeout (line 108) on the PartitionedDMLTransaction. If the timeout is <= 0, we do not cancel the retry. A simple fix would be to break in this case. Below is the stack trace:

Exception in thread "main" com.google.cloud.spanner.SpannerException: UNKNOWN: Invalid timeout: < 0 s
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerExceptionPreformatted(SpannerExceptionFactory.java:211)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:57)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:151)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:94)
	at com.google.cloud.spanner.PartitionedDMLTransaction.executeStreamingPartitionedUpdate(PartitionedDMLTransaction.java:156)
	at com.google.cloud.spanner.SessionImpl.executePartitionedUpdate(SessionImpl.java:118)
	at com.google.cloud.spanner.SessionPool$PooledSession.executePartitionedUpdate(SessionPool.java:1349)
	at com.google.cloud.spanner.SessionPool$PooledSessionFuture.executePartitionedUpdate(SessionPool.java:1236)
	at com.google.cloud.spanner.DatabaseClientImpl$3.apply(DatabaseClientImpl.java:227)
	at com.google.cloud.spanner.DatabaseClientImpl$3.apply(DatabaseClientImpl.java:224)
	at com.google.cloud.spanner.DatabaseClientImpl.runWithSessionRetry(DatabaseClientImpl.java:241)
	at com.google.cloud.spanner.DatabaseClientImpl.executePartitionedUpdate(DatabaseClientImpl.java:222)
	at com.google.cloud.spanner.PdmlIssue.main(PdmlIssue.java:14)
Caused by: java.lang.IllegalArgumentException: Invalid timeout: < 0 s
	at com.google.common.base.Preconditions.checkArgument(Preconditions.java:142)
	at com.google.api.gax.grpc.GrpcCallContext.withStreamWaitTimeout(GrpcCallContext.java:177)
	at com.google.cloud.spanner.spi.v1.GapicSpannerRpc.executeStreamingPartitionedDml(GapicSpannerRpc.java:1108)
	at com.google.cloud.spanner.PartitionedDMLTransaction.executeStreamingPartitionedUpdate(PartitionedDMLTransaction.java:113)
	... 8 more

This is my executor:

final SpannerOptions options = SpannerOptions.newBuilder().build();
final Spanner spanner = options.getService();
final DatabaseId id = DatabaseId.of(PROJECT, INSTANCE, DATABASE);
final DatabaseClient client = spanner.getDatabaseClient(id);

client.executePartitionedUpdate(Statement.of(
    "UPDATE Table SET bool = true WHERE true"
));

[thiagotnunes]

In any case, the failure occurs after the specified timeout (2 hours by default).

[olavloite]

@thiagotnunes Thanks for the test results. I've updated the retry-loop to take a potential zero or negative deadline into account, and I've added some additional unit tests for this class. PTAL.

[thiagotnunes]

The latest tests that I've done have terminated with a com.google.cloud.spanner.SpannerException: DEADLINE_EXCEEDED, but the weird thing is that the process did not take 2 hours to fail, but around 68 mins, so it does seem that the 2 hours window is still not being respected.
I might have misspoke when I said that the previous one failed in 2 hours, I thought it did, but I had no timer in runner code. I added it now. These are the logs from the execution:

Started running at Tue Jul 14 12:41:21 AEST 2020
Exception in thread "main" com.google.cloud.spanner.SpannerException: DEADLINE_EXCEEDED
Finished running at Tue Jul 14 13:49:33 AEST 2020 (took 4092380ms)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerExceptionPreformatted(SpannerExceptionFactory.java:211)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:57)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:52)
	at com.google.cloud.spanner.SpannerExceptionFactory.fromApiException(SpannerExceptionFactory.java:229)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:144)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:94)
	at com.google.cloud.spanner.PartitionedDMLTransaction.executeStreamingPartitionedUpdate(PartitionedDMLTransaction.java:162)
	at com.google.cloud.spanner.SessionImpl.executePartitionedUpdate(SessionImpl.java:118)
	at com.google.cloud.spanner.SessionPool$PooledSession.executePartitionedUpdate(SessionPool.java:1349)
	at com.google.cloud.spanner.SessionPool$PooledSessionFuture.executePartitionedUpdate(SessionPool.java:1236)
	at com.google.cloud.spanner.DatabaseClientImpl$3.apply(DatabaseClientImpl.java:227)
	at com.google.cloud.spanner.DatabaseClientImpl$3.apply(DatabaseClientImpl.java:224)
	at com.google.cloud.spanner.DatabaseClientImpl.runWithSessionRetry(DatabaseClientImpl.java:241)
	at com.google.cloud.spanner.DatabaseClientImpl.executePartitionedUpdate(DatabaseClientImpl.java:222)
	at com.google.cloud.spanner.PmlIssue.main(PmlIssue.java:19)

Process finished with exit code 1

[thiagotnunes]

nit: would it be hard to inject the Stopwatch instead? Not a big deal, just wondering if we could use composition here. Disregard if it would be too hard to inject.

[thiagotnunes]

Nice tests!

[thiagotnunes]

I know what the problem is: multiple failures are occurring so whenever we are subtracting the elapsed time, we are subtracting the accumulated time of the stopWatch every time. In order to fix this, we should reset the stopWatch in the case that we are about to retry. We could add stopWatch.reset() when catching the UnavailableException and inside the if statement (after line 135 of the PartitionedDMLTransaction).

An example of the problem I am seeing:

1. We start the PDML statement.

stopWatch = "PT0S"
remainingTimeout = "PT2H"; 

2. After 10 mins there is a retry-able failure. We subtract the stopWatch from the remainingTimeout.

stopWatch = "PT10M";
remainingTimeout = remainingTimeout - stopWatch = "PT1H50M";

3. After 20 mins from the start (1) there is another failure. We again subtract the stopWatch from the remainingTimeout, but instead of subtracting 10 mins (time elapsed from the first retry to the second retry), we subtract 20 mins (time elapsed from the start to the second retry).

stopWatch = "PT20M"
remainingTimeout = remainingTimeout - stopWatch = "PT1H30M"; // This should had been PT1H40M

Btw, @olavloite let me know if you this feedback loop is too big (me testing a day after your change). I could implement these minor fixes if you'd like so, otherwise I am happy on testing / reporting back the results to you.

[olavloite]

@thiagotnunes Thanks for the elaborate testing and report. Hopefully the timeout problem should be fixed now.

And yes, please do feel free to add any additional fixes that might be needed to get this 100%.

[thiagotnunes]

@olavloite thanks for the fix. It worked as expected (timing out after 2 hours).