Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Firestore networking fails intermittently #8503

Closed
kwan-research opened this issue Aug 6, 2021 · 19 comments
Closed

Firestore networking fails intermittently #8503

kwan-research opened this issue Aug 6, 2021 · 19 comments
Assignees

Comments

@kwan-research
Copy link

[REQUIRED] Step 1: Describe your environment

  • Xcode version: 12.5.1
  • Firebase SDK version: 8.5.0
  • Installation method: Swift Package Manager
  • Firebase Component: Firestore

[REQUIRED] Step 2: Describe the problem

Steps to reproduce:

Occasionally (feels like a quarter of the time) when I launch my app it fails to retrieve data from the Firestore server. The snapshot listener is called with cached local data, but nothing from the server. Then, a few minutes later, data arrives successfully.

My app waits for non-cached server data before proceeding, so this is really noticeable. It has been happening all year, but I assumed it was a hardware issue (an old second-hand iPhone 7). But it happens just as often in Xcode simulators.

Note that most of the time Firestore works fine, which makes this bug difficult to reproduce. And yes, I have a very reliable internet connection.

To test the hypothesis that the main thread was blocked, I tried adding a function that calls itself asynchronously every few seconds and prints a message. But it ran fine.

Relevant Code:

  private func onUserChanged(uid: String) {
    if let listener = userSnapshotListener {
      listener.remove()
    }
    requireServerData = true
    userSnapshotListener = Firestore.firestore()
      .collection("user")
      .document(uid)
      .addSnapshotListener(
        includeMetadataChanges: true
      ) { documentSnapshot, err in
        if let err = err {
          os_log("Query user: %s",
                 type: .error, err.localizedDescription)
        } else if let snapshot = documentSnapshot {
          self.processUserSnapshot(uid: uid, document: snapshot)
        }
      }
  }
  
  // Processes a recently-fetched update to the current user's
  // Firestore data.
  private func processUserSnapshot(
    uid: String,
    document: DocumentSnapshot
  ) {
    // Ensure the first result is from the server, not the cache.
    if requireServerData {
      if document.metadata.isFromCache {
        print("rejecting cached result")
        return
      }
      requireServerData = false
    }
    print("got result from the server")
  }

Here's a typical log for the app (called Metropolis). It uses Firebase Messaging as well, although that's probably not relevant. And I've seen Firestore take a lot longer than this to reach the server.

2021-08-06 17:34:18.502040+1000 Metropolis[82323:3195908] 8.5.0 - [Firebase/Messaging][I-FCM001000] FIRMessaging Remote Notifications proxy enabled, will swizzle remote notification receiver handlers. If you'd prefer to manually integrate Firebase Messaging, add "FirebaseAppDelegateProxyEnabled" to your Info.plist, and set it to NO. Follow the instructions at:
https://firebase.google.com/docs/cloud-messaging/ios/client#method_swizzling_in_firebase_messaging
to ensure proper integration.
rejecting cached result
2021-08-06 17:34:18.743205+1000 Metropolis[82323:3195909] 8.5.0 - [Firebase/Messaging][I-FCM012002] Error in application:didFailToRegisterForRemoteNotificationsWithError: remote notifications are not supported in the simulator
2021-08-06 17:34:18.894094+1000 Metropolis[82323:3195909] [] nw_protocol_get_quic_image_block_invoke dlopen libquic failed
2021-08-06 17:34:19.506400+1000 Metropolis[82323:3195909] Product request failed: UNKNOWN_ERROR
2021-08-06 17:34:29.728918+1000 Metropolis[82323:3196063] 8.5.0 - [Firebase/Firestore][I-FST000001] Could not reach Cloud Firestore backend. Backend didn't respond within 10 seconds.
 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-08-06 17:34:48.921787+1000 Metropolis[82323:3196267] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (600002acaa18) Stream error: 'Unavailable: failed to connect to all addresses'
2021-08-06 17:34:48.938634+1000 Metropolis[82323:3196267] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (600002acaa18) Stream error: 'Unavailable: failed to connect to all addresses'
2021-08-06 17:34:49.869870+1000 Metropolis[82323:3196265] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (600002acaa18) Stream error: 'Unavailable: failed to connect to all addresses'
got result from the server
@kwan-research
Copy link
Author

It's also common to see a bunch of these errors in the logs as well:

2021-08-07 14:55:41.612325+1000 Metropolis[84923:3498295] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (600000880b18) Stream error: 'Unavailable: DNS resolution failed'

FYI, when Firestore reaches the backend immediately, the logs look like this. Pretty much the same, apart from the network errors.

2021-08-07 14:46:42.255683+1000 Metropolis[84909:3491976] 8.5.0 - [Firebase/Messaging][I-FCM001000] FIRMessaging Remote Notifications proxy enabled, will swizzle remote notification receiver handlers. If you'd prefer to manually integrate Firebase Messaging, add "FirebaseAppDelegateProxyEnabled" to your Info.plist, and set it to NO. Follow the instructions at:
https://firebase.google.com/docs/cloud-messaging/ios/client#method_swizzling_in_firebase_messaging
to ensure proper integration.
rejecting cached result
2021-08-07 14:46:42.757805+1000 Metropolis[84909:3491981] 8.5.0 - [Firebase/Messaging][I-FCM012002] Error in application:didFailToRegisterForRemoteNotificationsWithError: remote notifications are not supported in the simulator
2021-08-07 14:46:42.758180+1000 Metropolis[84909:3491980] [] nw_protocol_get_quic_image_block_invoke dlopen libquic failed
got result from the server
2021-08-07 14:46:43.350598+1000 Metropolis[84909:3491980] Product request failed: UNKNOWN_ERROR

@kwan-research
Copy link
Author

I enabled Firestore logging, and got more comprehensive logs (with sensitive info redacted).

2021-08-07 15:21:06.216049+1000 Metropolis[85082:3524192] 8.5.0 - [Firebase/Messaging][I-FCM001000] FIRMessaging Remote Notifications proxy enabled, will swizzle remote notification receiver handlers. If you'd prefer to manually integrate Firebase Messaging, add "FirebaseAppDelegateProxyEnabled" to your Info.plist, and set it to NO. Follow the instructions at:
https://firebase.google.com/docs/cloud-messaging/ios/client#method_swizzling_in_firebase_messaging
to ensure proper integration.
2021-08-07 15:21:06.216653+1000 Metropolis[85082:3524192] 8.5.0 - [Firebase/Firestore][I-FST000001] Initializing. Current user: MWB5EmQ8SlVcMNzcGAxXnr5Nb1u1
2021-08-07 15:21:06.216867+1000 Metropolis[85082:3524192] 8.5.0 - [Firebase/Firestore][I-FST000001] Using /Users/XXXX/Library/Developer/CoreSimulator/Devices/XXXX/data/Containers/Data/Application/XXXX/Library/Application Support/firestore/__FIRAPP_DEFAULT/metropolis-devel/main for LevelDB storage
2021-08-07 15:21:06.262993+1000 Metropolis[85082:3524192] 8.5.0 - [GoogleUtilities/SceneDelegateSwizzler][I-SWZ001114] Successfully created Scene Delegate Proxy automatically. To disable the proxy, set the flag GoogleUtilitiesAppDelegateProxyEnabled to NO (Boolean) in the Info.plist
2021-08-07 15:21:06.263206+1000 Metropolis[85082:3524192] 8.5.0 - [Firebase/Core][I-COR000033] Data Collection flag is not set.
2021-08-07 15:21:06.263455+1000 Metropolis[85082:3524192] 8.5.0 - [GULReachability][I-REA902004] Network status has changed. Code:2, status:Connected
rejecting cached result
2021-08-07 15:21:06.367537+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Rewrite Targets Canonical Ids: 13 changes (0 bytes):
  - Put [query_target: canonical_id=XXXX|f:XXXX==MWB5EmQ8SlVcMNzcGAxXnr5Nb1u1|ob:__name__asc target_id=10] (0 bytes)
  - Put [query_target: canonical_id=XXXX/XXXX|f:|ob:__name__asc target_id=12] (0 bytes)
  - Put [query_target: canonical_id=XXXX/XXXX|f:|ob:__name__asc target_id=14] (0 bytes)
  - Put [query_target: canonical_id=XXXX|f:XXXXin[8085,808f]|ob:lastActivedesc__name__desc|l:1000 target_id=6] (0 bytes)
  - Put [query_target: canonical_id=user/MWB5EmQ8SlVcMNzcGAxXnr5Nb1u1/XXXX|f:|ob:__name__asc target_id=8] (0 bytes)
  - Put [query_target: canonical_id=user/MWB5EmQ8SlVcMNzcGAxXnr5Nb1u1/XXXX|f:|ob:sortIndexasc__name__asc target_id=4] (0 bytes)
  - Put [query_target: canonical_id=user/MWB5EmQ8SlVcMNzcGAxXnr5Nb1u1|f:|ob:__name__asc target_id=2] (0 bytes)
  - Put [query_target: canonical_id=user/XXXX/XXXX|f:|ob:__name__asc target_id=22] (0 bytes)
  - Put [query_target: canonical_id=user/XXXX|f:|ob:__name__asc target_id=20] (0 bytes)
  - Put [query_target: canonical_id=user/XXXX/XXXX|f:|ob:__name__asc target_id=18] (0 bytes)
  - Put [query_target: canonical_id=user/XXXX|f:|ob:__name__asc target_id=16] (0 bytes)
  - Put [query_target: canonical_id=user/XXXX/XXXX|f:|ob:__name__asc target_id=26] (0 bytes)
  - Put [query_target: canonical_id=user/XXXX|f:|ob:__name__asc target_id=24] (0 bytes)>
2021-08-07 15:21:06.370258+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Start LevelDB: 0 changes (0 bytes):>
2021-08-07 15:21:06.370546+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Start MutationQueue: 0 changes (0 bytes):>
2021-08-07 15:21:06.370809+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2021-08-07 15:21:06.371064+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Allocate target: 0 changes (0 bytes):>
2021-08-07 15:21:06.371260+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Firestore][I-FST000001] Using full collection scan to execute query: Query(canonical_id=user/MWB5EmQ8SlVcMNzcGAxXnr5Nb1u1|f:|ob:__name__asc)
2021-08-07 15:21:06.371531+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction ExecuteQuery: 0 changes (0 bytes):>
2021-08-07 15:21:06.371925+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) start
2021-08-07 15:21:06.372524+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Auth][I-AUT000002] Token auto-refresh enabled.
2021-08-07 15:21:06.372944+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Firestore][I-FST000001] Credential Changed. Current user: MWB5EmQ8SlVcMNzcGAxXnr5Nb1u1
2021-08-07 15:21:06.373348+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Auth][I-AUT000004] Token auto-refresh scheduled in 42:25 for the new token.
2021-08-07 15:21:06.373811+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Firestore][I-FST000001] RemoteStore 7fe134005510 restarting streams for new credential
2021-08-07 15:21:06.374152+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) stop
2021-08-07 15:21:06.374468+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Firestore][I-FST000001] WriteStream (7fe134005e98) stop
2021-08-07 15:21:06.374830+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) start
2021-08-07 15:21:06.375108+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2021-08-07 15:21:06.413283+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Installations][I-FIS002001] -[FIRInstallationsIDController installationWithValidAuthTokenForcingRefresh:0], appName: __FIRAPP_DEFAULT
2021-08-07 15:21:06.413595+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Auth][I-AUT000017] Has valid access token. Estimated expiration date: 2021-08-07 06:08:31 +0000, current date: 2021-08-07 05:21:06 +0000
2021-08-07 15:21:06.415451+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Auth][I-AUT000017] Has valid access token. Estimated expiration date: 2021-08-07 06:08:31 +0000, current date: 2021-08-07 05:21:06 +0000
2021-08-07 15:21:06.415718+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Firestore][I-FST000001] Creating Firestore stub.
2021-08-07 15:21:06.416002+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) watch: <ListenRequest 0x700004a85338>: {
  database: "projects/metropolis-devel/databases/(default)"
  add_target {
    documents {
      documents: "projects/metropolis-devel/databases/(default)/documents/user/MWB5EmQ8SlVcMNzcGAxXnr5Nb1u1"
    }
    resume_token: "\n\t\010\355\360\204\XXXX"
    target_id: 2
  }
}
2021-08-07 15:21:06.416336+1000 Metropolis[85082:3524208] 8.5.0 - [Firebase/Messaging][I-FCM012002] Error in application:didFailToRegisterForRemoteNotificationsWithError: remote notifications are not supported in the simulator
2021-08-07 15:21:07.076780+1000 Metropolis[85082:3524192] Product request failed: UNKNOWN_ERROR
2021-08-07 15:21:17.307516+1000 Metropolis[85082:3524209] 8.5.0 - [Firebase/Firestore][I-FST000001] Could not reach Cloud Firestore backend. Backend didn't respond within 10 seconds.
 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-08-07 15:21:36.382992+1000 Metropolis[85082:3524679] [] nw_protocol_get_quic_image_block_invoke dlopen libquic failed
2021-08-07 15:22:06.382147+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fc86c0'): operation of type 2 failed
2021-08-07 15:22:06.382705+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fc86c0'): finishing the underlying call
2021-08-07 15:22:06.383223+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fc86c0'): fast finishing 1 completion(s)
2021-08-07 15:22:06.383724+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fc86c0'): finishing and notifying observers
2021-08-07 15:22:06.384143+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fc86c0'): shutting down; completions: 0, is finished: true
2021-08-07 15:22:06.384554+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fc86c0'): fast finishing 0 completion(s)
2021-08-07 15:22:06.384934+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) Stream error: 'Unavailable: DNS resolution failed'
2021-08-07 15:22:06.385607+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fc86c0'): destroying stream
2021-08-07 15:22:06.386030+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] Could not reach Cloud Firestore backend. Connection failed 1 times. Most recent error: DNS resolution failed
 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-08-07 15:22:06.402447+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) backoff
2021-08-07 15:22:06.402737+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) start
2021-08-07 15:22:06.402940+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Auth][I-AUT000017] Has valid access token. Estimated expiration date: 2021-08-07 06:08:31 +0000, current date: 2021-08-07 05:22:06 +0000
2021-08-07 15:22:06.411755+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) watch: <ListenRequest 0x700004a85338>: {
  database: "projects/metropolis-devel/databases/(default)"
  add_target {
    documents {
      documents: "projects/metropolis-devel/databases/(default)/documents/user/MWB5EmQ8SlVcMNzcGAxXnr5Nb1u1"
    }
    resume_token: "\n\t\010\355\360\204\XXXX"
    target_id: 2
  }
}
2021-08-07 15:22:06.412053+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fc0ab0'): operation of type 2 failed
2021-08-07 15:22:06.412360+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fc0ab0'): finishing the underlying call
2021-08-07 15:22:06.412695+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fc0ab0'): fast finishing 1 completion(s)
2021-08-07 15:22:06.413157+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fc0ab0'): finishing and notifying observers
2021-08-07 15:22:06.413415+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fc0ab0'): shutting down; completions: 0, is finished: true
2021-08-07 15:22:06.414164+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fc0ab0'): fast finishing 0 completion(s)
2021-08-07 15:22:06.414580+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) Stream error: 'Unavailable: DNS resolution failed'
2021-08-07 15:22:06.415062+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fc0ab0'): destroying stream
2021-08-07 15:22:06.415678+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] Could not reach Cloud Firestore backend. Connection failed 1 times. Most recent error: DNS resolution failed
 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-08-07 15:22:06.416001+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) backoff
2021-08-07 15:22:06.416244+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] Backing off for 1078 ms (base delay: 1000 ms, delay with jitter: 1106 ms, last attempt: 28 ms ago)
2021-08-07 15:22:06.416705+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] Garbage collection skipped; Cache size 32015 is lower than threshold 104857600
2021-08-07 15:22:06.417030+1000 Metropolis[85082:3524995] 8.5.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Collect garbage: 0 changes (0 bytes):>
2021-08-07 15:22:07.597236+1000 Metropolis[85082:3525000] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) start
2021-08-07 15:22:07.597721+1000 Metropolis[85082:3525000] 8.5.0 - [Firebase/Auth][I-AUT000017] Has valid access token. Estimated expiration date: 2021-08-07 06:08:31 +0000, current date: 2021-08-07 05:22:07 +0000
2021-08-07 15:22:07.625755+1000 Metropolis[85082:3525000] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) watch: <ListenRequest 0x7000048fc338>: {
  database: "projects/metropolis-devel/databases/(default)"
  add_target {
    documents {
      documents: "projects/metropolis-devel/databases/(default)/documents/user/MWB5EmQ8SlVcMNzcGAxXnr5Nb1u1"
    }
    resume_token: "\n\t\010\355\360\204\XXXX"
    target_id: 2
  }
}
2021-08-07 15:22:07.626224+1000 Metropolis[85082:3525000] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fcd200'): operation of type 2 failed
2021-08-07 15:22:07.626523+1000 Metropolis[85082:3525000] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fcd200'): finishing the underlying call
2021-08-07 15:22:07.626859+1000 Metropolis[85082:3525000] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fcd200'): fast finishing 1 completion(s)
2021-08-07 15:22:07.627103+1000 Metropolis[85082:3525000] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fcd200'): finishing and notifying observers
2021-08-07 15:22:07.627395+1000 Metropolis[85082:3525000] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fcd200'): shutting down; completions: 0, is finished: true
2021-08-07 15:22:07.627729+1000 Metropolis[85082:3525000] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fcd200'): fast finishing 0 completion(s)
2021-08-07 15:22:07.628094+1000 Metropolis[85082:3525000] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) Stream error: 'Unavailable: DNS resolution failed'
2021-08-07 15:22:07.628479+1000 Metropolis[85082:3525000] 8.5.0 - [Firebase/Firestore][I-FST000001] GrpcStream('600002fcd200'): destroying stream
2021-08-07 15:22:07.628884+1000 Metropolis[85082:3525000] 8.5.0 - [Firebase/Firestore][I-FST000001] Could not reach Cloud Firestore backend. Connection failed 1 times. Most recent error: DNS resolution failed
 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-08-07 15:22:07.629134+1000 Metropolis[85082:3525000] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) backoff
2021-08-07 15:22:07.629333+1000 Metropolis[85082:3525000] 8.5.0 - [Firebase/Firestore][I-FST000001] Backing off for 1947 ms (base delay: 1500 ms, delay with jitter: 1976 ms, last attempt: 29 ms ago)

And here are the log messages when it finally connects, 6 minutes later.

2021-08-07 15:28:19.024414+1000 Metropolis[85082:3528804] 8.5.0 - [Firebase/Firestore][I-FST000001] Backing off for 63107 ms (base delay: 60000 ms, delay with jitter: 63137 ms, last attempt: 30 ms ago)
2021-08-07 15:29:28.438881+1000 Metropolis[85082:3529622] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) start
2021-08-07 15:29:28.439464+1000 Metropolis[85082:3529622] 8.5.0 - [Firebase/Auth][I-AUT000017] Has valid access token. Estimated expiration date: 2021-08-07 06:08:31 +0000, current date: 2021-08-07 05:29:28 +0000
2021-08-07 15:29:28.468654+1000 Metropolis[85082:3529622] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) watch: <ListenRequest 0x70000497f338>: {
  database: "projects/metropolis-devel/databases/(default)"
  add_target {
    documents {
      documents: "projects/metropolis-devel/databases/(default)/documents/user/MWB5EmQ8SlVcMNzcGAxXnr5Nb1u1"
    }
    resume_token: "\n\t\010\355\360\204\XXXX"
    target_id: 2
  }
}
2021-08-07 15:29:28.684267+1000 Metropolis[85082:3529622] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) headers (allowlisted): date: Sat, 07 Aug 2021 05:29:28 GMT
2021-08-07 15:29:28.684852+1000 Metropolis[85082:3529622] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) response: <ListenResponse 0x70000497f098>: {
  target_change {
    target_change_type: ADD
    target_ids: 2
  }
}
2021-08-07 15:29:28.685321+1000 Metropolis[85082:3529622] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) headers (allowlisted): date: Sat, 07 Aug 2021 05:29:28 GMT
2021-08-07 15:29:28.685841+1000 Metropolis[85082:3529622] 8.5.0 - [Firebase/Firestore][I-FST000001] WatchStream (6000021dc918) response: <ListenResponse 0x70000497f098>: {
  target_change {
    resume_token: "\n\t\010\355\360\204\XXXX"
    read_time {
      seconds: 1628313380
      nanos: 534381000
    }
  }
}

@rizafran
Copy link
Contributor

rizafran commented Aug 9, 2021

Hi @kwan-research, the error message you reported is usually caused by no connection from your device to your database, possibly due to network issues. With this, could you provide/try the following:

  • Confirmation if you are under a proxy network. Some carriers could block the connection with Firebase.
  • Try to run the app under different networks and using different devices, just to see if you are able to determine a pattern.
  • Try reproducing the issue with the Quickstart app: https://github.com/firebase/quickstart-ios/tree/master/firestore

Thanks.

@kwan-research
Copy link
Author

I've encountered the problem both at home (fibre + wifi) and in a co-working space (wifi). In both locations the wifi is excellent, suitable for video-conferencing. It occurs on both a physical device (iPhone 7) and various simulators.

I don't have any proxies in place. If it was a proxy issue, the app would never reach the server, ever. But most of the time it connects immediately, and when it does have a problem it connects eventually (but it can take minutes).

Note the Firebase authentication and messaging always work fine. This problem only affects Firestore, and seems to be caused by grpc.

I'm not sure if the Quickstart app will reproduce the problem, because it looks like it will run happily in offline mode, so the grpc problems won't affect it.

@kwan-research
Copy link
Author

FYI, this problem doesn't occur in the Android version of the app, which uses equivalent Firestore calls.

@thebrianchen
Copy link

@kwan-research Thanks for writing in. Could you try to reproduce the problem on the Quickstart app? While the app does support offline mode, it will continue to try reconnecting with the Firestore servers while it is offline.

Can you also try to maintain a connection to the Firestore API endpoint URL separately outside of the SDK? This way, we can be sure that the connection failures are exclusively part of the SDK. Thanks!

@kwan-research
Copy link
Author

Same problem in the Quickstart app. These are the logs when I ran in a simulator (iPhone 11 pro max) and didn't interact with the app.

2021-08-13 13:01:27.033059+1000 FirestoreExample[45279:976489] 8.2.0 - [Firebase/Analytics][I-ACS023007] Analytics v.8.2.0 started
2021-08-13 13:01:27.033367+1000 FirestoreExample[45279:976489] 8.2.0 - [Firebase/Analytics][I-ACS023008] To enable debug logging set the following application argument: -FIRAnalyticsDebugEnabled (see http://goo.gl/RfcP7r)
2021-08-13 13:01:27.166365+1000 FirestoreExample[45279:976483] 8.2.0 - [Firebase/Analytics][I-ACS800023] No pending snapshot to activate. SDK name: app_measurement
2021-08-13 13:01:27.179958+1000 FirestoreExample[45279:976487] 8.2.0 - [Firebase/Analytics][I-ACS023012] Analytics collection enabled
2021-08-13 13:01:27.180181+1000 FirestoreExample[45279:976487] 8.2.0 - [Firebase/Analytics][I-ACS023220] Analytics screen reporting is enabled. Call +[FIRAnalytics logEventWithName:FIREventScreenView parameters:] to log a screen view event. To disable automatic screen reporting, set the flag FirebaseAutomaticScreenReportingEnabled to NO (boolean) in the Info.plist
2021-08-13 13:01:38.618088+1000 FirestoreExample[45279:976483] 8.2.0 - [Firebase/Firestore][I-FST000001] Could not reach Cloud Firestore backend. Backend didn't respond within 10 seconds.
 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-08-13 13:01:57.345856+1000 FirestoreExample[45279:976483] [] nw_protocol_get_quic_image_block_invoke dlopen libquic failed
2021-08-13 13:02:27.666132+1000 FirestoreExample[45279:977112] 8.2.0 - [Firebase/Firestore][I-FST000001] WatchStream (60000350db18) Stream error: 'Unavailable: DNS resolution failed'
2021-08-13 13:02:27.692722+1000 FirestoreExample[45279:977113] 8.2.0 - [Firebase/Firestore][I-FST000001] WatchStream (60000350db18) Stream error: 'Unavailable: DNS resolution failed'
2021-08-13 13:02:29.122805+1000 FirestoreExample[45279:977113] 8.2.0 - [Firebase/Firestore][I-FST000001] WatchStream (60000350db18) Stream error: 'Unavailable: DNS resolution failed'
2021-08-13 13:02:31.312118+1000 FirestoreExample[45279:977113] 8.2.0 - [Firebase/Firestore][I-FST000001] WatchStream (60000350db18) Stream error: 'Unavailable: DNS resolution failed'
2021-08-13 13:02:34.469848+1000 FirestoreExample[45279:976767] 8.2.0 - [Firebase/Firestore][I-FST000001] WatchStream (60000350db18) Stream error: 'Unavailable: DNS resolution failed'
2021-08-13 13:02:39.511396+1000 FirestoreExample[45279:977113] 8.2.0 - [Firebase/Firestore][I-FST000001] WatchStream (60000350db18) Stream error: 'Unavailable: DNS resolution failed'
2021-08-13 13:02:44.457597+1000 FirestoreExample[45279:977113] 8.2.0 - [Firebase/Firestore][I-FST000001] WatchStream (60000350db18) Stream error: 'Unavailable: DNS resolution failed'
2021-08-13 13:02:56.777689+1000 FirestoreExample[45279:977477] 8.2.0 - [Firebase/Firestore][I-FST000001] WatchStream (60000350db18) Stream error: 'Unavailable: DNS resolution failed'
2021-08-13 13:03:15.510957+1000 FirestoreExample[45279:977635] 8.2.0 - [Firebase/Firestore][I-FST000001] WatchStream (60000350db18) Stream error: 'Unavailable: DNS resolution failed'
2021-08-13 13:03:33.890614+1000 FirestoreExample[45279:977641] 8.2.0 - [Firebase/Firestore][I-FST000001] WatchStream (60000350db18) Stream error: 'Unavailable: DNS resolution failed'
2021-08-13 13:03:50.564804+1000 FirestoreExample[45279:978493] 8.2.0 - [Firebase/Firestore][I-FST000001] WatchStream (60000350db18) Stream error: 'Unavailable: DNS resolution failed'

I ran it a second time, waited for the "could not reach backend" message, then successfully set up an account in the app with email and password. But shortly after the DNS resolution failure messages still appeared.

So it looks like Firebase Auth is connecting successfully, while Firestore is failing.

I'm not sure what you mean by maintaining a connection to the Firestore API endpoint URL. I tried loading this URL in a Chrome browser, and it always immediately failed with the expected 403 permission denied.

@kwan-research
Copy link
Author

It took a few tries, but I got the quickstart to generate the same errors on my iPhone 7 as well.

To summarize, connection failures occur on both

  • an iPhone 7, and all Xcode simulators on a Macbook Air (2020 intel model)
  • BoringSSL-GRPC version 0.0.7 (quickstart) and 0.7.2 (my app)
  • gRPC version 1.28.2 (quickstart) and 1.28.4 (my app)
  • Firebase version 8.2.0 (quickstart) and 8.5.0 (my app)
  • Cocoapods (quickstart) and Swift Package Manager (my app)

It's a long shot, but I'm in Sydney, Australia. Any chance the gRPC issue is triggered by round-trip latency?

@kwan-research
Copy link
Author

A couple more data points

  • In the quickstart demo the restaurant images appear in the app immediately, so we've got a fast connection to https://storage.googleapis.com/firestorequickstarts.appspot.com
  • when the app is running in offline mode, the Firestore database isn't being populated (I'm checking the Firebase console). It populates when the app finally connects. So both reads and writes are failing - not surprising if DNS isn't working. Although I'm surprised that gRPC has its own DNS logic.

@thebrianchen
Copy link

@kwan-research Thanks for the data points! No obvious cause stands out at the moment, but I will dig into this some more.

@kwan-research
Copy link
Author

Let me know if there are any more tests I can run or logs that I can enable. This is a P1 for me - I don't want to risk App Store submission when launch times can take a few minutes.

@thebrianchen
Copy link

@kwan-research I've been trying to reproduce this without success unfortunately. For me, the quickstart app never showed the DNS resolution failed error after ~20 tries. Not sure why this is the case.

@rizafran Can you try reproducing the error on quickstart?

@kwan-research
Copy link
Author

Disregard previous (deleted) comment regarding credentials. It was a red herring.

I just realized that I can edit Pod files, so I've added log messages to the Firestore code in quickstart and narrowed down the cause.

In firebase-ios-sdk/Firestore/core/src/remote/grpc_stream.cc it's taking a really long time to get the first call to GrpcStream::OnRead. So it looks like the problem is further down, in the grpc stack. I'll keep looking.

@kwan-research
Copy link
Author

I enabled logging in the grpc stack, and the problem seems to be in DNS resolution.

D0822 17:53:10.106109000 123145440624640 ev_posix.cc:174]              Using polling engine: poll
D0822 17:53:10.106659000 123145440624640 dns_resolver.cc:314]          Using native dns resolver
D0822 17:53:10.266007000 123145440624640 dns_resolver.cc:261]          Start resolving.
I0822 17:54:10.275274000 123145446526976 dns_resolver.cc:197]          dns resolution failed (will retry): {"created":"@1629618850.275182000","description":"nodename nor servname provided, or not known","errno":8,"file":"/Users/mkwan/Xcode/quickstart-ios/firestore/Pods/gRPC-Core/src/core/lib/iomgr/resolve_address_posix.cc","file_line":108,"os_error":"nodename nor servname provided, or not known","syscall":"getaddrinfo","target_address":"firestore.googleapis.com"}
D0822 17:54:10.275992000 123145446526976 dns_resolver.cc:214]          retrying in 1000 milliseconds
D0822 17:54:11.275280000 123145447063552 dns_resolver.cc:261]          Start resolving.
I0822 17:55:11.288410000 123145446526976 dns_resolver.cc:197]          dns resolution failed (will retry): {"created":"@1629618911.288325000","description":"nodename nor servname provided, or not known","errno":8,"file":"/Users/mkwan/Xcode/quickstart-ios/firestore/Pods/gRPC-Core/src/core/lib/iomgr/resolve_address_posix.cc","file_line":108,"os_error":"nodename nor servname provided, or not known","syscall":"getaddrinfo","target_address":"firestore.googleapis.com"}
D0822 17:55:11.289002000 123145446526976 dns_resolver.cc:214]          retrying in 1281 milliseconds
D0822 17:55:12.570754000 123145448136704 dns_resolver.cc:261]          Start resolving.

These are the messages when it finally connects.

I0822 18:00:35.452397000 123145446526976 dns_resolver.cc:197]          dns resolution failed (will retry): {"created":"@1629619235.452311000","description":"nodename nor servname provided, or not known","errno":8,"file":"/Users/mkwan/Xcode/quickstart-ios/firestore/Pods/gRPC-Core/src/core/lib/iomgr/resolve_address_posix.cc","file_line":108,"os_error":"nodename nor servname provided, or not known","syscall":"getaddrinfo","target_address":"firestore.googleapis.com"}
D0822 18:00:35.452958000 123145446526976 dns_resolver.cc:214]          retrying in 17398 milliseconds
D0822 18:00:52.849423000 123145447063552 dns_resolver.cc:261]          Start resolving.
I0822 18:01:05.412318000 123145448136704 subchannel.cc:1055]           New connected subchannel at 0x60000387fa20 for subchannel 0x7f9db3554600

@kwan-research
Copy link
Author

Calls to getaddrinfo("firestore.googleapis.com", "https", &hints, &result) fail with EAI_NONAME in 30 seconds.
A followup call to getaddrinfo("firestore.googleapis.com", "443", &hints, &result) also fails with EAI_NONAME in 30 seconds.

@kwan-research
Copy link
Author

The underlying issues seems to be grpc's use of getaddrinfo. This is not recommended by Apple.

The Dart project ran into a similar issue here. It seems that getaddrinfo doesn't work properly on iOS when the LAN supports ipv6 but there's no ipv6 route to a DNS server.

In resolve_address_posix.cc I changed hints.ai_family = AF_UNSPEC; to AF_INET and the problem went away. Unfortunately that's not a long-term solution.

To reproduce, make sure dig -6 firestore.googleapis.com times out on your Mac, then run the quickstart app in a simulator. Or make sure your WiFi router doesn't support ipv6 DNS and try it on an iPhone with only WiFi enabled.

It sounds like you'll need to punt this to the grpc team.

@thebrianchen
Copy link

@kwan-research Thanks for investigating further and posting your findings! Can you open an issue with the grpc github repo directly? That way, the bug can be triaged and handled appropriately by the code-owners.

@kwan-research
Copy link
Author

kwan-research commented Aug 24, 2021

Punted to grpc/grpc#27092

In case anyone else runs into this problem, a (rather desperate) work-around is to use the CFHost API to do a dummy DNS lookup of firestore.googleapi.com at launch time. It appears to populate the DNS cache, so getaddrinfo returns immediately.

@paulb777
Copy link
Member

@kwan-research Thanks for sharing the thorough investigation!

@firebase firebase locked and limited conversation to collaborators Sep 23, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

5 participants