Firestore .get .(addOnCompleteListener) not receiveing response in firestore sdk 21.4.3 or newer

[markic22]

• Android Studio version: 4.1.1
• Firebase Component: Firestore
• Component version: 21.4.3 or higher

[REQUIRED] Step 3: Describe the problem

Steps to reproduce:

I'm having issue with firestore Android sdk. We were using firestore sdk 22.0.0 but we found an issue with our application, that in some cases, data wouldn't load successfully. After investigation, we figured out that the issue was happening when user had closed application and when there was big number of changes happening, first try to load the data was not successful. If you closed and opened application again (called .addOnCompleteListener again) the data was loaded ok, so the issue is only when you call listener for the first time since there were a lot of changes made to the documents. The strange thing is that in this .get() none of the listeners got a response (neither addOnCompleteListener, addOnFailureListener or addOnCanceledListener). I tried to wait for hours (8 documents in this collection collection, but in other collections there were hundreds of changes if not thousands).

private fun getAssignmentConsumptions() { Log.d("firestoreService", "firestoreService: getAssignmentConsumptions, started") getFacilityDocumentRef(facilityId).collection(AssignmentConsumption.COLLECTION).get().addOnCompleteListener { snapshots -> assignmentConsumptionsList = snapshots.result?.documents?.toModels<AssignmentConsumption>()?.toMutableList() ?: mutableListOf() Log.d("firestoreService", "firestoreService: getAssignmentConsumptions, done") assignmentConsumptionsListBehaviourRelay.accept(assignmentConsumptionsList.toList()) }.addOnFailureListener { Log.d("firestoreService", "firestoreService: getAssignmentConsumptions, onFailure") }.addOnCanceledListener { Log.d("firestoreService", "firestoreService: getAssignmentConsumptions, onCanceled") } }

Then I tried to use firestore 19.0.0 version. And it worked as it should. Then I decided that I would figure out when was this "issue" introduced into firestore project. The last version that works OK for us is the 21.4.2 version, anything above this version, this .get() call gets 0 response.

In documentation for version 21.4.3 it says this:

Cloud Firestore version 21.4.3 Cloud Firestore now limits the number of concurrent document lookups it will perform when resolving inconsistencies in the local cache.

As we can see there were some changes done for local cache, but it seems that this broke loading/resolving local data with new changes, where we don't get response about what is happening.

I cannot make a sample where this is reproduceable , but in our case it's reproduceable 100% of the time. To reproduce this, we delete all collections and documents of this data set and populate it with the same again (our backend does this). First loading is not successful, the second one is. And this issue only occurs from version 21.4.2 onwards.

[google-oss-bot]

I found a few problems with this issue:

• I couldn't figure out how to label this issue, so I've labeled it for a human to triage. Hang tight.
• This issue does not seem to follow the issue template. Make sure you provide all the required information.

[dconeybe]

Hi @markic22. I'm sorry that this issue is affecting you. Thank you for the detailed bug report. I'm not sure what's happening but it does sound like something is not right.

The update in 21.4.3 that you've referred to ("Cloud Firestore now limits the number of concurrent document lookups it will perform when resolving inconsistencies in the local cache") is #1374. Your mentions that "there was big number of changes happening" and "we delete all collections and documents of this data set and populate it with the same again (our backend does this)" seem to suggest that this could indeed be related to the feature added in that PR.

Could you reproduce the issue with logging enabled and post the logs? The logs could prove to be very helpful if I am unable to reproduce the issue. To enable logging, call FirebaseFirestore.setLoggingEnabled(true).

In the meantime, I'll see if I can reproduce the issue.

[dconeybe]

Oh, and I'd like to confirm: When you say "not successful" do you mean that the listeners specified to get() never get called? Or do you mean that they do get called, but with incorrect data?

[markic22]

Hi @dconeybe , thanks for your time and quick response.

Oh, and I'd like to confirm: When you say "not successful" do you mean that the listeners specified to get() never get called? Or do you mean that they do get called, but with incorrect data?

.get() gets called, but neither of listeners gets any response (neither addOnCompleteListener, addOnFailureListener or addOnCanceledListenel receives any feedback).

Ok, i uploaded couple of scenarios for you, with logging enabled.

First load with 22.0.0 version:
first time loading firestore 22.0.0.txt

Load after changes with 22.0.o version: (it doesn't load):
loading application after changes firestore 22.0.0.txt

And now the same with the last working version 21.4.2
first time loading firestore 21.4.2.txt
loading application after changes firestore 21.4.2.txt

And the issue is with only one of the collection (assignment_consumptions). Only this listener "gets stuck". Really appriciate the time and help.

tip: you can use "firestoreService" string to search if listeners got a response or not.

[markic22]

@dconeybe Did you have any breaktrough? This is a big issue for us, since we cannot user newer version of firestore in our live app. Is there anything I can do? Anybody else I can contact regarding this? Please let me know.

[dconeybe]

Hi @markic22. My apologies for the delay in my reply. I realize that this is a frustrating issue for you and as of yesterday my time has freed up to invest more time in the investigation. I spent some time setting up a reproduction app yesterday and I am going to continue today. I have not had any breakthroughs and the logs did not, unfortunately, point to anything obvious. Thank you for your patience. This could be a tricky one to get to the bottom of but I'll keep you posted with updates.

[dconeybe]

@markic22 Reading the logs has not pointed to an obvious problem; however, I do see that there are 10 documents in the assignment_consumptions collection that go into limbo but seem to never get resolved, which is suspicious. I also was unable to reproduce the issue with my own test app.

I do, however, have a few hypotheses that I'd like to test out. If I were to provide you with a custom Firestore SDK build and instructions for modifying your app to use it, would you be willing to reproduce the issue with that custom build? Basically, I want to add some additional logging to try and figure out what's going on. We would probably need to do 5 or 6 iterations of this as the log output sends the investigation in different directions.

[markic22]

@dconeybe I'm willing to try anything, i'm trying to find what exactly causes the issue for about 2 weeks now and trying to reproduce in demo app for you, but no success. It seems to be specific situation. If you would agree, we could even have "Live" session, where I would share my screen and detail and show our issue to you exactly.

[dconeybe]

Are you, by any chance, able to share your entire app with me so that I can reproduce (as opposed to an isolated demo app)? Me being able to set breakpoints and debug locally would dramatically speed up this investigation. But I totally understand if that's not feasible, in which case we can go down this debugging-via-logging method.

[dconeybe]

Ok I have a build for you to try. I've included instructions for you to build it by yourself since that will be the easiest way for us to iterate on this. Also, I'd personally be wary about executing opaque binary artifacts that someone sent me on GitHub, so I don't want to do that to you either :)

Anyways, here are the steps:

1. git clone https://github.com/firebase/firebase-android-sdk.git
2. cd firebase-android-sdk
3. git checkout dconeybe/Issue2311Debug
4. ./gradlew :firebase-firestore:publishToMavenLocal
5. Verify that ~/.m2/repository/com/google/firebase/firebase-firestore/22.0.2-SNAPSHOT was created.
6. Add mavenLocal() to the root directory’s build.gradle file inside repositories{}. This tells gradle to resolve dependencies with local versions by looking in the ~/.m2/repository directory first:

repositories {
  jcenter()
  mavenLocal()
  google()
}

7. In your app’s build.gradle file (NOTE: not the one in the root directory) inside dependencies{}, point to the firestore snapshot you created earlier by replacing the existing implementation with: implementation 'com.google.firebase:firebase-firestore:22.0.2-SNAPSHOT'

With these changes, please rebuild your app, reproduce the bug, and post the logs in a GitHub Gist. I'm specifically interested in the log lines with "zzyzx" as their tag, so feel free to filter out the rest.

[markic22]

@dconeybe I tried to build snapshot, but I got some issues. First it was ndk issue, which I resolved with using older version (newest doesn't have platform folder). But now I'm stuck.

`* What went wrong:
A problem occurred evaluating project ':firebase-crashlytics'.

Illegal character in authority at index 7: file://C:\Users\marko\Documents\Projects\firebase-android-sdk\firebase-c
rashlytics/third_party_licenses/tape/LICENSE
`

i tried to comment those licence files in projects, but in the end, the same error comes for build/m2repository... something like that. I'm still trying to solve this issue with illegal character, but if you have any idea how I could fix this, it would be great help.

[dconeybe]

Hmmm I'm not familiar with that error. It could be a Windows specific thing. Let me try to reproduce on my end. I use Mac and Linux but not typically Windows so it's possible that I've been fortunate enough to simply not run into this issue.

[dconeybe]

Ok. I've pushed 017ca0d to the branch to work around the "Illegal character in authority at index 7" build error. Please do a git pull from the branch to get the fix.

Sorry this took so long to reply. I spent a good part of my day getting my Windows machine set up for building!

Also, which version of the NDK did you install to work around the missing "platforms" directory issue? I have 28.0.3 and 30.0.3 (according to Android Studio) and I'm still seeing the issue.

[markic22]

For licenses there is no more issues now, but there is still one in generated file I'm guessing:

Illegal character in authority at index 7: file://C:\Users\marko\Documents\Projects\firebase-android-sdk\build/m2repo sitory

Regarding issue with NDK, the numbers you are talking about sounds like SDK build tools version, not NDK numbers :

and then just write the path in local.properties to specify version

and thene it should look like this if you go into project structure

Thanks for help :)

[dconeybe]

Thanks for the detailed steps! I was able to work around the NDK "platforms" directory issue and fix the other "Illegal character in authority at index 7" with 9c6168f.

Please git pull and build again.

[markic22]

@dconeybe Ok, we are moving forward :D. I have successfully build snapshot now and used it in my app. Now I have an issue when I set this snapshot as library. At compiling I get this error

Could not determine the dependencies of task ':modules:compileBetaDebugAidl'.
Could not resolve all task dependencies for configuration ':modules:betaDebugCompileClasspath'.
Could not find com.google.firebase:firebase-common:19.5.1-SNAPSHOT.
Required by:
project :modules > com.google.firebase:firebase-firestore:22.0.2-SNAPSHOT
Could not find com.google.firebase:protolite-well-known-types:17.1.2-SNAPSHOT.
Required by:
project :modules > com.google.firebase:firebase-firestore:22.0.2-SNAPSHOT
Could not find com.google.firebase:firebase-database-collection:17.0.2-SNAPSHOT.
Required by:
project :modules > com.google.firebase:firebase-firestore:22.0.2-SNAPSHOT
Could not find com.google.firebase:firebase-components:16.1.1-SNAPSHOT.
Required by:
project :modules > com.google.firebase:firebase-firestore:22.0.2-SNAPSHOT
Could not find com.google.firebase:firebase-common:19.5.1-SNAPSHOT.
Required by:
project :modules > com.google.android.gms:play-services-measurement-api:18.0.0
project :modules > com.google.firebase:firebase-installations:16.3.2
Could not find com.google.firebase:firebase-components:16.1.1-SNAPSHOT.
Required by:
project :modules > com.google.android.gms:play-services-measurement-api:18.0.0
project :modules > com.google.firebase:firebase-installations:16.3.2

Do I need to build snapshot of those "missing" libraries also? for example for com.google.firebase:firebase-common:19.5.1-SNAPSHOT?

[dconeybe]

Yes, you're right. You will need to publish firestore's dependencies as well.

I tried running gradlew publishToMavenLocal but there are some Windows-specific build errors that I'm trying to figure out. I commented out a bunch of the unnecessary packages in subprojects.cfg in the root directory but I'm now trying to figure out a Dagger-related build error in transport-runtime.

If you by any chance have access to a Mac or Linux machine to do this work then that will likely greatly reduce this sort of friction. Otherwise, I'll keep digging. I have another commitment today so I won't have an update until tomorrow, unfortunately.

[markic22]

Hm... I guess I can make dual boot into linux, if we cannot figure out the issue, I will do that. I have managed to build all dependencies, and my application builds successfully with this snapshot now. The problem is that sdk crashes when being used in our application.

2021-01-27 18:00:24.151 18941-18941/si.creatriks.facility.beta E/AndroidRuntime: FATAL EXCEPTION: main Process: si.creatriks.facility.beta, PID: 18941 java.lang.RuntimeException: Internal error in Cloud Firestore (22.0.2). at com.google.firebase.firestore.util.AsyncQueue.lambda$panic$3(AsyncQueue.java:534) at com.google.firebase.firestore.util.AsyncQueue$$Lambda$3.run(Unknown Source:2) at android.os.Handler.handleCallback(Handler.java:883) at android.os.Handler.dispatchMessage(Handler.java:100) at android.os.Looper.loop(Looper.java:237) at android.app.ActivityThread.main(ActivityThread.java:7948) at java.lang.reflect.Method.invoke(Native Method) at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:493) at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1075) Caused by: java.lang.NoClassDefFoundError: Failed resolution of: Lio/grpc/protobuf/lite/ProtoLiteUtils; at com.google.firestore.v1.FirestoreGrpc.getListenMethod(FirestoreGrpc.java:395) at com.google.firebase.firestore.remote.WatchStream.<init>(WatchStream.java:61) at com.google.firebase.firestore.remote.Datastore.createWatchStream(Datastore.java:115) at com.google.firebase.firestore.remote.RemoteStore.<init>(RemoteStore.java:167) at com.google.firebase.firestore.core.MemoryComponentProvider.createRemoteStore(MemoryComponentProvider.java:72) at com.google.firebase.firestore.core.ComponentProvider.initialize(ComponentProvider.java:135) at com.google.firebase.firestore.core.FirestoreClient.initialize(FirestoreClient.java:249) at com.google.firebase.firestore.core.FirestoreClient.lambda$new$0(FirestoreClient.java:96) at com.google.firebase.firestore.core.FirestoreClient$$Lambda$1.run(Unknown Source:8) at com.google.firebase.firestore.util.AsyncQueue.lambda$enqueue$2(AsyncQueue.java:436) at com.google.firebase.firestore.util.AsyncQueue$$Lambda$2.call(Unknown Source:2) at com.google.firebase.firestore.util.AsyncQueue$SynchronizedShutdownAwareExecutor.lambda$executeAndReportResult$1(AsyncQueue.java:322) at com.google.firebase.firestore.util.AsyncQueue$SynchronizedShutdownAwareExecutor$$Lambda$2.run(Unknown Source:4) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:462) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:301) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) at com.google.firebase.firestore.util.AsyncQueue$SynchronizedShutdownAwareExecutor$DelayedStartFactory.run(AsyncQueue.java:229) at java.lang.Thread.run(Thread.java:919) Caused by: java.lang.ClassNotFoundException: Didn't find class "io.grpc.protobuf.lite.ProtoLiteUtils" on path: DexPathList[[zip file "/data/app/si.creatriks.facility.beta-1uNE2rwzCCgHEJa5C3W-_g==/base.apk"],nativeLibraryDirectories=[/data/app/si.creatriks.facility.beta-1uNE2rwzCCgHEJa5C3W-_g==/lib/arm64, /system/lib64]] at dalvik.system.BaseDexClassLoader.findClass(BaseDexClassLoader.java:196) at java.lang.ClassLoader.loadClass(ClassLoader.java:379) at java.lang.ClassLoader.loadClass(ClassLoader.java:312) at com.google.firestore.v1.FirestoreGrpc.getListenMethod(FirestoreGrpc.java:395)  at com.google.firebase.firestore.remote.WatchStream.<init>(WatchStream.java:61)  at com.google.firebase.firestore.remote.Datastore.createWatchStream(Datastore.java:115)  at com.google.firebase.firestore.remote.RemoteStore.<init>(RemoteStore.java:167)  at com.google.firebase.firestore.core.MemoryComponentProvider.createRemoteStore(MemoryComponentProvider.java:72)  at com.google.firebase.firestore.core.ComponentProvider.initialize(ComponentProvider.java:135)  at com.google.firebase.firestore.core.FirestoreClient.initialize(FirestoreClient.java:249)  at com.google.firebase.firestore.core.FirestoreClient.lambda$new$0(FirestoreClient.java:96)  at com.google.firebase.firestore.core.FirestoreClient$$Lambda$1.run(Unknown Source:8)  at com.google.firebase.firestore.util.AsyncQueue.lambda$enqueue$2(AsyncQueue.java:436)  at com.google.firebase.firestore.util.AsyncQueue$$Lambda$2.call(Unknown Source:2)  at com.google.firebase.firestore.util.AsyncQueue$SynchronizedShutdownAwareExecutor.lambda$executeAndReportResult$1(AsyncQueue.java:322)  at com.google.firebase.firestore.util.AsyncQueue$SynchronizedShutdownAwareExecutor$$Lambda$2.run(Unknown Source:4)  at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:462)  at java.util.concurrent.FutureTask.run(FutureTask.java:266)  at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:301)  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)  at com.google.firebase.firestore.util.AsyncQueue$SynchronizedShutdownAwareExecutor$DelayedStartFactory.run(AsyncQueue.java:229)  at java.lang.Thread.run(Thread.java:919) 

Does this have something to do with proguard? (in our project it's disabled)

[dconeybe]

Hmm it does look like it's proguard related; however, if you aren't using proguard then it must be something else. Sigh. Sorry this is so difficult. I'll investigate and reply tomorrow.

[dconeybe]

Update: I've finally gotten myself to the point where I am also experiencing the java.lang.RuntimeException: Internal error in Cloud Firestore (22.0.2). error due to java.lang.NoClassDefFoundError: Failed resolution of: Lio/grpc/protobuf/lite/ProtoLiteUtils;. I think I may just need to go through a few rounds of explicitly including dependencies that are automatically pulled in when using the non-snapshot version of Firestore. I'll reply back once I know.

[dconeybe]

Ok, I think I've gotten it figured out. Try adding these deps to your app's build.gradle:

implementation 'com.google.firebase:firebase-firestore:22.0.2-SNAPSHOT'
implementation 'com.google.firebase:firebase-auth-interop:18.0.0'
implementation 'io.grpc:grpc-protobuf-lite:1.15.0'
implementation 'io.grpc:grpc-okhttp:1.28.0'
implementation 'io.grpc:grpc-android:1.28.0'
implementation 'io.grpc:grpc-stub:1.28.0'

I also pushed up some fixes to the dconeybe/Issue2311Debug branch, so it wouldn't hurt to do a

git pull
gradlew publishToMavenLocal

again to make sure that we're on the same page.

[markic22]

Thank you for your time and effort on this. I added those dependencies, and generated new snapshots.
Filtered logs:
https://gist.github.com/markic22/205a4c86a8b92efabc97f39ce7004957
All logs:
https://gist.github.com/markic22/27d55102ba6c87d6885e31287fe1313b

[dconeybe]

Thank you for providing these logs. Something is suspicious for sure.

From the logs I can see that the call to activeLimboTargetsByKey.get(key) in SyncEngine.removeLimboTarget() is often returning null when I expect it to return non-null. This causes the limbo resolutions to fail to start and would explain why you're experiencing this bug.

To test this hypothesis I've added some more logging and reduced the maximum number of concurrent limbo resolutions from 100 to 10. This will likely cause the bug to be reproduced much more easily on your end and will also help limit the sheer amount of log output that would be introduced by my new logging.

So please git pull the most recent changes from the dconeybe/Issue2311Debug branch, run gradlew publishToMavenLocal, rebuild your app, reproduce the issue, and attach the logs. Thanks again for your cooperation!

[markic22]

Here are the new logs.
https://gist.github.com/markic22/4a6c0cd063a9ed027a356230adb17cf4

I used the same "stress test" as before, so not sure yet if it's now more easy to reproduce.

[dconeybe]

@markic22 I think that I may have found the problem. I've just pushed up dfa67b0 that may fix the issue. Could you test it out, let me know if it fixes your issue, and post the "zzyzx" logs?

[markic22]

OK, now it goes through 🍾 , but I wanna run some more tests tomorrow (to check if it's actually new data loaded, not previous and some other cases).

Can you maybe explain to me why did it cause issue in our case, and why it was so difficulty to reproduce? I saw the change you made, but I don't fully understand "limbo" state of document. I want to understand it more, to maybe avoid or improve our usage of firestore.

Here are logs of successfully loaded data.
https://gist.github.com/markic22/9626c705a763a6e8469b160f3282a1d6

Really appreciate your help and time!! :)

[dconeybe]

That's great news! To be honest, I don't fully understand why the query started by CollectionReference.get() was not completing; however, examining the logs pointed to the fix.

A "limbo" document is a document that is stored in the local cache is known to be out of sync with the server. The concept of "limbo documents" is internal to the SDK and that's why it is not discussed in public documentation. When a document goes into "limbo" the client issues a request to get the latest version to update the local cache. I can explain the gory details, if desired, but there is also a pretty good explanation in the bug report that brought about the throttling of limbo resolutions: firebase/firebase-js-sdk#2683.

As it turns out, this is a bug in the web and iOS SDKs as well so I'm going to work on a fix for all repositories.

[red42]

Great to hear this is being fixed, thank you, @dconeybe ! Been struggling with this for a couple of weeks as well!

I noticed this in my Flutter app too, but only on Android, and this seems to be the exact issue I'm having. A strange workaround that worked in my case (again, I'm on Flutter so there may be other things at play here), was to add a limit() to the query. Even adding a limit much bigger than the number of documents I expect to retrieve from the collection seems to have done the trick. I usually get less than 200 documents, and even adding limit(1000) worked.

[markic22]

@dconeybe Please wait a little bit with a fix, I think that this doesn't fully resolve the issue and there are some "side effects". I'm still testing and trying to figure out what exactly is going on, but I think that limbo resolution is not working correctly, there are still some data that should be there.

[dconeybe]

@red42 That's interesting to know that others are facing this issue as well. Thanks for the extra info. Adding a limit to your query shouldn't change limbo resolution, but limits to involve extra logic and introduce new cases where documents can go into limbo so it's entirely possible that adding a limit could help the situation serendipitously.

@markic22 I've updated the dconeybe/Issue2311Debug branch with the "official" fix that I've sent out for review in #2404. Could you update your branch and do your final testing against that code? I'm quite interested to hear your observations and I'll hold off merging the fix until you confirm the details about the "side effects". Thanks!

[markic22]

@dconeybe Ok, after some further tests, it seems that everything is okay. We had one internal bug, which I mistaken for issue with limbo resolution. It all looks good to me.

[dconeybe]

@markic22 Thank you for confirming. I'll get the fix merged and included in the next Android release.

[dconeybe]

The fix has been merged in c9fefbe and will be included in the next release of the Android SDK.

@markic22 Thank you for all of the time you spent going back and forth with me debugging, including the up-front investigation you did to find the release in which this bug was introduced. I'm sorry for how this bug has been affecting you and costing you precious time. I'm glad that we could get it resolved. Thank you for using Firestore!

[dconeybe]

Update: This fix did not get merged in time for the next release, but will be part of the release following the next release, which is expected (but not guaranteed!) to be near the end of this month (Feb 2021).

[dconeybe]

Update: The fix for this bug was included in the Firestore Android SDK release 22.1.1 on March 01, 2021. For some reason it was excluded from the release notes. I'll see if I can fix that.

https://firebase.google.com/support/release-notes/android#firestore_v22-1-1

Update: The release notes at the link above have been updated to include this bug fix.

[ywmei-brt1]

Hello, Denver,

Just wandering is there a plan to fix this Illegal character in authority at index 7: issue on master branch for windows user? I am having this problem on my PC.... Thank you.

[dconeybe]

@ywmei-brt1 I have no plans to fix the "Illegal character in authority at index 7" issue. It's outside of the purview of Firestore and was tangential to this issue so I just worked around it. If this bug concerns you, feel free to open a new GitHub issue for it and perhaps the team responsible will get it fixed. Thanks!