Firestore crashes on startup in offline mode while trying to refresh token when it has pending writes

[Olof-IL]

[REQUIRED] Please fill in the following fields:

• Pre-built SDK from the website or open-source from this repo: Prebuilt SDK
• Firebase C++ SDK version: 6.16.1
• Problematic Firebase Component: Firestore
• Other Firebase Components in use: Auth
• Platform you are using the C++ SDK on: Mac
• Platform you are targeting: iOS

[REQUIRED] Please describe the issue here:

(Please list the full steps to reproduce the issue. Include device logs, Unity logs, and stack traces if available.)

Steps to reproduce:

Issue is reproduceable with the firestore quickstart testapp, with the steps below:

1. Update firestore quickstart testapp so it builds with 6.16.1 SDK (minor fixes: new error_message parameter in AddSnapshotListener and kOk renamed to kErrorOk)
2. Comment out the " auth->SignOut();" call, so it stays signed in between runs and uses the cached token.
3. Run it once with internet connection.
4. Disable internet on the device
5. Run it again with disabled internet to make sure there is a pending write.
6. Wait until the token expires
7. Keep device offline, and try run testapp with expired token, and it crashes.

Repro rate: 100%

I get this error print in console before it crashes:

libc++abi.dylib: terminating with uncaught exception of type firebase::firestore::util::FirestoreInternalError: FIRESTORE INTERNAL ASSERTION FAILED: /Users/olle/Documents/git/quickstart-cpp/firestore/testapp/Pods/FirebaseFirestore/Firestore/core/src/remote/datastore.cc(326) static bool firebase::firestore::remote::Datastore::IsPermanentError(const firebase::firestore::util::Status &): Unknown status code: 19

the IsPermanentError function receives a status code 19, which is 3 higher then the highest error code in the enum, and HARD_FAIL:s

Full log output:

2020-11-11 18:01:06.730729+0100 testapp[2198:2135055] 6.32.0 - [Firebase/Core][I-COR000003] The default Firebase app has not yet been configured. Add `[FIRApp configure];` (`FirebaseApp.configure()` in Swift) to your application initialization. Read more: https://goo.gl/ctyzm8.
2020-11-11 18:01:06.807111+0100 testapp[2198:2135054] Initialized Firebase App.
2020-11-11 18:01:06.807354+0100 testapp[2198:2135054] Initializing Firebase Auth...
2020-11-11 18:01:06.848433+0100 testapp[2198:2135054] Initialized Firebase Auth.
2020-11-11 18:01:06.848517+0100 testapp[2198:2135054] Signing in...
2020-11-11 18:01:06.857362+0100 testapp[2198:2135066] Metal API Validation Enabled
2020-11-11 18:01:06.881137+0100 testapp[2198:2135050] 6.32.0 - [Firebase/Analytics][I-ACS031025] 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
2020-11-11 18:01:06.881544+0100 testapp[2198:2135050] 6.32.0 - [Firebase/Analytics][I-ACS800023] No pending snapshot to activate. SDK name: app_measurement
2020-11-11 18:01:06.881797+0100 testapp[2198:2135050] 6.32.0 - [Firebase/Analytics][I-ACS023007] Analytics v.60802000 started
2020-11-11 18:01:06.882004+0100 testapp[2198:2135050] 6.32.0 - [Firebase/Analytics][I-ACS023008] To enable debug logging set the following application argument: -FIRAnalyticsDebugEnabled (see http://goo.gl/RfcP7r)
2020-11-11 18:01:06.892552+0100 testapp[2198:2135063] 6.32.0 - [Firebase/Analytics][I-ACS800023] No pending snapshot to activate. SDK name: app_measurement
2020-11-11 18:01:06.911152+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Analytics][I-ACS023012] Analytics collection enabled
2020-11-11 18:01:06.955151+0100 testapp[2198:2135054] Signed in as an anonymous user, uid: 3PEv13aBO8ejwFZgGVbXkhS2Zwq2, email: .
2020-11-11 18:01:06.955466+0100 testapp[2198:2135054] Initialize Firebase Firestore.
2020-11-11 18:01:06.955545+0100 testapp[2198:2135054] Attempt to initialize Firebase Firestore.
2020-11-11 18:01:06.963473+0100 testapp[2198:2135054] Successfully initialized Firebase Firestore.
2020-11-11 18:01:06.965047+0100 testapp[2198:2135054] Successfully set Firestore settings.
2020-11-11 18:01:06.965182+0100 testapp[2198:2135054] Testing non-wrapping types.
2020-11-11 18:01:06.965263+0100 testapp[2198:2135054] Tested non-wrapping types.
2020-11-11 18:01:06.965335+0100 testapp[2198:2135054] Testing collections.
2020-11-11 18:01:06.968271+0100 testapp[2198:2135065] 6.32.0 - [Firebase/Firestore][I-FST000001] Initializing. Current user: 3PEv13aBO8ejwFZgGVbXkhS2Zwq2
2020-11-11 18:01:06.968685+0100 testapp[2198:2135054] Tested collections.
2020-11-11 18:01:06.968793+0100 testapp[2198:2135054] Testing documents.
2020-11-11 18:01:06.968859+0100 testapp[2198:2135054] Testing Set().
2020-11-11 18:01:06.976219+0100 testapp[2198:2135065] 6.32.0 - [Firebase/Firestore][I-FST000001] Using /var/mobile/Containers/Data/Application/F6DDED2F-13D9-4ABF-B42A-2BCD4ECC4C48/Library/Application Support/firestore/__FIRAPP_DEFAULT/quickstartappfirestore/main for LevelDB storage
2020-11-11 18:01:07.020723+0100 testapp[2198:2135065] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Start LevelDB: 0 changes (0 bytes):>
2020-11-11 18:01:07.029743+0100 testapp[2198:2135057] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Start MutationQueue: 0 changes (0 bytes):>
2020-11-11 18:01:07.030113+0100 testapp[2198:2135057] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:07.030512+0100 testapp[2198:2135057] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:07.030851+0100 testapp[2198:2135057] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:07.031194+0100 testapp[2198:2135057] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:07.031521+0100 testapp[2198:2135057] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:07.031840+0100 testapp[2198:2135057] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:22.281555+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:22.284009+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:22.292075+0100 testapp[2198:2135057] Connection 1: received failure notification
2020-11-11 18:01:22.292253+0100 testapp[2198:2135057] Connection 1: failed to connect 1:50, reason -1
2020-11-11 18:01:22.292384+0100 testapp[2198:2135057] Connection 1: encountered error(1:50)
2020-11-11 18:01:22.300819+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:22.302014+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] WriteStream (10fe1ca48) start
2020-11-11 18:01:22.302958+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Credential Changed. Current user: 3PEv13aBO8ejwFZgGVbXkhS2Zwq2
2020-11-11 18:01:22.304028+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] RemoteStore 280ac8400 restarting streams for new credential
2020-11-11 18:01:22.305126+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] WatchStream (280ac8a18) stop
2020-11-11 18:01:22.305928+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] WriteStream (10fe1ca48) stop
2020-11-11 18:01:22.309334+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Stopping write stream with 8 pending writes
2020-11-11 18:01:22.310319+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:22.311486+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:22.312635+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:22.313753+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:22.314748+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:22.315956+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:22.317028+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:22.318022+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:22.318274+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:22.319402+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] WriteStream (10fe1ca48) start
2020-11-11 18:01:22.320416+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Locally write mutations: 3 changes (116 bytes):
  - Put [collection_parent: collection_id=foo] (0 bytes)
  - Put [document_mutation: user_id=3PEv13aBO8ejwFZgGVbXkhS2Zwq2 path=foo/bar batch_id=25] (0 bytes)
  - Put [mutation: user_id=3PEv13aBO8ejwFZgGVbXkhS2Zwq2 batch_id=25] (116 bytes)>
2020-11-11 18:01:22.321397+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NotifyLocalViewChanges: 0 changes (0 bytes):>
2020-11-11 18:01:22.323972+0100 testapp[2198:2135057] Error getting network monitor context Error Domain=NSPOSIXErrorDomain Code=13 "Permission denied"
2020-11-11 18:01:22.324179+0100 testapp[2198:2135057] Task <7E026631-EC71-45DD-BF18-C44F42B6225C>.<1> HTTP load failed, 0/0 bytes (error code: -1009 [1:50])
2020-11-11 18:01:22.329163+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:22.329521+0100 testapp[2198:2135066] 6.32.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2020-11-11 18:01:22.336570+0100 testapp[2198:2135066] Task <7E026631-EC71-45DD-BF18-C44F42B6225C>.<1> finished with error [-1009] Error Domain=NSURLErrorDomain Code=-1009 "The Internet connection appears to be offline." UserInfo={_kCFStreamErrorCodeKey=50, NSUnderlyingError=0x2838bf3f0 {Error Domain=kCFErrorDomainCFNetwork Code=-1009 "(null)" UserInfo={_kCFStreamErrorCodeKey=50, _kCFStreamErrorDomainKey=1}}, _NSURLErrorFailingURLSessionTaskErrorKey=LocalDataTask <7E026631-EC71-45DD-BF18-C44F42B6225C>.<1>, _NSURLErrorRelatedURLSessionTaskErrorKey=(
    "LocalDataTask <7E026631-EC71-45DD-BF18-C44F42B6225C>.<1>"
), NSLocalizedDescription=The Internet connection appears to be offline., NSErrorFailingURLStringKey=https://securetoken.googleapis.com/v1/token?key=AIzaSyBWikDDSw5zun3GjLBmmtUSqn0yboaFop0, NSErrorFailingURLKey=https://securetoken.googleapis.com/v1/token?key=AIzaSyBWikDDSw5zun3GjLBmmtUSqn0yboaFop0, _kCFStreamErrorDomainKey=1}
2020-11-11 18:01:22.346608+0100 testapp[2198:2135057] Connection 2: received failure notification
2020-11-11 18:01:22.346712+0100 testapp[2198:2135057] Connection 2: failed to connect 1:50, reason -1
2020-11-11 18:01:22.346837+0100 testapp[2198:2135057] Connection 2: encountered error(1:50)
2020-11-11 18:01:22.350099+0100 testapp[2198:2135057] Task <85C87CC5-9FBC-40FB-98C5-76DD8476BD2C>.<1> HTTP load failed, 0/0 bytes (error code: -1009 [1:50])
2020-11-11 18:01:22.351119+0100 testapp[2198:2135057] Task <85C87CC5-9FBC-40FB-98C5-76DD8476BD2C>.<1> finished with error [-1009] Error Domain=NSURLErrorDomain Code=-1009 "The Internet connection appears to be offline." UserInfo={_kCFStreamErrorCodeKey=50, NSUnderlyingError=0x2838487e0 {Error Domain=kCFErrorDomainCFNetwork Code=-1009 "(null)" UserInfo={_kCFStreamErrorCodeKey=50, _kCFStreamErrorDomainKey=1}}, _NSURLErrorFailingURLSessionTaskErrorKey=LocalDataTask <85C87CC5-9FBC-40FB-98C5-76DD8476BD2C>.<1>, _NSURLErrorRelatedURLSessionTaskErrorKey=(
    "LocalDataTask <85C87CC5-9FBC-40FB-98C5-76DD8476BD2C>.<1>"
), NSLocalizedDescription=The Internet connection appears to be offline., NSErrorFailingURLStringKey=https://securetoken.googleapis.com/v1/token?key=AIzaSyBWikDDSw5zun3GjLBmmtUSqn0yboaFop0, NSErrorFailingURLKey=https://securetoken.googleapis.com/v1/token?key=AIzaSyBWikDDSw5zun3GjLBmmtUSqn0yboaFop0, _kCFStreamErrorDomainKey=1}
2020-11-11 18:02:12.216399+0100 testapp[2198:2135063] 6.32.0 - [Firebase/Firestore][I-FST000001] WriteStream (10fe1ca48) Stream error: 'Unknown code(19): Network error (such as timeout, interrupted connection or unreachable host) has occurred.'
libc++abi.dylib: terminating with uncaught exception of type firebase::firestore::util::FirestoreInternalError: FIRESTORE INTERNAL ASSERTION FAILED: /Users/olle/Documents/git/quickstart-cpp/firestore/testapp/Pods/FirebaseFirestore/Firestore/core/src/remote/datastore.cc(326) static bool firebase::firestore::remote::Datastore::IsPermanentError(const firebase::firestore::util::Status &): Unknown status code: 19
terminating with uncaught exception of type firebase::firestore::util::FirestoreInternalError: FIRESTORE INTERNAL ASSERTION FAILED: /Users/olle/Documents/git/quickstart-cpp/firestore/testapp/Pods/FirebaseFirestore/Firestore/core/src/remote/datastore.cc(326) static bool firebase::firestore::remote::Datastore::IsPermanentError(const firebase::firestore::util::Status &): Unknown status code: 19
(lldb) 

Relevant Code:

Reproducible with firestore quickstart testapp with the steps above, just make sure to update it to build with 6.16.1, update Pods to 6.32.2 and disable "auth->SignOut();" on line 130.

[Olof-IL]

It will crash as soon as there is a pending firestore write added while offline and the token is expired. Then it will keep crashing on startup even without further writes added.

This makes offline mode for firestore on iOS 100% broken and will continously crash any app using the firestore C++ sdk if you're offline for more then an hour or so.

[chkuang-g]

Hi Olof-IL,

Thank you for reporting this. I'll contact the team about the issue.

Shawn

[chkuang-g]

For reference, firebase/quickstart-unity#872 seems to be the same issue

[dconeybe]

I am investigating. Thanks for the great bug report and detailed reproduction steps!

[dconeybe]

I have found the root cause and have a fix. The bug is that we cast from a firebase::auth::AuthError to firebase::firestore::Error in credentials_provider_ios.cc and the mapping between these two enums using static_cast is not meaningful.

The error code 19 maps to AuthError::kAuthErrorNetworkRequestFailed, which makes sense since the device is offline.

The fix is to instead just use Error::kErrorUnknown instead of casting the error code from the Future to Error in the ConvertToken function in credentials_provider_ios.cc. Googlers can internally see the fix in cl/344296491.

Until this fix is released (which I unfortunately do not have an ETA for) the best workaround that I can think of is to remove the problematic assertion from Datastore::IsPermanentError(). To do this, edit Pods/FirebaseFirestore/Firestore/core/src/remote/datastore.cc and replace the line

HARD_FAIL("Unknown status code: %s", error.code());

with simply

return false;

[Olof-IL]

Great news!

I hope there will be a new public release of the Firebase C++ SDK soon. I've noticed it lags quite a far bit behind the iOS release, using 6.32.2 when iOS is at 7.1.0.

And also that the Firestore C++ API can leave alpha status soon... We were hoping to use it in production sometime in early 2021, but maybe that is too optimistic and we should seek other sollutions? Not having to do our own C++ wrappers of the iOS SDK saves us a lot of time though.

[dconeybe]

I completely understand your interest in seeing the Firestore C++ SDK graduating from "alpha" status. It will be an exciting day when that happens! Unfortunately, I cannot provide any guidance about when that will be and I am not sure when the next C++ release will be.

[dconeybe]

As an update to my previous comment (#182 (comment)) I can confirm that the fix for this bug will be included in the next C++ release; however, I do not have an ETA to provide. I'm going to close this ticket since there are no more actions to be taken on my part. However, if you find that the next release does not fix this issue then please re-open this ticket and we'll investigate.

Note to Googlers: b/174146134 is the internal ticket filed for the issue. The fix is cl/344844086.