Skip to content

Commit 544690e

Browse files
caohy1988claude
andcommitted
fix(bigquery): address round-5 review — completion-ordered cleanup, deadline-safe Storage Writer entry and teardown
Resolves both round-5 P1 findings on PR google#1344: 1. Finalization is completion-ordered: RxJava's doFinally notifies the downstream BEFORE running its action, so blockingAwait()/subscribers could observe success while lifecycle marking, processor draining, and teardown were still running. Both ensureInvocationCompleted and plugin-wide close now run an idempotent cleanup action via onErrorComplete().andThen(Completable.fromAction(cleanup)) — cleanup completes before the returned Completable does — with the same action in a trailing doFinally to cover disposal. 2. Storage Writer calls obey the public bound. Admission: StreamWriter's default LimitExceededBehavior.Block parks append() up to five minutes on inflight quota; the writer is now built with ThrowException, so quota saturation surfaces as an accounted append failure instead of an unbounded block. Teardown: StreamWriter.close() can block minutes (thread join + client/callback-pool waits); it is detached to a daemon thread so teardownOnce — and the public close()/deferred-flush path — honors the absolute deadline. No further work touches the writer at that point, and drop counters are final before delivery. Tests: new completion-ordering regression (async pending-task completion with latch-blocked cleanup; the returned Completable must not complete until cleanup releases); blocking StreamWriter.close() must not block the public close() while the writer is still closed eventually; the multi-processor close bound is tightened to <900ms so the old per-processor-deadline behavior fails; writer.close() verifications use timeout() now that teardown is detached. Focused BQAA suite 170 passed (previous: 168); full core 1,626 passed / 0 failed. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
1 parent b941ac7 commit 544690e

4 files changed

Lines changed: 162 additions & 36 deletions

File tree

core/src/main/java/com/google/adk/plugins/agentanalytics/BatchProcessor.java

Lines changed: 18 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -448,11 +448,24 @@ private void teardownOnce() {
448448
}
449449
}
450450
if (this.writer != null) {
451-
try {
452-
this.writer.close();
453-
} catch (RuntimeException e) {
454-
logger.log(Level.SEVERE, "Failed to close BigQuery writer", e);
455-
}
451+
// StreamWriter.close() can block far beyond any shutdownTimeout (it joins the append
452+
// thread, then may wait minutes on the client and callback pools). Detach it to a daemon
453+
// thread so teardown — and therefore the public close()/deferred-flush path — honors the
454+
// absolute deadline. No further work touches the writer: teardown only runs after appends
455+
// have stopped (closed gate + flush-mutex ownership), and drop counters are final below.
456+
StreamWriter writerToClose = this.writer;
457+
Thread writerCloser =
458+
new Thread(
459+
() -> {
460+
try {
461+
writerToClose.close();
462+
} catch (RuntimeException e) {
463+
logger.log(Level.SEVERE, "Failed to close BigQuery writer", e);
464+
}
465+
},
466+
"bq-analytics-writer-close");
467+
writerCloser.setDaemon(true);
468+
writerCloser.start();
456469
}
457470
// Deliver the final snapshot only now, when no flush can mutate the counters anymore.
458471
Consumer<ImmutableMap<String, Long>> statsConsumer = this.onFinalStats;

core/src/main/java/com/google/adk/plugins/agentanalytics/PluginState.java

Lines changed: 55 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,7 @@
2121
import static java.util.concurrent.TimeUnit.MILLISECONDS;
2222
import static java.util.concurrent.TimeUnit.SECONDS;
2323

24+
import com.google.api.gax.batching.FlowController;
2425
import com.google.api.gax.core.FixedCredentialsProvider;
2526
import com.google.api.gax.retrying.RetrySettings;
2627
import com.google.api.gax.rpc.FixedHeaderProvider;
@@ -34,6 +35,7 @@
3435
import com.google.common.collect.ImmutableList;
3536
import com.google.common.collect.ImmutableMap;
3637
import io.reactivex.rxjava3.core.Completable;
38+
import io.reactivex.rxjava3.functions.Action;
3739
import java.io.IOException;
3840
import java.util.Collection;
3941
import java.util.Map;
@@ -209,6 +211,11 @@ protected StreamWriter createWriter() {
209211
try {
210212
return StreamWriter.newBuilder(streamName, writeClient)
211213
.setTraceId(BigQueryUtils.getVersionHeaderValue() + ":" + UUID.randomUUID())
214+
// Nonblocking admission: the default LimitExceededBehavior.Block parks append() for up
215+
// to five minutes waiting on inflight quota, escaping every shutdownTimeout bound this
216+
// plugin enforces. ThrowException surfaces quota saturation as an append failure, which
217+
// the flush path catches and accounts as dropped rows.
218+
.setLimitExceededBehavior(FlowController.LimitExceededBehavior.ThrowException)
212219
.setRetrySettings(retrySettings)
213220
.setWriterSchema(BigQuerySchema.getArrowSchema())
214221
// Route Storage Write append RPCs to the dataset's region. Without this, appends to any
@@ -422,20 +429,13 @@ private Completable finalizeInvocation(String invocationId, java.time.Instant fi
422429
CompletableFuture.allOf(tasks.toArray(new CompletableFuture<?>[0])));
423430
}
424431
logger.fine("Waiting for pending tasks to complete for invocation ID: " + invocationId);
425-
return tasksState
426-
.timeout(config.shutdownTimeout().toMillis(), MILLISECONDS)
427-
.doOnError(
428-
e -> {
429-
if (e instanceof TimeoutException) {
430-
logger.log(
431-
Level.WARNING,
432-
"Timeout while waiting for pending tasks to complete for invocation ID: "
433-
+ invocationId,
434-
e);
435-
}
436-
})
437-
.onErrorComplete()
438-
.doFinally(
432+
// Idempotent cleanup shared by the completion-ordered andThen (normal path) and doFinally
433+
// (disposal path): RxJava's doFinally notifies the downstream FIRST and runs its action
434+
// afterwards, so relying on it alone would let blockingAwait()/subscribers observe success
435+
// while finalization is still running. andThen(fromAction) runs the cleanup BEFORE the
436+
// returned Completable completes.
437+
Action cleanup =
438+
runOnce(
439439
() -> {
440440
// Mark the durable lifecycle token FIRST (before removing the processor), so any
441441
// continuation that later finds no mapping is guaranteed to observe the terminal
@@ -464,6 +464,32 @@ private Completable finalizeInvocation(String invocationId, java.time.Instant fi
464464
logger.fine("Removing pending tasks for invocation ID: " + invocationId);
465465
pendingTasks.remove(invocationId);
466466
});
467+
return tasksState
468+
.timeout(config.shutdownTimeout().toMillis(), MILLISECONDS)
469+
.doOnError(
470+
e -> {
471+
if (e instanceof TimeoutException) {
472+
logger.log(
473+
Level.WARNING,
474+
"Timeout while waiting for pending tasks to complete for invocation ID: "
475+
+ invocationId,
476+
e);
477+
}
478+
})
479+
.onErrorComplete()
480+
.andThen(Completable.fromAction(cleanup))
481+
.doFinally(cleanup);
482+
}
483+
484+
/** Wraps an action so repeated invocations (completion path + disposal path) run it once. */
485+
private static Action runOnce(Action delegate) {
486+
java.util.concurrent.atomic.AtomicBoolean ran =
487+
new java.util.concurrent.atomic.AtomicBoolean(false);
488+
return () -> {
489+
if (ran.compareAndSet(false, true)) {
490+
delegate.run();
491+
}
492+
};
467493
}
468494

469495
private void foldStats(ImmutableMap<String, Long> stats) {
@@ -523,17 +549,9 @@ private Completable closeInternal(java.time.Instant closeDeadline) {
523549
Completable.fromCompletionStage(
524550
CompletableFuture.allOf(tasks.toArray(new CompletableFuture<?>[0])));
525551
}
526-
return tasksState
527-
.timeout(config.shutdownTimeout().toMillis(), MILLISECONDS)
528-
.doOnError(
529-
e -> {
530-
if (e instanceof TimeoutException) {
531-
logger.log(
532-
Level.WARNING, "Timeout while waiting for pending tasks to complete.", e);
533-
}
534-
})
535-
.onErrorComplete()
536-
.doFinally(
552+
// Completion-ordered cleanup shared with the disposal path; see finalizeInvocation.
553+
Action cleanup =
554+
runOnce(
537555
() -> {
538556
for (InvocationLifecycle lifecycle : lifecycles.values()) {
539557
lifecycle.markFinalized();
@@ -589,5 +607,17 @@ private Completable closeInternal(java.time.Instant closeDeadline) {
589607
logger.log(Level.WARNING, "Failed to close GCS offloader", e);
590608
}
591609
});
610+
return tasksState
611+
.timeout(config.shutdownTimeout().toMillis(), MILLISECONDS)
612+
.doOnError(
613+
e -> {
614+
if (e instanceof TimeoutException) {
615+
logger.log(
616+
Level.WARNING, "Timeout while waiting for pending tasks to complete.", e);
617+
}
618+
})
619+
.onErrorComplete()
620+
.andThen(Completable.fromAction(cleanup))
621+
.doFinally(cleanup);
592622
}
593623
}

core/src/test/java/com/google/adk/plugins/agentanalytics/BatchProcessorTest.java

Lines changed: 33 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -24,7 +24,6 @@
2424
import static org.mockito.Mockito.doReturn;
2525
import static org.mockito.Mockito.mock;
2626
import static org.mockito.Mockito.never;
27-
import static org.mockito.Mockito.times;
2827
import static org.mockito.Mockito.verify;
2928
import static org.mockito.Mockito.when;
3029

@@ -377,7 +376,7 @@ public void close_flushesAndClosesResources() throws Exception {
377376
}
378377

379378
verify(mockWriter).append(any(ArrowRecordBatch.class));
380-
verify(mockWriter).close();
379+
verify(mockWriter, org.mockito.Mockito.timeout(2000)).close();
381380
}
382381

383382
@Test
@@ -408,7 +407,7 @@ public void close_isIdempotent() {
408407
bp.close();
409408
bp.close();
410409

411-
verify(mockWriter, times(1)).close();
410+
verify(mockWriter, org.mockito.Mockito.timeout(2000).times(1)).close();
412411
}
413412

414413
@Test
@@ -481,7 +480,7 @@ public void close_waitsForInFlightFlushBeforeTeardown() throws Exception {
481480
"close should have waited for the in-flight flush, took " + elapsedMs + "ms",
482481
elapsedMs >= 100);
483482
assertTrue("close should be bounded, took " + elapsedMs + "ms", elapsedMs < 5_000);
484-
verify(mockWriter).close();
483+
verify(mockWriter, org.mockito.Mockito.timeout(2000)).close();
485484
}
486485

487486
@Test
@@ -530,6 +529,35 @@ public void close_deadlineExpired_defersTeardownAndStatsToInFlightFlush() throws
530529
statsDelivered.await(5, java.util.concurrent.TimeUnit.SECONDS));
531530
inFlight.join(2000);
532531
assertEquals(1L, (long) finalStats.get().get("append_error"));
533-
verify(mockWriter).close();
532+
verify(mockWriter, org.mockito.Mockito.timeout(2000)).close();
533+
}
534+
535+
@Test
536+
public void close_blockingWriterClose_doesNotBlockTeardown() throws Exception {
537+
// The real StreamWriter.close() can block for minutes (thread join + client/pool waits); the
538+
// public close() must not inherit that, while the writer still gets closed eventually.
539+
java.util.concurrent.CountDownLatch writerClosed = new java.util.concurrent.CountDownLatch(1);
540+
org.mockito.Mockito.doAnswer(
541+
invocation -> {
542+
Thread.sleep(1500);
543+
writerClosed.countDown();
544+
return null;
545+
})
546+
.when(mockWriter)
547+
.close();
548+
BatchProcessor bp =
549+
new BatchProcessor(
550+
mockWriter, 10, Duration.ofMinutes(1), 10, executor, Duration.ofMillis(300));
551+
552+
long start = System.nanoTime();
553+
bp.close();
554+
long elapsedMs = (System.nanoTime() - start) / 1_000_000;
555+
556+
assertTrue(
557+
"close() must not block on StreamWriter.close(), took " + elapsedMs + "ms",
558+
elapsedMs < 1_000);
559+
assertTrue(
560+
"the writer must still be closed eventually",
561+
writerClosed.await(5, java.util.concurrent.TimeUnit.SECONDS));
534562
}
535563
}

core/src/test/java/com/google/adk/plugins/agentanalytics/PluginStateTest.java

Lines changed: 56 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -535,8 +535,63 @@ protected StreamWriter createWriter() {
535535
slowState.close().blockingAwait();
536536
long elapsedMs = (System.nanoTime() - start) / 1_000_000;
537537

538+
// Old behavior was ~one deadline PER processor (>=1000ms for two 500ms drains) before
539+
// executor waits; the shared absolute deadline finishes in ~one timeout plus slack.
538540
assertTrue(
539541
"multi-processor close must share one shutdownTimeout, took " + elapsedMs + "ms",
540-
elapsedMs < 1_100);
542+
elapsedMs < 900);
543+
}
544+
545+
@Test
546+
public void ensureInvocationCompleted_doesNotCompleteBeforeCleanupFinishes() throws Exception {
547+
// RxJava's doFinally notifies the downstream BEFORE running its action; finalization must be
548+
// completion-ordered so callers cannot observe success while cleanup is still running.
549+
String invocationId = "inv-ordered";
550+
java.util.concurrent.CountDownLatch cleanupStarted = new java.util.concurrent.CountDownLatch(1);
551+
java.util.concurrent.CountDownLatch cleanupRelease = new java.util.concurrent.CountDownLatch(1);
552+
BatchProcessor blockingProcessor = mock(BatchProcessor.class);
553+
org.mockito.Mockito.doAnswer(
554+
invocation -> {
555+
cleanupStarted.countDown();
556+
cleanupRelease.await(5, TimeUnit.SECONDS);
557+
return null;
558+
})
559+
.when(blockingProcessor)
560+
.closeAndFold(org.mockito.ArgumentMatchers.any(), org.mockito.ArgumentMatchers.any());
561+
TestPluginState orderedState =
562+
new TestPluginState(config) {
563+
@Override
564+
protected BatchProcessor removeProcessor(String id) {
565+
return id.equals(invocationId) ? blockingProcessor : super.removeProcessor(id);
566+
}
567+
};
568+
CompletableFuture<Void> pending = new CompletableFuture<>();
569+
orderedState.addPendingTask(invocationId, pending);
570+
571+
java.util.concurrent.atomic.AtomicBoolean observedComplete =
572+
new java.util.concurrent.atomic.AtomicBoolean(false);
573+
var unused =
574+
orderedState
575+
.ensureInvocationCompleted(invocationId)
576+
.subscribe(() -> observedComplete.set(true));
577+
578+
// Complete the pending task ASYNCHRONOUSLY so the chain advances on another thread and
579+
// blocks inside the (latched) cleanup.
580+
Thread completer = new Thread(() -> pending.complete(null));
581+
completer.start();
582+
assertTrue(cleanupStarted.await(2, TimeUnit.SECONDS));
583+
584+
// Cleanup is running but blocked: the returned Completable must NOT have completed.
585+
Thread.sleep(100);
586+
assertTrue(
587+
"completion must not be observable before cleanup finishes", !observedComplete.get());
588+
589+
cleanupRelease.countDown();
590+
completer.join(2000);
591+
long deadline = Instant.now().plusMillis(2000).toEpochMilli();
592+
while (!observedComplete.get() && Instant.now().toEpochMilli() < deadline) {
593+
Thread.sleep(10);
594+
}
595+
assertTrue("completion must be observable after cleanup finishes", observedComplete.get());
541596
}
542597
}

0 commit comments

Comments
 (0)