firebase-android-sdk: Firestore takes up to 90 seconds to get new data after app returns to the foreground

  • Android Studio version: 4.1.1
  • Firebase Component: Firestore
  • Component version: bom 27.1.0

If the app is backgrounded and the phone is idle for a while (say 1-2 hours), then, upon returning to the app, Firestore won’t update with fresh data for up to 90 seconds. Which is a painful user experience because the data is stale and we can’t do anything to force a refresh. My use case is a sports app where the user has to wait with the app open for over a minute to get fresh scores. Another person over in the flutter wrapper sdk was talking about a chat app.

I found a way to reliably reproduce this in a minimal sample project. You’ll find the project and the logcat + steps in this drive folder: https://drive.google.com/drive/folders/1bWPX4IKmQqs86-Khf0CqwwzKOLlqfOEe?usp=sharing

Copying repro steps here:

I wrote a sample app that shows live data from firestore. The data itself is just a timestamp
with the current time (US Central) that's written to firestore by a python script every minute. 
So if you look at the app and the time displayed doesn't match the current time, then we know 
there's an unreasonable delay.

Repro steps:
1. Disable LTE data, just keep Wifi connected
2. Kill app, open app (around 16:23:35)
3. Wait for app to receive update from network (~16:24:03)
4. Navigate home, open google chrome to put the app in background
5. Force idle (adb shell dumpsys deviceidle force-idle)
6. Keep looking at logcat to see updates every minute (~16:25:02, 16:26:02, 16:27:02, 16:28:02)
7. Wait until there's a connection error that kicks off exponential backoff (~16:28:15 we see a connection error)
8. Open app after 8 minutes (~16:36:10) 
- Note: I was just looking at the exp backoff delay retries (it was as high as 84000s, and as soon as I saw 59947 ms I opened the app)
9. Wait with the app open until we finally get a network update at (~16:37:48)
- Note: this is about 1 minute after opening up the app, which matches the last backoff timer :O
10. Revert force-idle (adb shell dumpsys deviceidle unforce)

Expected behavior:
As soon as you re-open app (step 8) it should check the network for new data.

Current behavior:
It is not until after 60ish seconds after re-opening app that we get network data.

Repro attemps: 5/5

See the txt file in drive for more info and some useful logs from Firestore and the sample app

I feel that being backgrounded and the device being idle should not count as a connection error that triggers exponential backoff strategy. Or at least, the sdk should detect that we’ve transitioned from the bg to the foreground and retry immediately instead of waiting for the backoff timer to expire. It’s pretty obvious that this strategy is the issue, I saw backoffs as high as 84000ms, which coincide with reports of delays anywhere from 30-90 seconds…

The only workaround is to either restart the app (awful) or migrate back to real-time database.

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Reactions: 11
  • Comments: 20 (6 by maintainers)

Most upvoted comments

This should be included in our next release, which is only a couple of days away.

Very sorry about the delay. I’m wrapping up my current work and will investigate this as my next task. We understand this is a significant issue.

Thank you for the detailed reproduction steps and the test app! I’ll investigate and let you know how it goes. It does look like the issue could be that the exponential backoff doesn’t get reset.

Hello @var-const, may I please check if you were able to investigate? This issue is really a big problem for apps that is constantly listening for data from Firestore.

Practically makes the app unusable if the data cannot be fetched immediately or if the user has to restart the app. I hope you understand the severity of this bug and help to prioritize the fix. Thank you.

I also see the same problem with flutter firestore package. When the app goes background for some time(ex. 5min) and get resumed, any try to access to firestore doesn’t work. Restarting the app is the only choice. It is really critical and ruins all of the user experience in my app 😔. My app can’t stay in production without solving this issue.

Thank you @jorgegil96 for reproducing on Android. Very excited to see that a fix may arrive relatively soon!

I am able to reproduce this occasionally. It seems like the background detection we use errs on the side of caution and is not aggressive enough. It only invokes the restart when it is certain that the app was in the background and transitioned to the foreground. Instead, we want something that always fires when we go back to the foreground. This change will shortly be in review.

Still seeing this in 23.0.1 - it doesn’t look like the backoff retry is reset after entering the foreground (as the CL said it would). Same steps to reproduce still work.

FYI: I noticed it’s significantly harder to get the backoff to trigger in the Android 12 beta, which makes it way harder to get into a state where you can start reproducing this issue. Just thought I’d mention it, in case you all use android 12 in development and are finding it hard to follow the repro steps, maybe try using a previous OS version.

Thanks again for looking into it.

Logs:

2021-06-12 11:39:52.959 18479-12113/com.jorgegil.firestorebackgroundissuedemo W/Firestore: (23.0.1) [WatchStream]: (72876be) Stream closed with status: Status{code=UNAVAILABLE, description=Unable to resolve host firestore.googleapis.com, cause=java.lang.RuntimeException: java.net.UnknownHostException: Unable to resolve host "firestore.googleapis.com": No address associated with hostname
        at io.grpc.internal.DnsNameResolver.resolveAll(DnsNameResolver.java:436)
        at io.grpc.internal.DnsNameResolver$Resolve.resolveInternal(DnsNameResolver.java:272)
        at io.grpc.internal.DnsNameResolver$Resolve.run(DnsNameResolver.java:228)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
        at java.lang.Thread.run(Thread.java:919)
     Caused by: java.net.UnknownHostException: Unable to resolve host "firestore.googleapis.com": No address associated with hostname
        at java.net.Inet6AddressImpl.lookupHostByName(Inet6AddressImpl.java:156)
        at java.net.Inet6AddressImpl.lookupAllHostAddr(Inet6AddressImpl.java:103)
        at java.net.InetAddress.getAllByName(InetAddress.java:1152)
        at io.grpc.internal.DnsNameResolver$JdkAddressResolver.resolveAddress(DnsNameResolver.java:646)
        at io.grpc.internal.DnsNameResolver.resolveAll(DnsNameResolver.java:404)
        at io.grpc.internal.DnsNameResolver$Resolve.resolveInternal(DnsNameResolver.java:272) 
        at io.grpc.internal.DnsNameResolver$Resolve.run(DnsNameResolver.java:228) 
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) 
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) 
        at java.lang.Thread.run(Thread.java:919) 
     Caused by: android.system.GaiException: android_getaddrinfo failed: EAI_NODATA (No address associated with hostname)
        at libcore.io.Linux.android_getaddrinfo(Native Method)
        at libcore.io.ForwardingOs.android_getaddrinfo(ForwardingOs.java:74)
        at libcore.io.BlockGuardOs.android_getaddrinfo(BlockGuardOs.java:200)
        at libcore.io.ForwardingOs.android_getaddrinfo(ForwardingOs.java:74)
        at java.net.Inet6AddressImpl.lookupHostByName(Inet6AddressImpl.java:135)
        at java.net.Inet6AddressImpl.lookupAllHostAddr(Inet6AddressImpl.java:103) 
        at java.net.InetAddress.getAllByName(InetAddress.java:1152) 
        at io.grpc.internal.DnsNameResolver$JdkAddressResolver.resolveAddress(DnsNameResolver.java:646) 
        at io.grpc.internal.DnsNameResolver.resolveAll(DnsNameResolver.java:404) 
        at io.grpc.internal.DnsNameResolver$Resolve.resolveInternal(DnsNameResolver.java:272) 
        at io.grpc.internal.DnsNameResolver$Resolve.run(DnsNameResolver.java:228) 
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) 
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) 
        at java.lang.Thread.run(Thread.java:919) 
    }.
2021-06-12 11:39:52.962 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [OnlineStateTracker]: Could not reach Cloud Firestore backend. Connection failed 1 times. Most recent error: Status{code=UNAVAILABLE, description=Unable to resolve host firestore.googleapis.com, cause=java.lang.RuntimeException: java.net.UnknownHostException: Unable to resolve host "firestore.googleapis.com": No address associated with hostname
        at io.grpc.internal.DnsNameResolver.resolveAll(DnsNameResolver.java:436)
        at io.grpc.internal.DnsNameResolver$Resolve.resolveInternal(DnsNameResolver.java:272)
        at io.grpc.internal.DnsNameResolver$Resolve.run(DnsNameResolver.java:228)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
        at java.lang.Thread.run(Thread.java:919)
     Caused by: java.net.UnknownHostException: Unable to resolve host "firestore.googleapis.com": No address associated with hostname
        at java.net.Inet6AddressImpl.lookupHostByName(Inet6AddressImpl.java:156)
        at java.net.Inet6AddressImpl.lookupAllHostAddr(Inet6AddressImpl.java:103)
        at java.net.InetAddress.getAllByName(InetAddress.java:1152)
        at io.grpc.internal.DnsNameResolver$JdkAddressResolver.resolveAddress(DnsNameResolver.java:646)
        at io.grpc.internal.DnsNameResolver.resolveAll(DnsNameResolver.java:404)
        at io.grpc.internal.DnsNameResolver$Resolve.resolveInternal(DnsNameResolver.java:272) 
        at io.grpc.internal.DnsNameResolver$Resolve.run(DnsNameResolver.java:228) 
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) 
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) 
        at java.lang.Thread.run(Thread.java:919) 
     Caused by: android.system.GaiException: android_getaddrinfo failed: EAI_NODATA (No address associated with hostname)
        at libcore.io.Linux.android_getaddrinfo(Native Method)
        at libcore.io.ForwardingOs.android_getaddrinfo(ForwardingOs.java:74)
        at libcore.io.BlockGuardOs.android_getaddrinfo(BlockGuardOs.java:200)
        at libcore.io.ForwardingOs.android_getaddrinfo(ForwardingOs.java:74)
        at java.net.Inet6AddressImpl.lookupHostByName(Inet6AddressImpl.java:135)
        at java.net.Inet6AddressImpl.lookupAllHostAddr(Inet6AddressImpl.java:103) 
        at java.net.InetAddress.getAllByName(InetAddress.java:1152) 
        at io.grpc.internal.DnsNameResolver$JdkAddressResolver.resolveAddress(DnsNameResolver.java:646) 
        at io.grpc.internal.DnsNameResolver.resolveAll(DnsNameResolver.java:404) 
        at io.grpc.internal.DnsNameResolver$Resolve.resolveInternal(DnsNameResolver.java:272) 
        at io.grpc.internal.DnsNameResolver$Resolve.run(DnsNameResolver.java:228) 
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) 
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) 
        at java.lang.Thread.run(Thread.java:919) 
    }
    This typically indicates that your device does not have a healthy Internet connection at the moment. The client will operate in offline mode until it is able to successfully connect to the backend.
2021-06-12 11:39:52.963 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [ExponentialBackoff]: Backing off for 85273 ms (base delay: 60000 ms, delay with jitter: 85335 ms, last attempt: 62 ms ago)

-------------------------------------------------------
***RE-OPENED APP HERE AND WAITED
-------------------------------------------------------

2021-06-12 11:40:17.331 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [GrpcCallProvider]: Current gRPC connectivity state: CONNECTING
2021-06-12 11:40:17.332 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [GrpcCallProvider]: Setting the connectivityAttemptTimer
2021-06-12 11:40:17.530 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [GrpcCallProvider]: Current gRPC connectivity state: READY
2021-06-12 11:40:17.531 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [GrpcCallProvider]: Clearing the connectivityAttemptTimer
2021-06-12 11:40:52.775 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [Persistence]: Starting transaction: Collect garbage
2021-06-12 11:40:52.780 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [LruGarbageCollector]: Garbage collection skipped; Cache size 94208 is lower than threshold 104857600


-------------------------------------------------------
***FINALLY ABOUT THE GET UPDATE AFTER 85 seconds (exactly what the backoff said above -85273ms-)
-------------------------------------------------------


2021-06-12 11:41:18.243 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [WatchStream]: (72876be) Stream is open
2021-06-12 11:41:18.252 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [WatchStream]: (72876be) Stream sending: # com.google.firestore.v1.ListenRequest@3d8a1a3a
    add_target {
      query {
        parent: "projects/firestorebackgroundissue/databases/(default)/documents"
        structured_query {
          from {
            collection_id: "debugging"
          }
          order_by {
            direction: ASCENDING
            direction_value: 1
            field {
              field_path: "__name__"
            }
          }
          where {
            field_filter {
              field {
                field_path: "version"
              }
              op: EQUAL
              op_value: 5
              value {
                integer_value: 1
              }
            }
          }
        }
      }
      resume_token: "\n\t\b\357\271\246\246\303\222\361\002"
      target_id: 2
    }
    database: "projects/firestorebackgroundissue/databases/(default)"
2021-06-12 11:41:18.253 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [FirestoreCallCredentials]: Firebase Auth API not available, not using authentication.
2021-06-12 11:41:18.257 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/chatty: uid=10260(com.jorgegil.firestorebackgroundissuedemo) FirestoreWorker identical 1 line
2021-06-12 11:41:18.383 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [WatchStream]: (72876be) Stream received headers: {date=Sat, 12 Jun 2021 16:41:14 GMT}
2021-06-12 11:41:18.386 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [WatchStream]: (72876be) Stream received: # com.google.firestore.v1.ListenResponse@72b7dc77
    target_change {
      target_change_type: ADD
      target_change_type_value: 1
      target_ids: 2
    }
2021-06-12 11:41:18.389 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [WatchStream]: (72876be) Stream received: # com.google.firestore.v1.ListenResponse@9a708182
    target_change {
      read_time {
        nanos: 385327000
        seconds: 1623515703
      }
      resume_token: "\n\t\b\357\271\246\246\303\222\361\002"
    }
2021-06-12 11:41:18.389 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [Persistence]: Starting transaction: Apply remote event
2021-06-12 11:41:18.395 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [Persistence]: Starting transaction: notifyLocalViewChanges
2021-06-12 11:41:18.472 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/chatty: uid=10260(com.jorgegil.firestorebackgroundissuedemo) FirestoreWorker identical 1 line
2021-06-12 11:41:18.477 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [WatchStream]: (72876be) Stream received: # com.google.firestore.v1.ListenResponse@edeb0310
    document_change {
      document {
        create_time {
          nanos: 541067000
          seconds: 1619980902
        }
        fields {
          key: "now"
          value {
            integer_value: 0
            string_value: "06/12 11:41"
          }
        }
        fields {
          key: "version"
          value {
            integer_value: 1
          }
        }
        name: "projects/firestorebackgroundissue/databases/(default)/documents/debugging/time"
        update_time {
          nanos: 725116000
          seconds: 1623516062
        }
      }
      target_ids: 2
    }
2021-06-12 11:41:18.480 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [WatchStream]: (72876be) Stream received: # com.google.firestore.v1.ListenResponse@1a6557d
    filter {
      count: 1
      target_id: 2
    }
2021-06-12 11:41:18.483 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [WatchStream]: (72876be) Stream received: # com.google.firestore.v1.ListenResponse@b749ccb3
    target_change {
      read_time {
        nanos: 395706000
        seconds: 1623516074
      }
      resume_token: "\n\t\b\272\220\233\327\304\222\361\002"
      target_change_type: CURRENT
      target_change_type_value: 3
      target_ids: 2
    }
2021-06-12 11:41:18.485 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [WatchStream]: (72876be) Stream received: # com.google.firestore.v1.ListenResponse@1e58d918
    target_change {
      read_time {
        nanos: 395706000
        seconds: 1623516074
      }
      resume_token: "\n\t\b\272\220\233\327\304\222\361\002"
    }
2021-06-12 11:41:18.486 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [Persistence]: Starting transaction: Apply remote event
2021-06-12 11:41:18.502 18479-12113/com.jorgegil.firestorebackgroundissuedemo I/Firestore: (23.0.1) [Persistence]: Starting transaction: notifyLocalViewChanges

Looking forward to seeing this finally solved!