Firebase-tools: FIRESTORE (5.8.0) INTERNAL ASSERTION FAILED: Unknown FieldValue on calling firebase.firestore.FieldValue.serverTimestamp() Ask Question

[flfk]

[REQUIRED] Environment info

firebase-tools: 6.3.1
firebase SDK: 5.8.2

Platform: ReactJS web app using create-react-app, redux and firestore

[REQUIRED] Test case

There is no complete example I can show you to reproduce that, it seems to be an internal library error and we just need to know why this is happening. Just knowing the reason this error is raised could help us find the problem.

[REQUIRED] Steps to reproduce

I'm not sure what is producing this error, it seems to occur randomly. Sometimes it works, sometimes it doesn't. Roughly once in every 20 function calls the error fires. Below is the function where the serverTimestamp is called.

export const sendMsg = msg => async dispatch => {
  await db
    .collection('messages')
    .add({ ...msg, timestamp: firebase.firestore.FieldValue.serverTimestamp() });
};

[REQUIRED] Expected behavior

Firestore document added with server timestamp.

[REQUIRED] Actual behavior

Firestore document not added. Console error as below.

index.cjs.js:175 Uncaught Error: FIRESTORE (5.8.0) INTERNAL ASSERTION FAILED: 
    AsyncQueue is already failed: Error: FIRESTORE (5.8.0) INTERNAL ASSERTION FAILED: Unknown FieldValue {"localWriteTime":{"seconds":1548602883,"nanoseconds":762000000},"previousValue":null,"typeOrder":3}
    at fail (index.cjs.js:175) at JsonProtoSerializer.toValue (index.cjs.js:6976) at index.cjs.js:7726 at Array.map () 
    at JsonProtoSerializer.toCursor (index.cjs.js:7725) 
    at JsonProtoSerializer.toQueryTarget (index.cjs.js:7558) 
    at JsonProtoSerializer.toTarget (index.cjs.js:7650) 
    at PersistentListenStream.watch (index.cjs.js:16906) 
    at RemoteStore.sendWatchRequest (index.cjs.js:17859) 
    at RemoteStore.listen (index.cjs.js:17814) at SyncEngine. (index.cjs.js:19354) 
    at step (tslib.es6.js:197) 
    at Object.next (tslib.es6.js:127) 
    at fulfilled (tslib.es6.js:80) 
    at fail (index.cjs.js:175) 
    at AsyncQueue.verifyNotFailed (index.cjs.js:8735) 
    at AsyncQueue.enqueue (index.cjs.js:8682) 
    at AsyncQueue.enqueueAndForget (index.cjs.js:8671) 
    at index.cjs.js:16850 
    at StreamBridge.wrappedOnMessage (index.cjs.js:16801) 
    at StreamBridge.callOnMessage (index.cjs.js:7992) 
    at index.cjs.js:8267 
    at W. (index.cjs.js:8210) 
    at W.push../node_modules/@firebase/webchannel-wrapper/dist/index.esm.js.e.Lb (index.esm.js:860) 
    at W.push../node_modules/@firebase/webchannel-wrapper/dist/index.esm.js.e.dispatchEvent (index.esm.js:815) 
    at X.push../node_modules/@firebase/webchannel-wrapper/dist/index.esm.js.X.ud (index.esm.js:3682) 
    at $c.push../node_modules/@firebase/webchannel-wrapper/dist/index.esm.js.e.dg (index.esm.js:3431) at $c.push../node_modules/@firebase/webchannel-wrapper/dist/index.esm.js.e.ue (index.esm.js:3320) 
    at R.push../node_modules/@firebase/webchannel-wrapper/dist/index.esm.js.e.Yc (index.esm.js:1875) 
    at R.push../node_modules/@firebase/webchannel-wrapper/dist/index.esm.js.e.Fd (index.esm.js:1771) 
    at R.push../node_modules/@firebase/webchannel-wrapper/dist/index.esm.js.e.hg (index.esm.js:1733) 
    at R.push../node_modules/@firebase/webchannel-wrapper/dist/index.esm.js.e.Me (index.esm.js:1690) 
    at R.push../node_modules/@firebase/webchannel-wrapper/dist/index.esm.js.e.mg (index.esm.js:1685) 
    at V.push../node_modules/@firebase/webchannel-wrapper/dist/index.esm.js.e.Lb (index.esm.js:860) 
    at V.push../node_modules/@firebase/webchannel-wrapper/dist/index.esm.js.e.dispatchEvent (index.esm.js:815) 
    at V.push../node_modules/@firebase/webchannel-wrapper/dist/index.esm.js.e.se (index.esm.js:2840) at V.push../node_modules/@firebase/webchannel-wrapper/dist/index.esm.js.e.eg (index.esm.js:2836) 
    at V.push../node_modules/@firebase/webchannel-wrapper/dist/index.esm.js.e.te (index.esm.js:2832)

[ryanpbrewster]

Thanks for filing this issue. I'm going to try to reproduce this on my end and determine the root cause.

[flfk]

Hi @ryanpbrewster I was finally able to reproduce this error using create-react-app.

It seems as though the bug occurs when attempting to add firestore document listeners with a query cursor that had a pending serverTimestamp value.

This happened when the query cursor was set using an existing document listener listening for the "added" change type. Given this change type is invoked when a new document was added locally, the query cursor was still pending a server timestamp.

As a workaround I updated the query cursor only on "modified" change types given this would only be invoked when the server timestamp was created.

Below is the code I used to reproduce the error in a new create-react-app App.js file

// App.js

import React, { Component } from "react";

import firebase from "firebase/app";
import "firebase/firestore";

const config = {
  apiKey: "YOUR_API_KEY",
  authDomain: "YOUR_AUTH_DOMAIN",
  databaseURL: "YOUR_DATABASE_URL",
  projectId: "YOUR_PROJECT_ID",
  storageBucket: "YOUR_STORAGE_BUCKET",
  messagingSenderId: "YOUR_MESSAGING_SENDER_ID"
};

firebase.initializeApp(config);

class App extends Component {
  state = {
    lastVisibleDoc: null
  };

  addDoc = async () => {
    await firebase
      .firestore()
      .collection("COLLECTION")
      .add({
        timestamp: firebase.firestore.FieldValue.serverTimestamp()
      });
  };

  addDocsListener = async () => {
    const { lastVisibleDoc } = this.state;
    console.log("calling addDocsListener, lastVisibleDoc is", lastVisibleDoc);
    const ref = firebase
      .firestore()
      .collection("COLLECTION")
      .orderBy("timestamp", "desc");
    const queryRef = !lastVisibleDoc
      ? ref.limit(1)
      : ref.startAfter(lastVisibleDoc).limit(1);
    await queryRef.onSnapshot(snap => {
      snap.docChanges().forEach(change => {
        if (change.type === "added") {
          const { doc } = change;
          console.log(
            "snapshot docChange of type added called, new lastVisibleDoc data",
            doc.data()
          );
          this.setState({ lastVisibleDoc: doc });
        }
        if (change.type === "modified") {
          const { doc } = change;
          console.log(
            "snapshot docChange of type modified called, serverTimestamp received for doc",
            doc.data()
          );
        }
      });
    });
  };

  render() {
    return (
      <div>
        <button onClick={this.addDocsListener}>
          1. First click to add docs listener
        </button>
        <br />
        <button onClick={this.addDoc}>
          2. Then click To add doc with Server Timestamp
        </button>
        <br />
        <button onClick={this.addDocsListener}>
          3. Now click to add another DocsListener using added doc
        </button>
      </div>
    );
  }
}

export default App;

[ryanpbrewster]

Awesome, thanks for the detailed repro. Can you trigger this behavior against the production Firestore service, or is it only against the emulator?

EDIT: From your repro, it actually looks like this is currently happening against the production service. Adding @mikelehen to triage.

[wilhuff]

As you've observed, trying to use a pending server timestamp as a constraint or ordering on a query doesn't work. Unfortunately, the bug here is really that we're giving you a poor error message about this.

We saw this in the Android SDK https://github.com/firebase/firebase-android-sdk/issues/106 and added an error message fix in https://github.com/firebase/firebase-android-sdk/pull/138. It appears that in the juggle around the holidays we didn't port that fix to the javascript SDK. Sorry about that.

Note that may not want to wait for modified change types, since this is racy. It should be vanishingly rare but if the server timestamp happens to get fixated before your listener starts then you wouldn't see a modified event. Instead of using the last visible document to indirectly specify the bound to startAfter, use the last timestamp you have, and only update that when any new document contains a timestamp. This way you'll be able to page through older data as well that has already fixated timestamps.

See here for some more background on what's going on: https://groups.google.com/d/msg/google-cloud-firestore-discuss/ffcnv-P1C5c/JPrM68QfCgAJ.

[rsgowman]

The port of the "fix" to the js sdk has now landed here: https://github.com/firebase/firebase-js-sdk/pull/1529. It should go out in our next release. (As a reminder, the "fix" only fixes the error message.)

[tmk1991]

Still observed in 5.8.1

[rsgowman]

@tmk1991 5.8.1 was released on 2019-01-24 (which was before this was fixed.) Could you upgrade to the latest (5.8.5) and try again?

[tmk1991]

Sorry about that - i will give it a try. My temp workaround has been to save with a new Date() object on the field that I also sort on for cursors. Will upgrade soon.

[tmk1991]

Tried. No luck. Getting the following:
ERROR FirebaseError: Invalid query. You are trying to start or end a query using a document for which the field "createdAt" is an uncommitted server timestamp. (Since the value of this field is unknown, you cannot start/end a query with it.)

[rsgowman]

Ah. Yes that error's expected. Basically, if you create a document that contains a field set to FieldValue.serverTimestamp(), then the value of that field is effectively unknown until the document has been written to the server. (We can't just assume "now", since the end user's clock might not be accurate.) So attempting to start/end a query based on a field in this state can't work, since we don't know its value.

(The "fix" in https://github.com/firebase/firebase-js-sdk/pull/1529 was to make the error message more explicit rather than somehow make this work.)

There's a couple workarounds you could employ. One, as you noted, would be to use a local date object rather than a serverTimestamp. (But keep in mind that the local clock could be incorrect.) A similar approach would be to create a new query and call https://firebase.google.com/docs/reference/js/firebase.firestore.Query#where, specifying your 'startedAt' field and the (possibly incorrect) local time. i.e. You wouldn't use your newly created document at all. (However, this has the awkwardness of your query possibly not returning your newly created document... Particularly if the local clock is slightly ahead of the "real" time.) A third option might be to wait for the document to be written to the server before starting your query. This would be the most accurate approach, but has the disadvantage of needing to wait for a network round trip before starting your query. (And obviously it won't work at all if you're offline.)

Of course, there's no reason you can't combine multiple approaches. i.e. possibly an initial query (which may be slightly wrong if the local clock is wrong) followed by approach three once your write settles.

[tmk1991]

Awesome and thorough explanation!