Bc/bulk error debug by schmidt-sebastian · Pull Request #1330 · googleapis/nodejs-firestore

schmidt-sebastian · 2020-10-15T03:42:20Z

Thank you for opening a Pull Request! Before submitting your PR, there are a few things you can do to make sure it goes smoothly:

Make sure to open an issue as a bug/issue before writing your code! That way we can discuss the change, evaluate designs, and agree on the general idea
Ensure the tests and linter pass
Code coverage does not decrease (if any source code was changed)
Appropriate docs were updated (if necessary)

Fixes #<issue_number_goes_here> 🦕

…e into bc/bulk-error

schmidt-sebastian

Thanks for the update. We are pretty close. Feel free to ignore feedback that is contradicting :)

schmidt-sebastian · 2020-10-16T22:41:15Z

+export function voidPromise(promise: Promise<unknown>): Promise<void> {
+  return promise.then(
+    () => {},
+    () => {}
+  );
+}


The scary part of this is that it swallows all errors. This is what you want, but it should apparent from the name.

schmidt-sebastian · 2020-10-16T22:42:08Z

+   *
+   * @private
+   */
+  _addOperation(


Now unused.

schmidt-sebastian · 2020-10-16T22:43:02Z

+   *
+   * @private
+   */
+  get _lastOp(): PendingWriteOp {


Now unused.

schmidt-sebastian · 2020-10-16T23:23:13Z

    });
  }

+  private wrapRetry(


Please add a method comment.

Renamed and done.

schmidt-sebastian · 2020-10-16T23:23:27Z

+  private wrapRetry(
+    promise: Promise<WriteResult>,
+    documentRef: firestore.DocumentReference,
+    retryCount: number,


Again, not sure what this means.

Renamed to failedAttempts.

schmidt-sebastian · 2020-10-16T23:25:26Z

+        } else {
+          throw bulkWriterError;
+        }
+      });


Nit: This might be slightly prettier if we used try/catch with async/await here.

good idea. Looks much cleaner and easier to understand.

schmidt-sebastian · 2020-10-16T23:26:42Z

+    documentRef: firestore.DocumentReference,
+    retryCount: number,
+    operationType: 'create' | 'set' | 'update' | 'delete',
+    retryFn: () => Promise<WriteResult>


This is the original function isn't it? Could we just call it in this method ourselves, which would drop the promise argument.

High IQ vision. +10000

codecov · 2020-10-21T20:33:20Z

Codecov Report

Merging #1330 into master will increase coverage by 0.02%.
The diff coverage is 100.00%.

@@            Coverage Diff             @@
##           master    #1330      +/-   ##
==========================================
+ Coverage   98.48%   98.51%   +0.02%     
==========================================
  Files          32       32              
  Lines       19108    19282     +174     
  Branches     1377     1382       +5     
==========================================
+ Hits        18819    18995     +176     
+ Misses        286      284       -2     
  Partials        3        3

Impacted Files	Coverage Δ
dev/src/bulk-writer.ts	`99.80% <100.00%> (+0.04%)`	⬆️
dev/src/util.ts	`98.50% <100.00%> (+0.11%)`	⬆️
dev/src/write-batch.ts	`100.00% <100.00%> (ø)`
dev/src/pool.ts	`98.23% <0.00%> (-0.45%)`	⬇️
dev/src/watch.ts	`99.06% <0.00%> (-0.12%)`	⬇️
dev/src/document.ts	`98.68% <0.00%> (-0.10%)`	⬇️
dev/src/index.ts	`97.52% <0.00%> (-0.07%)`	⬇️
dev/src/reference.ts	`99.89% <0.00%> (+<0.01%)`	⬆️
dev/src/v1/firestore_client.ts	`98.17% <0.00%> (+0.05%)`	⬆️
dev/src/v1/firestore_admin_client.ts	`98.84% <0.00%> (+0.05%)`	⬆️
... and 4 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 6b7371b...9a2a792. Read the comment docs.

schmidt-sebastian · 2020-10-21T19:21:52Z

  // on end users.
  // eslint-disable-next-line @typescript-eslint/no-explicit-any
  get(field: string | FieldPath): any {
+    console.error('current field', field);


Please remove.

schmidt-sebastian · 2020-10-21T19:22:34Z

+ * This is primarily used to wait for a promise to complete when the result of
+ * the promise will be discarded.
+ */
+export function voidPromiseNoThrow(promise: Promise<unknown>): Promise<void> {


Optional suggestion: s/voidPromiseNoThrow/silence?

changed to silencePromise.

schmidt-sebastian · 2020-10-21T20:03:31Z

+   * new operations can be enqueued, except for retry operations scheduled by
+   * the error handler.
+   */
+  private _closed = false;


s/_closed/_closing based on your comment.

schmidt-sebastian · 2020-10-21T20:05:54Z

+   * fails.
+   */
+  private _errorFn: (error: BulkWriterError) => boolean = error => {
+    const retryCodes = getRetryCodes('batchWrite');


Regarding logging since the comment thread doesn't show up:

I think we need to add logging, otherwise we have no insight into what happens and why writes get re-scheduled. I am not worried about this being noisy, but we should log to the log function and not to console.log.

Note that a user-provided error handler would also overwrite this.

added logger.

schmidt-sebastian · 2020-10-21T20:08:09Z

+   * bulkWriter
+   *   .onWriteError((error) => {
+   *     if (
+   *       shouldRetry(error.code) &&


Can you just use some hardcoded error check (error.code === GrpcStatus.UNAVAILABLE) in this example?

schmidt-sebastian · 2020-10-21T20:21:54Z


-      this.sendReadyBatches();
+      if (batchQueue === this._retryBatchQueue) {
+        this._retryBatchQueue.forEach(batch => batch.markReadyToSend());


Who is going to send these batches? Don't we need to schedule a commit here so that the retries work even without flush()? If we do so, we might not need to retry in _flush().

Changed to power all retry batch scheduling to sendBatch(). Now, flush() schedules writes on the batchQueue, then kicks off the retryBatch if there are retries. Subsequent retries are now handled when the first retry batch comes back.

Also, I moved the markReadyToSend() mapping for retryBatches into sendReadyBatches(). There's two call points (flush and sendBatch) that would require a forEach() call, and I got bitten several times by forgetting to mark the batches as ready to send.

schmidt-sebastian · 2020-10-21T20:33:29Z

+    documentRef: firestore.DocumentReference,
+    operationType: 'create' | 'set' | 'update' | 'delete',
+    operationFn: (bulkCommitBatch: BulkCommitBatch) => Promise<WriteResult>
+  ): Promise<WriteResult> {
+    this.verifyNotClosed();
+
+    // A deferred promise that resolves when operationFn completes.
+    const operationCompletedDeferred = new Deferred<void>();
+    this._pendingOps.add(operationCompletedDeferred.promise);
+
+    const op = this.runOperationWithRetries(
+      documentRef,
+      operationType,
+      operationFn,
+      /* failedAttempts= */ 0
+    );
+
+    this.sendReadyBatches();
+    return op
+      .then(res => {
+        operationCompletedDeferred.resolve();
+        this._pendingOps.delete(operationCompletedDeferred.promise);
+        return res;
+      })
+      .catch(err => {
+        operationCompletedDeferred.resolve();
+        this._pendingOps.delete(operationCompletedDeferred.promise);
+        throw err;
+      });
+  }
+
+  /**
+   * Runs the provided operation and retries on failure until the error
+   * callback says not to.
+   */
+  private async runOperationWithRetries(
+    documentRef: firestore.DocumentReference,
+    operationType: 'create' | 'set' | 'update' | 'delete',
+    operationFn: (bulkCommitBatch: BulkCommitBatch) => Promise<WriteResult>,
+    failedAttempts: number
+  ): Promise<WriteResult> {
+    try {
+      const batchQueue =
+        failedAttempts > 0 ? this._retryBatchQueue : this._batchQueue;
+      const bulkCommitBatch = this.getEligibleBatch(batchQueue);
+      const operationResult = await operationFn(bulkCommitBatch);
+
+      this._successFn(documentRef, operationResult);
+      return operationResult;
+    } catch (error) {
+      const bulkWriterError = new BulkWriterError(
+        error.code,
+        error.message,
+        documentRef,
+        operationType,
+        failedAttempts
+      );
+
+      const shouldRetry = this._errorFn(bulkWriterError);
+      if (shouldRetry) {
+        return this.runOperationWithRetries(
+          documentRef,
+          operationType,
+          operationFn,
+          failedAttempts + 1
+        );
+      } else {
+        throw bulkWriterError;
+      }
+    }
+  }


Simplification suggestion:

Suggested change

documentRef: firestore.DocumentReference,

operationType: 'create' | 'set' | 'update' | 'delete',

operationFn: (bulkCommitBatch: BulkCommitBatch) => Promise<WriteResult>

): Promise<WriteResult> {

this.verifyNotClosed();

// A deferred promise that resolves when operationFn completes.

const operationCompletedDeferred = new Deferred<void>();

this._pendingOps.add(operationCompletedDeferred.promise);

const op = this.runOperationWithRetries(

documentRef,

operationType,

operationFn,

/* failedAttempts= */ 0

);

this.sendReadyBatches();

return op

.then(res => {

operationCompletedDeferred.resolve();

this._pendingOps.delete(operationCompletedDeferred.promise);

return res;

})

.catch(err => {

operationCompletedDeferred.resolve();

this._pendingOps.delete(operationCompletedDeferred.promise);

throw err;

});

}

/**

* Runs the provided operation and retries on failure until the error

* callback says not to.

*/

private async runOperationWithRetries(

documentRef: firestore.DocumentReference,

operationType: 'create' | 'set' | 'update' | 'delete',

operationFn: (bulkCommitBatch: BulkCommitBatch) => Promise<WriteResult>,

failedAttempts: number

): Promise<WriteResult> {

try {

const batchQueue =

failedAttempts > 0 ? this._retryBatchQueue : this._batchQueue;

const bulkCommitBatch = this.getEligibleBatch(batchQueue);

const operationResult = await operationFn(bulkCommitBatch);

this._successFn(documentRef, operationResult);

return operationResult;

} catch (error) {

const bulkWriterError = new BulkWriterError(

error.code,

error.message,

documentRef,

operationType,

failedAttempts

);

const shouldRetry = this._errorFn(bulkWriterError);

if (shouldRetry) {

return this.runOperationWithRetries(

documentRef,

operationType,

operationFn,

failedAttempts + 1

);

} else {

throw bulkWriterError;

}

}

}

private async runOperation(

documentRef: firestore.DocumentReference,

operationType: 'create' | 'set' | 'update' | 'delete',

operationFn: (bulkCommitBatch: BulkCommitBatch) => Promise<WriteResult>

): Promise<WriteResult> {

this.verifyNotClosed();

this.sendReadyBatches();

for (let failedAttempts = 0; ; ++failedAttempts) {

// A deferred promise that resolves when operationFn completes.

const operationCompletedDeferred = new Deferred<void>();

this._pendingOps.add(operationCompletedDeferred.promise);

const batchQueue =

failedAttempts > 0 ? this._retryBatchQueue : this._batchQueue;

const bulkCommitBatch = this.getEligibleBatch(batchQueue);

try {

const operationResult = await operationFn(bulkCommitBatch);

this._successFn(documentRef, operationResult);

return operationResult;

} catch (error) {

const bulkWriterError = new BulkWriterError(

error.code,

error.message,

documentRef,

operationType,

failedAttempts

);

const shouldRetry = this._errorFn(bulkWriterError);

if (!shouldRetry) {

throw bulkWriterError;

}

} finally {

this._pendingOps.delete(operationCompletedDeferred.promise);

}

}

}

Man... I remember staring at my code trying to cut it down, but you've done it!

Had to make a couple of changes

move out operationCompletedDeferred to outside of the for-loop. The implementation here resolved the pendingOp after each retry loop.

move out verifyNotClosed() so an error is thrown instead of a rejected promise.

move sendReadyBatches() into the for loop since it needs to wait for getEligibleBatch() to create the new batch (for the first batch).

resolved the deferred promise at the end.

schmidt-sebastian · 2020-10-21T20:34:53Z

     * @param data The object to serialize as the document.
-     * @returns A promise that resolves with the result
-     * of the write. Throws an error if the write fails.
+     * @returns {Promise<WriteResult>} A promise that resolves with the result


No need to include the return type in TypeScript. You should keep the type of the rejected result, since that is not apparent here.

Co-authored-by: Sebastian Schmidt <[email protected]>

schmidt-sebastian

This is pretty good. I think we should verify some of the assumptions we made at API discussion, but we can probably take this back to the original PR

schmidt-sebastian · 2020-10-22T22:45:55Z

+      error.code !== undefined &&
+      retryCodes.includes(error.code) &&
+      error.failedAttempts < MAX_RETRY_ATTEMPTS;
+    logger(


As proposed in API meeting, we should move this logging to the callsite. This will also allow to us to log user-customized retries.

schmidt-sebastian · 2020-10-22T22:48:40Z

+    let batchQueue = this._batchQueue;
+    batchQueue.forEach(batch => batch.markReadyToSend());
+
+    // Send all scheduled operations on the BatchQueue first.
+    this.sendReadyBatches(batchQueue);
+    await Promise.all(this._pendingBatches);
+
+    // Afterwards, send all accumulated retry operations. Wait until the
+    // retryBatchQueue is cleared. This way, operations scheduled after
+    // flush() will not be sent until the retries are completed.
+    batchQueue = this._retryBatchQueue;
+    if (batchQueue.length > 0) {
+      this.sendReadyBatches(batchQueue);
+    }


I wonder if this logic can be combined. The logic for the two different lists is essentially the same.

I could combine it into a two-loop for-loop, but that doesn't feel as readable. Any suggestions?

schmidt-sebastian · 2020-10-22T22:49:51Z

+    // Always mark retry batches as READY_TO_SEND.
+    if (batchQueue === this._retryBatchQueue) {
+      batchQueue.forEach(batch => batch.markReadyToSend());
+    }


This seems out of place here. Can we do this at the callsite?

There are two callsites, which is why i originally moved it into here. Moved it back out.

schmidt-sebastian · 2020-10-22T22:53:01Z

+    } finally {
+      operationCompletedDeferred.resolve();
+      this._pendingOps.delete(operationCompletedDeferred.promise);
+    }


I think the double try/catch block is a bit harder to parse then just calling these two lines twice.

The operationCompletedDeferred must resolve after the error is thrown, or else the flush and write promises resolve out of order. Given that, I don't see any good way to do so other than moving the outer try block into a separate function that encapsulates this one, or having duplicate code to handle this in each operation.

schmidt-sebastian · 2020-10-22T22:54:12Z

+    process.on('unhandledRejection', () => {
+      errorThrown = true;
+      unhandledDeferred.resolve();
+    });


Let's confirm with Yoshi team whether it would be ok to swallow these.

SG, started a conversation with them in the node room.

…restore into bc/bulk-error-debug

schmidt-sebastian · 2020-10-28T22:55:25Z

Closing this as well are moving back to the original PR.

Brian Chen and others added 14 commits September 30, 2020 12:30

feat: add onError handler to BulkWriter

09bc422

add additional test

8721708

Merge branch 'master' into bc/bulk-error

a35e9ad

rename retry to addOperation

d748c20

feat: add onError handler to BulkWriter

7c292c4

add additional test

2183baa

rename retry to addOperation

0a26962

Merge branch 'master' into bc/bulk-error

e704188

Merge branch 'bc/bulk-error' of github.com:googleapis/nodejs-firestor…

dbba557

…e into bc/bulk-error

resolve comments

6ed9bda

Add BulkWriterError

2bfcb0b

update comments

83698f4

Remove usage of BulkWriterOperation

1c60b61

wip

d89c0ef

schmidt-sebastian requested review from a team October 15, 2020 03:42

schmidt-sebastian marked this pull request as draft October 15, 2020 03:42

google-cla Bot added the cla: yes This human has signed the Contributor License Agreement. label Oct 15, 2020

almost working but close() resolves a tick before the last set()

c716b54

thebrianchen force-pushed the bc/bulk-error-debug branch from d144bfe to c716b54 Compare October 15, 2020 04:38

thebrianchen mentioned this pull request Oct 15, 2020

feat: add onWriteError() and onWriteResult() handlers to BulkWriter #1315

Merged

product-auto-label Bot added the api: firestore Issues related to the googleapis/nodejs-firestore API. label Oct 15, 2020

Brian Chen and others added 8 commits October 15, 2020 11:54

tried aggregating promises without success

11e6bdd

Checkmark

09c4846

Checkmark

d1a1b81

Before retry batches

edade9d

Before removing OPInfo

37acbd9

Remove batch queue

ec82fc2

Checkmark

168254a

Before pending batch list

c4078f6

schmidt-sebastian and others added 5 commits October 15, 2020 13:18

Before removing pendingOps

e5bbf81

all but one test working

b36478b

Cleanup

4ec3db6

fix

c5bba24

clean up code, add retryBatchQueue

6965b48

schmidt-sebastian commented Oct 16, 2020

View reviewed changes

Brian Chen added 3 commits October 21, 2020 14:00

massive cleanup + proper flush() resolution

41c97fa

Merge branch 'master' into bc/bulk-error-debug

c8c8eb7

remove it.only in system test

6ca67f9

thebrianchen force-pushed the bc/bulk-error-debug branch from d3cd6d0 to 6ca67f9 Compare October 21, 2020 20:26

schmidt-sebastian commented Oct 21, 2020

View reviewed changes

resolve comments, refactor code, send retry batches from sendBatch

be98ffa

schmidt-sebastian commented Oct 21, 2020

View reviewed changes

Comment thread dev/src/bulk-writer.ts Outdated

Brian Chen and others added 2 commits October 22, 2020 10:09

Merge branch 'master' into bc/bulk-error-debug

1a03fec

Update dev/src/bulk-writer.ts

dc13be2

Co-authored-by: Sebastian Schmidt <[email protected]>

schmidt-sebastian commented Oct 22, 2020

View reviewed changes

Brian Chen added 2 commits October 26, 2020 14:26

silence UnhandledPromiseRejections + resolve other comments

4a583c5

Merge branch 'bc/bulk-error-debug' of github.com:googleapis/nodejs-fi…

9a2a792

…restore into bc/bulk-error-debug

schmidt-sebastian closed this Oct 28, 2020

thebrianchen deleted the bc/bulk-error-debug branch January 25, 2021 23:32

Conversation

schmidt-sebastian commented Oct 15, 2020

Uh oh!

schmidt-sebastian left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

codecov Bot commented Oct 21, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

schmidt-sebastian left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

codecov Bot commented Oct 21, 2020 •

edited

Loading