[Question] "Out of sync" data in Firestore

[Nyankoo]

[REQUIRED] Please fill in the following fields:

• Unity editor version: 2020.3.9f1
• Firebase Unity SDK version: 7.2.0
• Source you installed the SDK: Unity Package Manager with tgz
• Problematic Firebase Component: Firestore
• Other Firebase Components in use: Auth, Crashlytics, Remote Config
• Additional SDKs you are using:
• Platform you are using the Unity editor on: Windows
• Platform you are targeting: Android
• Scripting Runtime: IL2CPP

[REQUIRED] Please describe the question here:

I stumbled about the following information when looking into Firestore's cache behavior:

These things (set(), update(), or delete()) will happen eventually, if the app comes back online and the SDK is able to sync. But if the app process dies while offline and is relaunched online, those methods of tracking the completion of the operation will no longer work.

When I understand this correctly, data saved to the cache before the app dies/stops is not automatically updated to the Firestore backend when the app launches again.

Is this correct and when yes, what would be the best way to handle the "out of sync" data only present in the cache?

[dconeybe]

Hi @Nyankoo. A quick Google search for that quote lead me to this article: https://medium.com/firebase-developers/firestore-clients-to-cache-or-not-to-cache-or-both-8f66a239c329. Is this where you copied that quote from?

Assuming it is, I believe you are asking if writes made while offline will eventually be sync'd to the backend when the app goes back online, even if interrupted by an app restart. If that is your question then the answer is "yes". Although the promise/task/callback initially attached to the write operation no longer exist after the app is restarted, the write is recorded in the local cache and will be sync'd with the backend once connectivity is restored.

Does this answer your question?

[Nyankoo]

Hi @dconeybe, thank you for the quick answer!
Yep, that's where the quote is from! Sorry about that, I forgot to add the link to the article in my post.

When attaching a listener directly on the app's startup, is this sync then reflected in querySnapshot.Metadata.HasPendingWrites when querySnapshot.Metadata.IsFromCache is true?

[dconeybe]

Yes. HasPendingWrites will change to false once the write has been written to the backend. IsFromCache may still be true if the document has not yet been read from the backend, which means there may be changes that occurred to the document by other apps/users that have not been downloaded into the local cache.

[Nyankoo]

@dconeybe Just to confirm: HasPendingWrites will change to true when the write is successfully send to the backend? Shouldn't it be false instead?

[dconeybe]

Oops, yes. Sorry. That was a typo (I've edited that comment to correct it). You are correct: HasPendingWrites will change to false once the write has been successfully written to the backend.

Note that you can also call FirebaseFirestore.WaitForPendingWritesAsync() to get a Task that completes when all writes have completed.

[Nyankoo]

@dconeybe I'm experiencing a really weird issue when testing offline-syncing. Here is simplified code to see the call order:

DisableNetworkAsync();
CollectionReference.Listen();
> IsFromCache is true
> someValue contains 1
DocumentReference.SetAsync(someValue = 2);
> someValue is now 2

> Quit app
> Remove DisableNetworkAsync();

CollectionReference.Listen();
IsFromCache is true
> someValue is still(!) 1 (looks like the backend value even when IsFromCache is true)

> Quit app
> Add DisableNetworkAsync(); back in

DisableNetworkAsync();
CollectionReference.Listen();
IsFromCache is true
> someValue is 2 (back to cached value)

This behavior is reproduceable on my end every time I add or remove DisableNetworkAsync, but our project is too big to create a sample project from it in the near future.

Maybe I'm missing something here anyway, so it would be great when you could take a look.

[dconeybe]

@Nyankoo This definitely does not sound like intended behavior.

A few questions:

1. Does this only happen on Android? Have you been able to try on iOS or in the Unity Editor?
2. Can you reproduce this in an isolated app that just does the steps you outlined? Or is it only when these steps are exercised in your large app?
3. Can you enable debug logging by setting FirebaseFirestore.LogLevel to Debug, reproduce, capture the logs, and post them?

Thank you.

[Nyankoo]

@dconeybe

1. I currently only tested this in the Unity Editor.
2. I sadly didn't had the time to create an extra app for this issue
3. You can find the editor log with FirebaseFirestore.LogLevel Debug enabled here:
   firestore.txt

You can search for "Repetitions" to see our manual log outputs to see the value change.

[dconeybe]

Hi @Nyankoo. I attempted to reproduce the behavior you're noting but did not have success. I observed the expected behavior.

Here the test script that I used. Each time I would uncomment exactly one of the "steps" and re-run the app in the Unity Editor.

using Firebase.Extensions;
using Firebase.Firestore;
using System.Collections.Generic;
using UnityEngine;

public class UnityIssue1083 : MonoBehaviour {

  void Start() {
    Firebase.FirebaseApp.CheckAndFixDependenciesAsync().ContinueWithOnMainThread(task => {
      if (task.IsFaulted) {
        Debug.LogError("zzyzx CheckAndFixDependenciesAsync() FAILED: " + task.Exception);
        return;
      }

      FirebaseFirestore db = FirebaseFirestore.DefaultInstance;
      DocumentReference doc = db.Document("UnityIssue1083-2/testdoc");

      // Uncomment exactly one of the steps below.
      //Step1(db, doc);
      //Step2(db, doc);
      //Step3(db, doc);
    });
  }

  private void Step1(FirebaseFirestore db, DocumentReference doc) {
    var data = new Dictionary<string, object> {
      {"TestKey", 4321}
    };

    Debug.Log("zzyzx Step1() SetAsync() start");
    doc.SetAsync(data).ContinueWithOnMainThread(task => {
      Debug.Log("zzyzx Step1() SetAsync() completed");
      if (task.Exception != null) {
        Debug.LogError("zzyzx Step1() SetAsync() FAILED: " + task.Exception);
      }
    });

    doc.Parent.Listen(MetadataChanges.Include, snapshot => {
      Debug.Log("zzyzx Step1() Listen callback: " + logLineFromSnapshot(snapshot));
    });
  }

  private void Step2(FirebaseFirestore db, DocumentReference doc) {
    db.DisableNetworkAsync().ContinueWithOnMainThread(task1 => {
      doc.Parent.Listen(MetadataChanges.Include, snapshot => {
        Debug.Log("zzyzx Step2() Listen callback: " + logLineFromSnapshot(snapshot));
      });

      doc.SetAsync(new Dictionary<string, object> { {"TestKey", 5555} }).ContinueWithOnMainThread(task2 => {
        Debug.LogError("zzyzx Step2() SetAsync() completed, but should never get here since the Task should not complete while offline");
        if (task2.Exception != null) {
          Debug.LogError("zzyzx Step2() SetAsync() FAILED: " + task2.Exception);
        }
      });
    });
  }

  private void Step3(FirebaseFirestore db, DocumentReference doc) {
    doc.Parent.Listen(MetadataChanges.Include, snapshot => {
      Debug.Log("zzyzx Step3() Listen callback: " + logLineFromSnapshot(snapshot));
    });
  }

  private static string logLineFromSnapshot(QuerySnapshot snapshot) {
    var message = "Count=" + snapshot.Count +
        " HasPendingWrites=" + snapshot.Metadata.HasPendingWrites +
        " IsFromCache=" + snapshot.Metadata.IsFromCache;

    if (snapshot.Count > 0) {
      message += " TestKey=" + snapshot[0].GetValue<int>("TestKey", ServerTimestampBehavior.None);
    }

    return message;
  }

}

Each time I observed the expected output, which looked like this:

zzyzx Step1() SetAsync() start
zzyzx Step1() Listen callback: Count=1 HasPendingWrites=True IsFromCache=True TestKey=4321
zzyzx Step1() Listen callback: Count=1 HasPendingWrites=True IsFromCache=False TestKey=4321
zzyzx Step1() Listen callback: Count=1 HasPendingWrites=False IsFromCache=False TestKey=4321
zzyzx Step1() SetAsync() completed

zzyzx Step2() Listen callback: Count=1 HasPendingWrites=False IsFromCache=True TestKey=4321
zzyzx Step2() Listen callback: Count=1 HasPendingWrites=True IsFromCache=True TestKey=5555

zzyzx Step3() Listen callback: Count=1 HasPendingWrites=True IsFromCache=True TestKey=5555
zzyzx Step3() Listen callback: Count=1 HasPendingWrites=True IsFromCache=False TestKey=5555
zzyzx Step3() Listen callback: Count=1 HasPendingWrites=False IsFromCache=False TestKey=5555

I'm going to comb through your logs now and see if anything looks suspicious. Can you take a look at my code here to see if it accurately captures what you're trying to do?