Skip to content
This repository was archived by the owner on Mar 4, 2026. It is now read-only.
This repository was archived by the owner on Mar 4, 2026. It is now read-only.

15 duplicate documents from query.stream after retry #1790

Closed
#1806
Closed
15 duplicate documents from query.stream after retry#1790
#1806
Assignees
dconeybe
Labels
api: firestoreIssues related to the googleapis/nodejs-firestore API.priority: p2Moderately-important priority. Fix may not be included in next release.type: bugError or flaw in code with unintended results or allowing sub-optimal usage patterns.
@wvanderdeijl

Description

@wvanderdeijl
wvanderdeijl
opened on Oct 22, 2022

Environment details

  • OS: MacOS 12.7 and Ubuntu 20.x (Cloud Run)
  • Node.js version: 16.17.1
  • npm version: 8.15.0
  • @google-cloud/firestore version: 4.15.1

In production (Cloud Run) we are suffering from an intermittent issue where we receive some documents twice from query.stream(). In our production code this reproduces almost 100% of the time and I've been trying to get a locally running example. Unfortunately I cannot get it to reproduce as frequently, but it does fail sometimes.

Logging indicates we suffer from an error:
Received stream error: Error: 14 UNAVAILABLE: The datastore operation timed out, or the data was temporarily unavailable.

The implementation at

nodejs-firestore/dev/src/reference.ts

Line 2347 in 50747ad

if (lastReceivedDocument) {
than tries to restart the stream from lastReceivedDocument but this sometimes seems to restart at a point that re-emits 15 documents from the stream that have already been emitted.
I guess there is some buffering going on between the different streams that are set up. According to https://nodejs.org/api/stream.html#buffering object streams have a default of 16 buffered objects and we consistently see 15 re-remitted documents. So it seems some documents are already in some buffer without lastReceivedDocument knowing about it.

It also appears that there might be multiple stream with 16 buffered elements at play here. After receiving document 58855 the stream resets to 58841 but the actual firestore error from the backend was after receiving 58902 which is even further along in the query.

My guess is that the root cause is error handler on the backendStream at

nodejs-firestore/dev/src/reference.ts

Line 2335 in 50747ad

backendStream.on('error', err => {
It unpipes the streams and starts over at lastReceivedDocument, but could it be that there are still documents buffered between the backendStream and the transformer that builds them into documents and keeps track of the lastReceivedDocument. If so, shouldn't these first be flushed to the transformer to emit them and increase the lastReceivedDocument before making a next attempt?

The example below sometimes reproduces this error locally:

import { Firestore, setLogFunction } from '@google-cloud/firestore';
import * as assert from 'assert';

const firestore = new Firestore({ projectId: 'my-project' });
setLogFunction(msg => process.stdout.write(msg + '\n'));

(async () => {
    // create 100_000 documents in batches of 10_000 (to prevent errors)
    for (let i = 0; i < 10; i++) {
        await Promise.all(
            Array.from({ length: 10_000 }, (_, idx) =>
                firestore
                    .collection('docs')
                    .doc()
                    .set({ foo: i * 10_000 + idx }),
            ),
        );
    }

    console.log('start counting at', new Date().toLocaleTimeString());
    let count = 0;
    const nums = [];
    // orderBy is not required to replicate issue but makes detecting duplicates a lot easier
    for await (const doc of firestore.collection('docs').orderBy('foo').stream()) {
        nums.push((doc as unknown as FirebaseFirestore.QueryDocumentSnapshot).data().foo);
        count++;
        const until = Date.now() + 2;
        while (until > Date.now()) {
            // appear busy
        }
        await new Promise(resolve => setTimeout(resolve));
    }
    console.log('done counting at', new Date().toLocaleTimeString());
    // log all numbers received from the documents to we can see the duplicates
    console.log(JSON.stringify(nums, undefined, 4));
    assert.strictEqual(count, 100_000);
})().catch(e => {
    console.log(e);
    process.exit(1);
});

The full logfile is 120MB and a bit much for a github issue attachment. Below is the interesting part where you can see the documents being fetched, the error and then some of the old documents being fetched again:

start counting at 11:36:43
Firestore (4.15.1) 2022-10-22T09:36:43.658Z hGIr6 [ClientPool.acquire]: Re-using existing client with 100 remaining operations
Firestore (4.15.1) 2022-10-22T09:36:43.658Z hGIr6 [Firestore.requestStream]: Sending request: {"parent":"projects/my-project/databases/(default)/documents","structuredQuery":{"from":[{"collectionId":"docs"}],"orderBy":[{"field":{"fieldPath":"foo"},"direction":"ASCENDING"}]}}
Firestore (4.15.1) 2022-10-22T09:36:43.725Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"0","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/OAZ5qSYpo4BV5AsCfpnv","createTime":{"seconds":"1666431351","nanos":352182000},"updateTime":{"seconds":"1666431351","nanos":352182000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:36:43.725Z hGIr6 [Firestore._initializeStream]: Releasing stream
Firestore (4.15.1) 2022-10-22T09:36:43.728Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"1","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/yHrEMsYdSn16z2PmKGXs","createTime":{"seconds":"1666431352","nanos":625035000},"updateTime":{"seconds":"1666431352","nanos":625035000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
<<snip document fetches that increment by 1>>
Firestore (4.15.1) 2022-10-22T09:39:35.951Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58830","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/qbRS5YHY1fyszPIXMmiZ","createTime":{"seconds":"1666431385","nanos":824604000},"updateTime":{"seconds":"1666431385","nanos":824604000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:39:35.951Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58831","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/6pYE69zRxRu7qdsfadHC","createTime":{"seconds":"1666431385","nanos":997470000},"updateTime":{"seconds":"1666431385","nanos":997470000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:39:35.951Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58832","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/KBWYahhOECXZLPi8H4cX","createTime":{"seconds":"1666431385","nanos":824641000},"updateTime":{"seconds":"1666431385","nanos":824641000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
<<snip document fetches that increment by 1>>
Firestore (4.15.1) 2022-10-22T09:39:36.095Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58884","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/510PozVyJPme0G9NaVgp","createTime":{"seconds":"1666431385","nanos":997601000},"updateTime":{"seconds":"1666431385","nanos":997601000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:39:36.095Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58885","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/1XTErTyO4xli2myqHoib","createTime":{"seconds":"1666431385","nanos":985602000},"updateTime":{"seconds":"1666431385","nanos":985602000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:39:36.095Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58886","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/H7BA3pQUiSiVNb0W2yyU","createTime":{"seconds":"1666431386","nanos":11813000},"updateTime":{"seconds":"1666431386","nanos":11813000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:39:36.136Z hGIr6 [Firestore._initializeStream]: Received stream error: Error: 14 UNAVAILABLE: The datastore operation timed out, or the data was temporarily unavailable.
    at Object.callErrorFromStatus (/Users/***/node_modules/@grpc/grpc-js/src/call.ts:81:24)
    at Object.onReceiveStatus (/Users/***/node_modules/@grpc/grpc-js/src/client.ts:577:32)
    at Object.onReceiveStatus (/Users/***/node_modules/@grpc/grpc-js/src/client-interceptors.ts:392:48)
    at /Users/***/node_modules/@grpc/grpc-js/src/call-stream.ts:299:24
    at processTicksAndRejections (node:internal/process/task_queues:78:11) {
  code: 14,
  details: 'The datastore operation timed out, or the data was temporarily unavailable.',
  metadata: Metadata {
    internalRepr: Map(1) { 'content-disposition' => [Array] },
    options: {}
  }
}
Firestore (4.15.1) 2022-10-22T09:39:36.136Z hGIr6 [Firestore._initializeStream]: Received stream end
Firestore (4.15.1) 2022-10-22T09:39:36.137Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58887","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/6ZtkdHXPorN2WxT39LfI","createTime":{"seconds":"1666431385","nanos":997529000},"updateTime":{"seconds":"1666431385","nanos":997529000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:39:36.137Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58888","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/IubZjcNfasAN252kahPv","createTime":{"seconds":"1666431385","nanos":410388000},"updateTime":{"seconds":"1666431385","nanos":410388000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:39:36.137Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58889","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/VuQ6weH1v7Mg8WmvJsR7","createTime":{"seconds":"1666431386","nanos":94746000},"updateTime":{"seconds":"1666431386","nanos":94746000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
<<snip document fetches that increment by 1>>
Firestore (4.15.1) 2022-10-22T09:39:36.137Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58900","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/M6W35EBBQ2NXUM7G2Y2l","createTime":{"seconds":"1666431385","nanos":682013000},"updateTime":{"seconds":"1666431385","nanos":682013000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:39:36.137Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58901","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/u1wvtsmGkSZ4b7sDzEZr","createTime":{"seconds":"1666431385","nanos":273555000},"updateTime":{"seconds":"1666431385","nanos":273555000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:39:36.137Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58902","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/dvT6jdErVuIJs3x5bx68","createTime":{"seconds":"1666431385","nanos":681961000},"updateTime":{"seconds":"1666431385","nanos":681961000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:39:36.137Z hGIr6 [Query._stream]: Query failed with retryable stream error: Error: 14 UNAVAILABLE: The datastore operation timed out, or the data was temporarily unavailable.
    at Object.callErrorFromStatus (/Users/***/node_modules/@grpc/grpc-js/src/call.ts:81:24)
    at Object.onReceiveStatus (/Users/***/node_modules/@grpc/grpc-js/src/client.ts:577:32)
    at Object.onReceiveStatus (/Users/***/node_modules/@grpc/grpc-js/src/client-interceptors.ts:392:48)
    at /Users/***/node_modules/@grpc/grpc-js/src/call-stream.ts:299:24
    at processTicksAndRejections (node:internal/process/task_queues:78:11) {
  code: 14,
  details: 'The datastore operation timed out, or the data was temporarily unavailable.',
  metadata: Metadata {
    internalRepr: Map(1) { 'content-disposition' => [Array] },
    options: {}
  }
}
Firestore (4.15.1) 2022-10-22T09:39:36.140Z hGIr6 [ClientPool.acquire]: Re-using existing client with 100 remaining operations
Firestore (4.15.1) 2022-10-22T09:39:36.140Z hGIr6 [Firestore.requestStream]: Sending request: {"parent":"projects/my-project/databases/(default)/documents","structuredQuery":{"from":[{"collectionId":"docs"}],"orderBy":[{"field":{"fieldPath":"foo"},"direction":"ASCENDING"},{"field":{"fieldPath":"__name__"},"direction":"ASCENDING"}],"startAt":{"values":[{"integerValue":58840},{"referenceValue":"projects/my-project/databases/(default)/documents/docs/HdA5T5JGI3bv07dIX3hB"}]}},"readTime":{"seconds":"1666431403","nanos":703161000}}
Firestore (4.15.1) 2022-10-22T09:39:36.477Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58841","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/9QlDGznvrnK0mflWtld7","createTime":{"seconds":"1666431386","nanos":44926000},"updateTime":{"seconds":"1666431386","nanos":44926000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:39:36.477Z hGIr6 [Firestore._initializeStream]: Releasing stream
Firestore (4.15.1) 2022-10-22T09:39:36.479Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58842","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/A3lrPufimLlSmCGlhM2J","createTime":{"seconds":"1666431385","nanos":868236000},"updateTime":{"seconds":"1666431385","nanos":868236000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:39:36.479Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58843","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/rB0gpGkdyx694ITvHZeK","createTime":{"seconds":"1666431386","nanos":1925000},"updateTime":{"seconds":"1666431386","nanos":1925000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:39:36.479Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58844","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/RqXvAQGiYojGgKiPYQ3s","createTime":{"seconds":"1666431386","nanos":23856000},"updateTime":{"seconds":"1666431386","nanos":23856000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
<<snip document fetches that increment by 1>>
Firestore (4.15.1) 2022-10-22T09:39:36.483Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58908","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/tgEr50ODWDGyJ1Q85NPg","createTime":{"seconds":"1666431385","nanos":958878000},"updateTime":{"seconds":"1666431385","nanos":958878000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:39:36.483Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58909","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/tWkTMbivyeZRSr4cCWaE","createTime":{"seconds":"1666431385","nanos":814137000},"updateTime":{"seconds":"1666431385","nanos":814137000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:39:36.483Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"58910","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/MgxnJZFIhbuKJDAsm9vW","createTime":{"seconds":"1666431385","nanos":92463000},"updateTime":{"seconds":"1666431385","nanos":92463000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
<<snip document fetches that increment by 1>>
Firestore (4.15.1) 2022-10-22T09:41:36.477Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"99997","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/m8qzAqXGFALlklyVWaJE","createTime":{"seconds":"1666431403","nanos":465775000},"updateTime":{"seconds":"1666431403","nanos":465775000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:41:36.477Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"99998","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/YuBZR39BEhC7Uxc4AYTd","createTime":{"seconds":"1666431403","nanos":88294000},"updateTime":{"seconds":"1666431403","nanos":88294000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:41:36.477Z hGIr6 [Firestore.requestStream]: Received response: {"document":{"fields":{"foo":{"integerValue":"99999","valueType":"integerValue"}},"name":"projects/my-project/databases/(default)/documents/docs/G8Ooox3mwKBoGm0uJy2k","createTime":{"seconds":"1666431402","nanos":27423000},"updateTime":{"seconds":"1666431402","nanos":27423000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1666431403","nanos":703161000},"skippedResults":0}
Firestore (4.15.1) 2022-10-22T09:41:36.477Z hGIr6 [Firestore._initializeStream]: Received stream end
done counting at 11:41:36

At the end of the script I print all the numbers we've received from the stream and you can see the stream resets back to 58841 after already having received 58855:

    58840,
    58841,
    58842,
    58843,
    58844,
    58845,
    58846,
    58847,
    58848,
    58849,
    58850,
    58851,
    58852,
    58853,
    58854,
    58855,
    58841,
    58842,
    58843,
    58844,
    58845,
    58846,
    58847,
    58848,
    58849,
    58850,
    58851,
    58852,
    58853,
    58854,
    58855,
    58856,
    58857,
    58858,
    58859,
    58860,

And the script ends with an assertion error:

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

100015 !== 100000

    at /Users/***:36:12
    at step (/Users/***:33:23)
    at Object.next (/Users/***14:53)
    at fulfilled (/Users/***:5:58) {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: 100015,
  expected: 100000,
  operator: 'strictEqual'
}

As a workaround we'll be wrapping the stream with a stream of our own to keep a sliding window of the last 16 document-id's so we can remove the duplicates.

Apologies I couldn't create a 100% reproducible example or a failing unit test. Hopefully there is enough information in this bug report for you to create a failing unit test.

Metadata

Metadata

Assignees

Labels

api: firestoreIssues related to the googleapis/nodejs-firestore API.priority: p2Moderately-important priority. Fix may not be included in next release.type: bugError or flaw in code with unintended results or allowing sub-optimal usage patterns.

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions