firebase-js-sdk icon indicating copy to clipboard operation
firebase-js-sdk copied to clipboard

FAILED_PRECONDITION error when committing transaction to clean Firestore Emulator

Open ikappaki opened this issue 3 years ago • 12 comments

[REQUIRED] Describe your environment

  • Operating System version: Windows 10
  • Browser version: Microsoft Edge 94, Firefox 95
  • Firebase SDK version: 9.6.1
  • Firebase Product: firestore

[REQUIRED] Describe the problem

I'm getting a FAILED_PRECONDITION error when submitting a simple transaction with runTransaction to the Firestone Emulator which has no data. Error message is similar to #3977.

the stored version (1641498227413898) does not match the required base version (0)

I'm calling firebase from ClojureScript via the firebase npm package.

Logs

produced with firebase.firestore.setLogLevel('debug').

[2022-01-07T21:24:52.832Z]  @firebase/firestore: Firestore (9.6.1): FirebaseAuthCredentialsProvider Auth detected
index.cjs.js:90 [2022-01-07T21:24:52.834Z]  @firebase/firestore: Firestore (9.6.1): FirestoreClient Received user= null
index.cjs.js:90 [2022-01-07T21:24:52.834Z]  @firebase/firestore: Firestore (9.6.1): FirestoreClient Using default OnlineComponentProvider
index.cjs.js:90 [2022-01-07T21:24:52.835Z]  @firebase/firestore: Firestore (9.6.1): FirestoreClient Using default OfflineComponentProvider
index.cjs.js:90 [2022-01-07T21:24:52.835Z]  @firebase/firestore: Firestore (9.6.1): FirestoreClient Initializing OfflineComponentProvider
index.cjs.js:90 [2022-01-07T21:24:52.836Z]  @firebase/firestore: Firestore (9.6.1): FirestoreClient Initializing OnlineComponentProvider
index.cjs.js:90 [2022-01-07T21:24:52.838Z]  @firebase/firestore: Firestore (9.6.1): FirebaseAppCheckTokenProvider AppCheck not yet detected
index.cjs.js:90 [2022-01-07T21:24:52.841Z]  @firebase/firestore: Firestore (9.6.1): RestConnection Sending:  http://localhost:8080/v1/projects/xxx/databases/(default)/documents:batchGet {"documents":["projects/xxx/databases/(default)/documents/:repl-words/browser"]}
index.cjs.js:90 [2022-01-07T21:24:52.849Z]  @firebase/firestore: Firestore (9.6.1): Connection XHR received: [{"missing":"projects/xxx/databases/(default)/documents/:repl-words/browser","readTime":"2022-01-07T21:24:52.845714Z"}]
index.cjs.js:90 [2022-01-07T21:24:52.849Z]  @firebase/firestore: Firestore (9.6.1): Connection RPC "BatchGetDocuments" completed.
index.cjs.js:90 [2022-01-07T21:24:52.849Z]  @firebase/firestore: Firestore (9.6.1): RestConnection Received:  [{"missing":"projects/xxx/databases/(default)/documents/:repl-words/browser","readTime":"2022-01-07T21:24:52.845714Z"}]
index.cjs.js:90 [2022-01-07T21:24:52.852Z]  @firebase/firestore: Firestore (9.6.1): RestConnection Sending:  http://localhost:8080/v1/projects/xxx/databases/(default)/documents:commit {"writes":[{"update":{"name":"projects/xxx/databases/(default)/documents/:repl-words/browser","fields":{"any":{"integerValue":"1"}}},"currentDocument":{"updateTime":"1970-01-01T00:00:00.000000000Z"}}]}
index.cjs.js:90 [2022-01-07T21:24:52.861Z]  @firebase/firestore: Firestore (9.6.1): Connection RPC "Commit" failed with status: 400 response text: {"error":{"code":400,"message":"the stored version (1641498227413898) does not match the required base version (0)","status":"FAILED_PRECONDITION"}}
index.cjs.js:90 [2022-01-07T21:24:52.862Z]  @firebase/firestore: Firestore (9.6.1): Connection RPC "Commit" completed.
index.cjs.js:90 [2022-01-07T21:24:52.862Z]  @firebase/firestore: Firestore (9.6.1): RestConnection Commit failed with error:  {"code":"failed-precondition","name":"FirebaseError"} url:  http://localhost:8080/v1/projects/xxx/databases/(default)/documents:commit request: {"writes":[{"update":{"name":"projects/xxx/databases/(default)/documents/:repl-words/browser","fields":{"any":{"integerValue":"1"}}},"currentDocument":{"updateTime":"1970-01-01T00:00:00.000000000Z"}}]}

Thanks

ikappaki avatar Jan 07 '22 22:01 ikappaki

@ikappaki I wasn't able to reproduce the error message that you mentioned. I got this expected error instead:

FirestoreError [FirebaseError]: Can't update a document that doesn't exist.

Here is the code that I used to reproduce:

import { initializeApp } from "firebase/app";
import { connectFirestoreEmulator, collection, doc, getFirestore, runTransaction } from "firebase/firestore";

const firebaseConfig = {
  // insert config data here
};
const app = initializeApp(firebaseConfig);
const firestore = getFirestore();
connectFirestoreEmulator(firestore, 'localhost', 8080);

const docRef = doc(collection(firestore, 'foo'));

runTransaction(firestore, (transaction): Promise<any> => {
  return transaction.get(docRef)
    .then((snapshot) => {
      transaction.update(docRef, {'foo': 42});
    });
});

(this code is published at https://github.com/dconeybe/FirestoreEmulatorTransactionFailedPreconditionIssue5871)

Could you provide the full code snippet that you used to reproduce? Do you notice anything different in your code than mine? I'd like to reproduce for myself to facilitate debugging.

Here is the full log:

[2022-01-08T03:46:14.658Z]  @firebase/firestore: Firestore (9.6.1): FirebaseAuthCredentialsProvider Auth not yet detected
[2022-01-08T03:46:14.660Z]  @firebase/firestore: Firestore (9.6.1): FirestoreClient Using default OnlineComponentProvider
[2022-01-08T03:46:14.660Z]  @firebase/firestore: Firestore (9.6.1): FirestoreClient Using default OfflineComponentProvider
[2022-01-08T03:46:14.661Z]  @firebase/firestore: Firestore (9.6.1): FirestoreClient Initializing OfflineComponentProvider
[2022-01-08T03:46:14.662Z]  @firebase/firestore: Firestore (9.6.1): FirestoreClient Initializing OnlineComponentProvider
[2022-01-08T03:46:14.742Z]  @firebase/firestore: Firestore (9.6.1): FirebaseAppCheckTokenProvider AppCheck not yet detected
[2022-01-08T03:46:14.745Z]  @firebase/firestore: Firestore (9.6.1): Connection RPC 'BatchGetDocuments' invoked (streaming) with request: {
  documents: [
    'projects/REDACTED/databases/(default)/documents/foo/5GGlNzbp5GBk7WmNtDq2'
  ]
}
[2022-01-08T03:46:14.745Z]  @firebase/firestore: Firestore (9.6.1): Connection Creating Firestore stub.
[2022-01-08T03:46:14.793Z]  @firebase/firestore: Firestore (9.6.1): Connection RPC BatchGetDocuments received result: {
  transaction: <Buffer >,
  readTime: { seconds: '1641613574', nanos: 781838000 },
  missing: 'projects/REDACTED/databases/(default)/documents/foo/5GGlNzbp5GBk7WmNtDq2'
}
[2022-01-08T03:46:14.795Z]  @firebase/firestore: Firestore (9.6.1): Connection RPC 'BatchGetDocuments' completed.
node_modules/@firebase/firestore/src/core/transaction.ts:176
        throw new FirestoreError(
              ^
FirestoreError [FirebaseError]: Can't update a document that doesn't exist.
    at Transaction$2.preconditionForUpdate (node_modules/@firebase/firestore/src/core/transaction.ts:176:15)
    at Transaction$2.update (node_modules/@firebase/firestore/src/core/transaction.ts:84:44)
    at Transaction.update (node_modules/@firebase/firestore/src/lite-api/transaction.ts:229:23)
    at index.ts:37:19
    at processTicksAndRejections (node:internal/process/task_queues:96:5) {
  code: 'invalid-argument',
  toString: [Function (anonymous)]
}

dconeybe avatar Jan 08 '22 03:01 dconeybe

Hi @dconeybe,

Thanks for looking into this. I am using the Web API in from a browser in ClojureScript to invoke the transaction, thus the calls to the emulators seem to me that are performed via REST not RPC (I'm inferring this from the logs).

It will take me some time to figure out how to extract the minimal possible reproducible JS code from the ClojureScript compiler output.

Would you be able to perhaps provide me with a minimal setup similar to https://github.com/dconeybe/FirestoreEmulatorTransactionFailedPreconditionIssue5871 but using Web API REST calls that can be invoked from a browser instead of utilising RPC? Not sure where to start if I go down this path by myself, perhaps I should look into the firestore quickstart-js for inspiration.

If I modify your example to match my code it looks like the below and it does work fine when invoked from node.js:

import { initializeApp } from "firebase/app";
import { connectFirestoreEmulator, collection, doc, getFirestore, runTransaction, setLogLevel } from "firebase/firestore";

const firebaseConfig = {
// config
};

const app = initializeApp(firebaseConfig);
setLogLevel('debug');
const firestore = getFirestore();
connectFirestoreEmulator(firestore, 'localhost', 8080);

const docRef = doc(firestore, 'repl-words', 'foo');

runTransaction(firestore, (transaction): Promise<any> => {
  return transaction.get(docRef)
    .then((snapshot) => {

      transaction.set(docRef, {'foo': 42});
    });
});

log

$ npx ts-node index.ts
npx: installed 14 in 2.121s
[2022-01-08T10:05:20.363Z]  @firebase/firestore: Firestore (9.6.1): FirebaseAuthCredentialsProvider Auth not yet detected
[2022-01-08T10:05:20.363Z]  @firebase/firestore: Firestore (9.6.1): FirestoreClient Using default OnlineComponentProvider
[2022-01-08T10:05:20.363Z]  @firebase/firestore: Firestore (9.6.1): FirestoreClient Using default OfflineComponentProvider
[2022-01-08T10:05:20.363Z]  @firebase/firestore: Firestore (9.6.1): FirestoreClient Initializing OfflineComponentProvider
[2022-01-08T10:05:20.364Z]  @firebase/firestore: Firestore (9.6.1): FirestoreClient Initializing OnlineComponentProvider
[2022-01-08T10:05:20.442Z]  @firebase/firestore: Firestore (9.6.1): FirebaseAppCheckTokenProvider AppCheck not yet detected
[2022-01-08T10:05:20.445Z]  @firebase/firestore: Firestore (9.6.1): Connection RPC 'BatchGetDocuments' invoked (streaming) with request: {
  documents: [
    'projects/xxx/databases/(default)/documents/repl-words/foo'
  ]
}
[2022-01-08T10:05:20.445Z]  @firebase/firestore: Firestore (9.6.1): Connection Creating Firestore stub.
[2022-01-08T10:05:20.479Z]  @firebase/firestore: Firestore (9.6.1): Connection RPC BatchGetDocuments received result: {
  transaction: <Buffer >,
  readTime: { seconds: '1641636320', nanos: 473860000 },
  missing: 'projects/xxx/databases/(default)/documents/repl-words/foo'
}
[2022-01-08T10:05:20.480Z]  @firebase/firestore: Firestore (9.6.1): Connection RPC 'BatchGetDocuments' completed.
[2022-01-08T10:05:20.482Z]  @firebase/firestore: Firestore (9.6.1): Connection RPC 'Commit' invoked with request: {
  writes: [
    {
      update: {
        name: 'projects/xxx/databases/(default)/documents/repl-words/foo',
        fields: { foo: { integerValue: '42' } }
      },
      currentDocument: { updateTime: { seconds: '0', nanos: 0 } }
    }
  ]
}
[2022-01-08T10:05:20.491Z]  @firebase/firestore: Firestore (9.6.1): Connection RPC 'Commit' completed with response: {
  writeResults: [
    {
      transformResults: [],
      updateTime: { seconds: '1641636320', nanos: 488859000 }
    }
  ],
  commitTime: { seconds: '1641636320', nanos: 488859000 }
}

Thanks!

ikappaki avatar Jan 08 '22 10:01 ikappaki

Good news, I've managed to reproduce it with your example, it is the mere presence of firebase/auth that is causing the issue

import { initializeApp } from "firebase/app";
import "firebase/auth";
import { connectFirestoreEmulator, collection, doc, getFirestore, runTransaction, setLogLevel } from "firebase/firestore";

const firebaseConfig = {
// ...
};

const app = initializeApp(firebaseConfig);
setLogLevel('debug');
const firestore = getFirestore();
connectFirestoreEmulator(firestore, 'localhost', 8080);

const docRef = doc(firestore, 'repl-words', 'foo');

runTransaction(firestore, (transaction): Promise<any> => {
  return transaction.get(docRef)
    .then((snapshot) => {

      transaction.set(docRef, {'foo': 42});
    });
});

log

$ npx ts-node index.ts
npx: installed 14 in 1.463s
[2022-01-08T11:57:22.261Z]  @firebase/firestore: Firestore (9.6.1): FirebaseAuthCredentialsProvider Auth not yet detected
[2022-01-08T11:57:22.261Z]  @firebase/firestore: Firestore (9.6.1): FirestoreClient Using default OnlineComponentProvider
[2022-01-08T11:57:22.261Z]  @firebase/firestore: Firestore (9.6.1): FirestoreClient Using default OfflineComponentProvider
[2022-01-08T11:57:22.262Z]  @firebase/firestore: Firestore (9.6.1): FirestoreClient Initializing OfflineComponentProvider
[2022-01-08T11:57:22.264Z]  @firebase/firestore: Firestore (9.6.1): FirestoreClient Initializing OnlineComponentProvider
[2022-01-08T11:57:22.332Z]  @firebase/firestore: Firestore (9.6.1): FirebaseAppCheckTokenProvider AppCheck not yet detected
[2022-01-08T11:57:22.348Z]  @firebase/firestore: Firestore (9.6.1): Connection RPC 'BatchGetDocuments' invoked (streaming) with request: {
  documents: [
    'projects/xxx/databases/(default)/documents/repl-words/foo'
  ]
}
[2022-01-08T11:57:22.348Z]  @firebase/firestore: Firestore (9.6.1): Connection Creating Firestore stub.
[2022-01-08T11:57:22.371Z]  @firebase/firestore: Firestore (9.6.1): Connection RPC BatchGetDocuments received result: {
  transaction: <Buffer >,
  readTime: { seconds: '1641643042', nanos: 365638000 },
  missing: 'projects/xxx/databases/(default)/documents/repl-words/foo'
}
[2022-01-08T11:57:22.372Z]  @firebase/firestore: Firestore (9.6.1): Connection RPC 'BatchGetDocuments' completed.
[2022-01-08T11:57:22.374Z]  @firebase/firestore: Firestore (9.6.1): Connection RPC 'Commit' invoked with request: {
  writes: [
    {
      update: {
        name: 'projects/xxx/databases/(default)/documents/repl-words/foo',
        fields: { foo: { integerValue: '42' } }
      },
      currentDocument: { updateTime: { seconds: '0', nanos: 0 } }
    }
  ]
}
[2022-01-08T11:57:22.397Z]  @firebase/firestore: Firestore (9.6.1): Connection RPC 'Commit' failed with error: Error: 9 FAILED_PRECONDITION: the stored version (1641636454958701) does not match the required base version (0)
    at Object.callErrorFromStatus (d:\clj\issues\FirestoreEmulatorTransactionFailedPreconditionIssue5871\node_modules\@grpc\grpc-js\src\call.ts:81:24)
    at Object.onReceiveStatus (d:\clj\issues\FirestoreEmulatorTransactionFailedPreconditionIssue5871\node_modules\@grpc\grpc-js\src\client.ts:343:36)
    at Object.onReceiveStatus (d:\clj\issues\FirestoreEmulatorTransactionFailedPreconditionIssue5871\node_modules\@grpc\grpc-js\src\client-interceptors.ts:462:34)
    at Object.onReceiveStatus (d:\clj\issues\FirestoreEmulatorTransactionFailedPreconditionIssue5871\node_modules\@grpc\grpc-js\src\client-interceptors.ts:424:48)
    at d:\clj\issues\FirestoreEmulatorTransactionFailedPreconditionIssue5871\node_modules\@grpc\grpc-js\src\call-stream.ts:323:24
    at processTicksAndRejections (internal/process/task_queues.js:79:11) {
  code: 9,
  details: 'the stored version (1641636454958701) does not match the required base version (0)',
  metadata: Metadata {
    internalRepr: Map { 'content-type' => [ 'application/grpc' ] },
    options: {}
  }
}

thanks

ikappaki avatar Jan 08 '22 12:01 ikappaki

@ikappaki I still cannot reproduce the "the stored version (1641636454958701) does not match the required base version (0)" error, even when I add the import for firebase/auth.

What sort of authentication do you have set up in the Firestore emulator? What security rules have you configured?

dconeybe avatar Jan 10 '22 16:01 dconeybe

Hi @dconeybe, indeed it does not occur the first time the db is brought up, the db has to be cleared first.

could you please try the following

  1. bring up the emulators.
  2. run the code snippet I posted last, some data will be created in the emulated firestore.
  3. hit the clear all data button in the firestore emulator to clear the store.
  4. rerun the snippet, it should error out.

I don't have any authentication or security rules setup. It is as plain as it can get.

Thanks

ikappaki avatar Jan 10 '22 17:01 ikappaki

Ahh okay NOW I can reproduce. Let me dig into this a bit.

dconeybe avatar Jan 10 '22 18:01 dconeybe

I'm assigning this to @yuchenshi who has expertise in the Firestore emulator.

Here are the results of my investigation:

Here is the problematic code (hereafter referred to as index.ts):

import { initializeApp } from "firebase/app";
import { connectFirestoreEmulator, collection, doc, getFirestore, runTransaction, setLogLevel } from "firebase/firestore";

const firebaseConfig = {
  // INSERT CONFIG HERE
};

const app = initializeApp(firebaseConfig);
setLogLevel('debug');
const firestore = getFirestore();
connectFirestoreEmulator(firestore, 'localhost', 8080);

const docRef = doc(firestore, 'repl-words', 'foo');

runTransaction(firestore, (transaction): Promise<any> => {
  return transaction.get(docRef)
    .then((snapshot) => {
      transaction.set(docRef, {'foo': 42});
    });
});

Prerequisites

  1. npm install -g typescript ts-node

Steps

  1. firebase emulators:start --only firestore --project YOUR_FIREBASE_PROJECT_ID
  2. ts-node index.ts
  3. CLick "Clear all data" in the Firestore Emulator Web UI (e.g. http://localhost:4000/firestore/data/).
  4. ts-node index.ts again

Expected Results

Both times that the index.ts script is run complete successfully.

Actual Results:

The first time that the index.ts script is run completes successfully (as expected); however, the second time that it is run fails with this error:

@firebase/firestore: Firestore (9.6.1): Connection RPC 'Commit' failed with error: Error: 9 FAILED_PRECONDITION: the stored version (1641841011407934) does not match the required base version (0)

Minimal app to reproduce: https://github.com/dconeybe/FirestoreEmulatorTransactionFailedPreconditionIssue5871

dconeybe avatar Jan 10 '22 19:01 dconeybe

Let me try to explain why this happens.

clearData is nothing more than a commit that deletes all database data.

From the repro steps:

  1. firebase emulators:start --only firestore --project YOUR_FIREBASE_PROJECT_ID
  2. ts-node index.ts Some entity is written.
  3. CLick "Clear all data" in the Firestore Emulator Web UI (e.g. http://localhost:4000/firestore/data/). All entities is cleared with a non-zero delete timestamp.
  4. ts-node index.ts again It tries to update the document with a precondition of currentDocument: { updateTime: { seconds: '0', nanos: 0 } }, but since the document was deleted at a non-zero timestamp the precondition failed.

It would say this is an SDK bug, we should change SDK to use currentDocument: { exists: false} instead of the updateTime. BatchGetDocument don't return the last mutated timestamp, so a precondition of updateTime can be wrong.

I would guess that prod database would behave similarly. (clearData is just deleting all entities)

Can we route this to the admin SDK them?

fredzqm avatar Jan 31 '22 22:01 fredzqm

@schmidt-sebastian would you mind looking at this?

yuchenshi avatar Jan 31 '22 22:01 yuchenshi

Assigning to current on-call. We should be sending a precondition of {exists: false}.

schmidt-sebastian avatar Feb 01 '22 16:02 schmidt-sebastian

Any update for this? The precondition failed is causing my automated tests to error out when using clearFirestore() method before every test. I assume that is the same as the clear all data button.

bruxr avatar Apr 29 '22 19:04 bruxr

This same scenario is a problem when using firebase firestore:delete --project {project-name} --all-collections -f

dpsthree avatar Jul 31 '22 22:07 dpsthree

Hi @ehsannas, @dconeybe, @schmidt-sebastian and @yuchenshi.

apologies for the wide distribution, but not sure who is supposed to be looking at this.

It has been more than a year since this issue was reported and it appears there is an easy fix to apply. As mentioned by other users, the bug is still out there at large.

Could someone please apply the suggested fix so as to close this issue?

Thanks

ikappaki avatar Aug 21 '22 19:08 ikappaki

I'll get a fix out by the end of the week.

dconeybe avatar Aug 22 '22 16:08 dconeybe

The fix has been merged: https://github.com/firebase/firebase-js-sdk/pull/6550. It should be included in the next release. I'll reply back here once the release is out.

I'm also going to make sure the fix is ported to Android and iOS, but I have no ETA for those fixes.

dconeybe avatar Aug 26 '22 01:08 dconeybe

FYI The fix has been released in Firebase JS SDK version 9.9.4 (released Sept 01, 2022): https://firebase.google.com/support/release-notes/js#version_994_-_september_1_2022

dconeybe avatar Oct 03 '22 15:10 dconeybe