Slow response on firestore addSnapShotListener

[maclir]

[REQUIRED] Step 2: Describe your environment

• Android Studio version: 4.0.1
• Firebase Component: Firestore
• Component version: ktx-21.5.0

[REQUIRED] Step 3: Describe the problem

When doing a single document get query, if phone is on wifi, the initial result from server comes with a very long delay (1 minute).

If I disable wifi on phone to switch to mobile data, response comes back immediately.

Steps to reproduce:

• App is in killed state and have wifi on.
• Open application where firestore get is called.
• Observe that callback is being delayed. (This is random and does not happen all the time)
• Disable wifi.
• Response comes in callback right away.

Relevant Code:

fs.collection("games").document("blah").addSnapshotListener { snapshot, e ->
    if (e != null) {
        Timber.e(e, "Listen failed.")
        return@addSnapshotListener
    }

    data.value = snapshot?.toObject()
}

[schmidt-sebastian]

Assigning to current on-call.

[rafikhan]

@maclir - Can you please enable logging in Firestore and re-run this query so we can better diagnose this? Thank you.

[maclir]

This happens on a real device only and not the emulator. I will make a build and get the logs during the week.

[maclir]

OK. Finally got around to making the build for this on my phone. Now is the wait game to see when it happens again.

[maclir]

I see this on crashlytics non-fatal logs, which is addSnapShotListener's onFailedListener:

UNAVAILABLE: Unable to resolve host firestore.googleapis.com

I'm pretty sure that the device has internet when this happens though ^, other than other apps having connectivity, new ads are also fetched on the screen that addSnapShotListener is failing.

Not from firestore logs, but the error exception itself.

[rafikhan]

Thanks for this update. Generally speaking the Android networking stack varies a lot from version to version, device to device, and isn't always reliable. We do our best to compensate for this but this issue will never fully go away.

The exception you shared is helpful however we still need the firestore log to understand what the retry logic might have been doing when it happened. Without this there isn't much we can do. Once you have it, please attach/link it and include as much detail on the device/os as you can.

[maclir]

Device that I am using is:
Samsung Galaxy S10
Model number: SM-G973F
Android version: 10
Build number: QP1A.190711.020.G973FXXS7CTF3

I am still trying to get the log but this issue, so far, is only happening on my release builds which makes it not possible to get the logs for them.

I have a debug build on my phone as well, and will continue to test on it and see if I can reproduce it there.

[maclir]

Finally managed to catch it:

[08-12 20:45:13.946 12574:12633 I/Firestore]
(21.5.0) [GrpcCallProvider]: Current gRPC connectivity state: IDLE

[08-12 20:45:13.950 12574:12633 I/Firestore]
(21.5.0) [GrpcCallProvider]: Current gRPC connectivity state: CONNECTING

[08-12 20:45:13.951 12574:12633 I/Firestore]
(21.5.0) [GrpcCallProvider]: Setting the connectivityAttemptTimer

[08-12 20:45:13.951 12574:12633 I/Firestore]
(21.5.0) [GrpcCallProvider]: Current gRPC connectivity state: TRANSIENT_FAILURE

[08-12 20:45:13.953 12574:12633 I/Firestore]
(21.5.0) [GrpcCallProvider]: Clearing the connectivityAttemptTimer

[08-12 20:45:16.436 12574:12633 I/Firestore]
(21.5.0) [GrpcCallProvider]: Current gRPC connectivity state: CONNECTING

[08-12 20:45:16.437 12574:12633 I/Firestore]
(21.5.0) [GrpcCallProvider]: Setting the connectivityAttemptTimer

[08-12 20:45:16.729 12574:12633 I/Firestore]
(21.5.0) [GrpcCallProvider]: Current gRPC connectivity state: READY

[08-12 20:45:16.730 12574:12633 I/Firestore]
(21.5.0) [GrpcCallProvider]: Clearing the connectivityAttemptTimer

[08-12 20:45:21.497 12574:12633 I/Firestore]
(21.5.0) [Persistence]: Starting transaction: Allocate target

[08-12 20:45:21.506 12574:12633 I/Firestore]
(21.5.0) [IndexFreeQueryEngine]: Using full collection scan to execute query: Query(target=Query(games/h37s5PpKKNY9dyKXvYGQ order by __name__);limitType=LIMIT_TO_FIRST)

[08-12 20:45:21.509 12574:12633 I/Firestore]
(21.5.0) [WatchStream]: (788e7e) Stream is open

[08-12 20:45:21.512 12574:12633 I/Firestore]
(21.5.0) [WatchStream]: (788e7e) Stream sending: # com.google.firestore.v1.ListenRequest@13b620b7
add_target {
  documents {
    documents: "projects/dekode/databases/(default)/documents/games/h37s5PpKKNY9dyKXvYGQ"
  }
  target_id: 10
}
database: "projects/dekode/databases/(default)"

[08-12 20:45:22.098 12574:12633 I/Firestore]
(21.5.0) [FirestoreClient]: Credential changed. Current user: urxLXpdQuoek6QaFJgHO8q4SVtu1

[08-12 20:45:22.098 12574:12633 I/Firestore]
(21.5.0) [RemoteStore]: Restarting streams for new credential.

[08-12 20:45:22.098 12574:12633 I/Firestore]
(21.5.0) [WatchStream]: (788e7e) Performing stream teardown

[08-12 20:45:22.098 12574:12633 I/Firestore]
(21.5.0) [WatchStream]: (788e7e) Closing stream client-side

[08-12 20:45:22.101 12574:12633 I/Firestore]
(21.5.0) [WatchStream]: (788e7e) Stream is open

[08-12 20:45:22.103 12574:12633 I/Firestore]
(21.5.0) [WatchStream]: (788e7e) Stream sending: # com.google.firestore.v1.ListenRequest@13b620b7
add_target {
  documents {
    documents: "projects/dekode/databases/(default)/documents/games/h37s5PpKKNY9dyKXvYGQ"
  }
  target_id: 10
}
database: "projects/dekode/databases/(default)"

[08-12 20:45:32.104 12574:12633 I/Firestore]
(21.5.0) [OnlineStateTracker]: Could not reach Cloud Firestore backend. Backend didn't respond within 10 seconds

[08-12 20:47:05.257 12574:12633 I/Firestore]
(21.5.0) [Persistence]: Starting transaction: Release target

[08-12 20:47:05.262 12574:12633 I/Firestore]
(21.5.0) [WatchStream]: (788e7e) Stream sending: # com.google.firestore.v1.ListenRequest@9c281c2a
database: "projects/dekode/databases/(default)"
remove_target: 10

[08-12 20:47:45.764 12574:12633 I/Firestore]
(21.5.0) [Persistence]: Starting transaction: Collect garbage

[08-12 20:47:45.772 12574:12633 I/Firestore]
(21.5.0) [LruGarbageCollector]: Garbage collection skipped; Cache size 90112 is lower than threshold 104857600

[maclir]

What does firestore use for networking? Is it okhttp? Can it be overridden?

[yzalvov]

Hi @maclir
Have you managed to find any solution? Same problem here.

[thebrianchen]

@maclir I've been trying to investigate this issue, or at least reproduce it, but without success.

Based on the log line [Persistence]: Starting transaction: Release target, it appears that you've unsubscribed from the query. Could you share more of the logs from before and after what you've posted, including the part where you're able to get the data by disabling wifi? I'm curious to see what the connectivity state is when that switch happens. Thanks!

[google-oss-bot]

Hey @maclir. 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!

[maclir]

I will try to collect those longs. It will take some time as it doesn't happen often :)

[maclir]

It may be worth mentioning that the only times I could reproduce this, it was when I clicked a notification and deeplinked directly into the screen that was listening for the updates.

[google-oss-bot]

Hey @maclir. 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!

[google-oss-bot]

Since there haven't been any recent updates here, I am going to close this issue.

@maclir if you're still experiencing this problem and want to continue the discussion just leave a comment here and we are happy to re-open this.