[Bug] Firestore reads do not work unless there was a write before

[dex3r]

[REQUIRED] Please fill in the following fields:

• Unity editor version: 2020.3.13f1
• Firebase Unity SDK version: 8.3.0 (also present on 8.1.0)
• Source you installed the SDK: .unitypackage
• Problematic Firebase Component: Firestore
• Other Firebase Components in use: Firestore
• Additional SDKs you are using: none
• Platform you are using the Unity editor on: Windows
• Platform you are targeting: Android, tested in Editor
• Scripting Runtime: Editor, scripting backend set to IL2CPP

[REQUIRED] Please describe the issue here:

On an otherwise empty scene I have one script that reads a document from Firestore. GetSnapshotAsync always, 10/10 times throws an exception FirestoreException: Failed to get document from server. UNLESS(!) before this read, I execute any write operation on the Firestore (or so it seems).

Once again, the read is ONLY successful if there is a write before it. This is really bizarre. Also, the initial write always takes a very long time, from my tests it's always 20 seconds.

The strange thing is, earlier today everything was working perfectly. I started working on another project, came back to this one, and my app just stopped working. No changes in git today. I've tried restarting Unity, PC, installed newest SDK (8.3.0). Nothing helped.

Steps to reproduce:

1. Run the following code.
2. Exit play mode.
3. Uncomment TestWrite call
4. Run the following code again.

This problem is so utterly bizarre that I wonder if this is somehow a problem with Firebase cache on my PC. How can I delete everything that Firebase/Firestore cached on my Windows machine?

I would like to see and attach more logs, however switching logging to Verbose does not seem to do anything in Editor.

Relevant Code:

public class TestScript : MonoBehaviour
{
    async void Start()
    {
        //await TestWrite(); // The following Read works ONLY if this line is not commented out
        await TestRead();
    }

    private async Task TestRead()
    {
        Debug.Log("Read starting");
        
        DocumentReference doc = FirebaseFirestore.DefaultInstance.Document("test/test");
        await doc.GetSnapshotAsync(Source.Server);

        Debug.Log("Read finished");
    }

    private async Task TestWrite()
    {
        Debug.Log("Write starting");
        
        var loginCounter = FirebaseFirestore.DefaultInstance.Document("test/test");
        var data = new Dictionary<string, object>();

        await loginCounter.SetAsync(data);
        
        Debug.Log("Write finished");
    }
}

This gives two possible results, depending if TestWrite is commented out:

With write and then read:

Read only:

[paulinon]

Hi @dex3r,

Thanks for reporting this issue. In order to be able to replicate this, could you also include the libraries you used in the code you provided?

Additionally, in the steps you provided, could you add if you've observed any changes in your data from the Firebase console?

[dex3r]

@paulinon

I've removed everything from the project, except this TestScript, Firestore 8.3.0 and Unity build-in packages. The problem still persists.

Yes, the write operation does actually alter the Firestore database state (new documents are created)

[dconeybe]

I'll take a look.

[dex3r]

I tried running the Firestore tests from this repo. E.g. the TestDocumentSnapshot failed once the initial "write" was removed. Tested on two of my Firebase projects.

[dex3r]

Furthermore, Auth and Functions works fine.

[dconeybe]

I wasn't able to reproduce.

You asked about deleting the local Firestore cache. That sounds like a good idea. You can do that by running

rd /s /q %USERPROFILE%\AppData\Local\firestore

You'll have to exit the Unity Editor first or else you'll get errors like

The process cannot access the file because it is being used by another process.

Also, you mentioned that you tried to enable logging. How did you attempt to do that? The right way would be to call

FirebaseFirestore.LogLevel = LogLevel.Debug;

before doing ANYTHING else with Firebase.

[dex3r]

Logs with verbose log level: Write+Read: https://pastebin.com/uJs5CJY8 Only Read: https://pastebin.com/10wxCEtM

[dex3r]

Deleting cache unfortunately did not make a difference :/

[dex3r]

I tried something different. In editor, the "Only read" does not work (timeouts?) on my local internet that I used for years. It does work, however, on a mobile internet.

I tried building this test for Android. It works on both mobile internet and my local WIFI (the same that do not work in Editor).

I think I don't want to be a programmer anymore, I'm going to look into goat farming now.

[dconeybe]

That observation makes some sense. The Android implementation is completely different from all other platforms so the fact that it behaves differently is not all that surprising. If you tested in on iOS, however, I'd expect the same behavior that you're seeing in the Unity Editor.

Would you be able to reproduce and re-capture the logs, but add timestamps to each of your log lines? For example, change

Debug.Log("Read starting");

to

Debug.Log(DateTime.Now.ToLongTimeString() + " Read starting");

Just a heads up that I don't think that we are going to be able to solve this issue quickly, and I will not be able to devote too much time to this issue in the coming weeks. Therefore, my recommendation is to work around the issue for now by issuing a "dummy write" in your Start() method just so that future reads work correctly.

[dconeybe]

Oh also, could you try to reproduce using the Firestore emulator?

[dex3r]

Logs with timestamps: https://pastebin.com/mv2tzdFJ Firestore emulator works fine.

Also, I realized I'm behind double NAT. This might be the issue here, however, as I said, I have this network configuration for years and everything else works fine.

[dconeybe]

@dex3r Based on the timestamps in the logs that you provided it looks like the problem is that the initial connection with the Firestore backend is taking a very long time, around 20 seconds. Since writes have a more relaxed timeout algorithm than reads do, they are better equipped to tolerate these long initial connection times. Once the connection is established then the subsequent writes and reads finish quickly. After I asked for logs with timestamps, I noticed that the screenshots in your initial comment on this issue actually included timestamps, which further support this explanation.

So when a read is the first operation and initiates the connection with the Firestore backend it times out after 10 seconds because the initial connection takes 20 seconds. But if a read is issued after the connection has been established then it finishes quickly.

My guess is that something has changed in your network configuration to cause these excessively-long initial connection times. Can you look into your network configuration to see if anything could be causing these long initial connection times?

[dex3r]

@dconeybe the strange thing is that my network configuration is relatively simple and nothing has been changed for a while now. I am the only person who has admin access to both routers and my PC but I've done nothing. I've checked when the last time the software was updated on both of them but for both it was more than 30 days. Unfortunately, I'm not able to check if it would work behind a single NAT.

I'll leave the bug-fixing db write before any read attempts are made in my app, even though I feel weird with it.

I will at some point port the app to iOS, but unfortunately It will happen not sooner than next year.

[dconeybe]

One option that I can think of to narrow down the root cause is to attempt to reproduce this bug in the C++ SDK (https://github.com/firebase/firebase-cpp-sdk) since the Unity SDK is just a C# layer on top of the C++ SDK. I could give you a quick test app to build against the C++ SDK to see if you can reproduce. If you can, then I can roll some custom builds for you with extra logging to narrow down the root cause. Is this something you'd be willing to explore? It would probably be a bunch of back-and-forth but it could point in the right direction.

[dex3r]

Yes, I'm down.

[dconeybe]

Here is the app: https://github.com/dconeybe/UnityIssue1154TestApp Let me know if you can get it working. Once you confirm, I'll roll a custom build for you with some additional logging.

[google-oss-bot]

Hey @dex3r. We need more information to resolve this issue but there hasn't been an update in 5 weekdays. I'm marking the issue as stale and if there are no new updates in the next 5 days I will close it automatically.

If you have more information that will help us get to the bottom of this, just add a comment!

[dex3r]

@dconeybe done https://pastebin.com/zrYn6x0e

[dconeybe]

Oops, the --help argument was broken. I just pushed up https://github.com/dconeybe/UnityIssue1154TestApp/commit/39bc9f34f9d430722d453a61688df03b20c18645 to fix that.

Could you pull down those changes and try it out again? In case you're not a cmake expert, you can just run cmake --build . after git pull (i.e. you don't have to cmake -S ... again).

Specifically, try this sequence of commands:

debug\firebase_unity_issue_1154_test_app.exe write
debug\firebase_unity_issue_1154_test_app.exe read
debug\firebase_unity_issue_1154_test_app.exe write read

I'm especially interested if you observe the long (20-ish second) initial connection times and if the "read" times out if not preceded by a write.

Thanks!

[dex3r]

@dconeybe https://pastebin.com/c2jqX0KL

[dconeybe]

Ok great. You're able to reproduce with that command-line app. The first operation is taking about 20 seconds.

Please now run debug\firebase_unity_issue_1154_test_app.exe write --debug so I can see the full debug logs.

In the meantime, I'll work on a custom build of the C++ SDK with some extra logging to try out. I probably won't have this ready until Monday.

[dex3r]

Here you go: https://pastebin.com/Q8VFddwH

[dconeybe]

@dex3r Sorry for the delay. I ran into some issues creating the custom build of the C++ SDK. I have one ready though that I'd like for you to try out. It doesn't have exactly the logging that I need but I'd like to ensure that these custom builds will actually work for you. I hope to have a build with the necessary logging mid next week. So no rush, but please try it out at your convenience and post the logs.

You can get the custom build from here: https://github.com/firebase/firebase-cpp-sdk/actions/runs/1395114785. Click the firebase_cpp_sdk.zip link near the bottom of the page. Then do a git clean -dffx in your checkout of https://github.com/dconeybe/UnityIssue1154TestApp and unzip that zip file into there and follow the instructions as you did with the "official" C++ SDK. Thank you for your patience and cooperation.

[dex3r]

Output of debug\firebase_unity_issue_1154_test_app.exe write --debug https://gist.github.com/dex3r/3b41dc441a90b5474223d9fb24e3d834

Feel free to ask for output from any other command if needed.

[dconeybe]

Perfect. Looks like the build worked exactly as I'd hoped. I'll get you a new build with extra logging next week.

[dconeybe]

Sorry for the long delay. We were heads down on the latest Unity SDK release. Anyways, that is past us now and I have a new build for you to test: https://github.com/firebase/firebase-cpp-sdk/actions/runs/1437861123. Could you run the app with debug\firebase_unity_issue_1154_test_app.exe write --debug and post the output at your convenience. Thank you!

[dex3r]

https://gist.github.com/dex3r/3e4e5854776669409d338726d40ea277

[dconeybe]

Here's another build: https://github.com/firebase/firebase-cpp-sdk/actions/runs/1442420763. You can omit the --debug flag this time. At this point it's just adding noise to the logs.

[dex3r]

Here you go :) https://gist.github.com/dex3r/01ec92ed8f79c50389bf93a7cfb823f4