remote config realtime listener frequently cannot fetch current version of the template

[mikehardy]

Description

In wrapping the realtime remote config feature for react-native-firebase I have noticed that the iOS SDK frequently generates this error:

 AssertionError: error {"code":"config_update_not_fetched","message":"Unable to fetch the latest version of the template..","nativeErrorMessage":"Unable to fetch the latest version of the template.."}

This does not happen in the same tests using the near-identical firebase-android-sdk APIs

Reproducing the issue

1- create a cloud function that uses the firebase-admin-sdk to alter a remote config template (like perhaps this one https://github.com/invertase/react-native-firebase/blob/feat%2Fremote-config-onconfigupdated/.github/workflows/scripts/functions/src/testFunctionRemoteConfigUpdate.ts) and wraps that behind a POST API

2- create a test that adds an SDK listener for realtime remoteconfig changes

3- post to your cloud function to update the template

4- repeat 3 until it fails here:

firebase-ios-sdk/FirebaseRemoteConfig/Sources/RCNConfigRealtime.m

Lines 487 to 492 in 0e4aa6d

	NSError *error = [NSError errorWithDomain:FIRRemoteConfigUpdateErrorDomain
	code:FIRRemoteConfigUpdateErrorNotFetched
	userInfo:@{
	NSLocalizedDescriptionKey :
	@"Unable to fetch the latest version of the template."
	}];

Does the iOS SDK have different tunings with regard to retry intervals / retry count vs firebase-android-sdk? It's curious that I'm coming close to 100+ trials now and android has never had this while on iOS I see it maybe 10% of the time.

As a follow-on, I'm not sure how I can work around this at the react-native-firebase level, or what to prescribe to our users if this happens. Should they attempt to use directly / manually fetch the new config template? Will that potentially run into caching or throttling issues vs the realtime updates?

Firebase SDK Version

10.11.0

Xcode Version

14.3.1

Installation Method

CocoaPods

Firebase Product(s)

Remote Config

Targeted Platforms

iOS

Relevant Log Output

No response

If using Swift Package Manager, the project's Package.resolved

Expand Package.resolved snippet

Replace this line with the contents of your Package.resolved.

If using CocoaPods, the project's Podfile.lock

Expand Podfile.lock snippet

Replace this line with the contents of your Podfile.lock!

[google-oss-bot]

I couldn't figure out how to label this issue, so I've labeled it for a human to triage. Hang tight.

[mikehardy]

Here is an example workflow run showing the issue:

https://github.com/invertase/react-native-firebase/actions/runs/5329796344/jobs/9656036675

simulator log file attached to workflow with equivalent of FIRLogDebug enabled (though I do it at runtime by turning firebase-ios-sdk log level to debug with setLogLevel API) - https://github.com/invertase/react-native-firebase/actions/runs/5329796344

mike@kunashir:~/Desktop % cat -n simulator.log |grep RemoteConfig shows this:

208244	2023-06-21 04:04:06.838 Db NewsToday2[27539:16a0e] [com.apple.remoteconfiguration:RemoteConfiguration] Saved remote-configuration cache in 3.393962 ms
208249	2023-06-21 04:04:06.838 Db NewsToday2[27539:16a0e] [com.apple.remoteconfiguration:RemoteConfiguration] Cache Status:
227379	2023-06-21 04:04:13.282 Df weatherd[26871:16505] [com.apple.remoteconfiguration:RemoteConfiguration] <__NSCFLocalDataTask Task <39EA3679-9B84-4A52-9380-D07CE45BA17A>.<1>> finished
227380	2023-06-21 04:04:13.282 Df weatherd[26871:16505] [com.apple.remoteconfiguration:RemoteConfiguration] <RCURLFetchOperation 4A8F6B07035851DE> max-age missing from Cache-Control header for URL: https://weather-edge.apple.com/v1/configs
227381	2023-06-21 04:04:13.283 E  weatherd[26871:16505] [com.apple.remoteconfiguration:RemoteConfiguration] <RCURLFetchOperation 4A8F6B07035851DE> failed with error: Error Domain=NSURLErrorDomain Code=-1001 "The request timed out." UserInfo={_kCFStreamErrorCodeKey=-2102, NSUnderlyingError=0x600000f74b10 {Error Domain=kCFErrorDomainCFNetwork Code=-1001 "(null)" UserInfo={_kCFStreamErrorCodeKey=-2102, _kCFStreamErrorDomainKey=4}}, _NSURLErrorFailingURLSessionTaskErrorKey=LocalDataTask <39EA3679-9B84-4A52-9380-D07CE45BA17A>.<1>, _NSURLErrorRelatedURLSessionTaskErrorKey=(
227384	2023-06-21 04:04:13.283 E  weatherd[26871:16505] [com.apple.remoteconfiguration:RemoteConfiguration] <RCURLFetchOperation 4A8F6B07035851DE> failed to request configuration <RCConfigurationSettings: 0x600002558ae0; requestInfos: (
227387	2023-06-21 04:04:13.283 Df weatherd[26871:16505] [com.apple.remoteconfiguration:RemoteConfiguration] <RCEndpointOperation D2D8431941E3D60A> Endpoint JSON HTTP response status code: 0 (server error)
227388	2023-06-21 04:04:13.284 E  weatherd[26871:16505] [com.apple.remoteconfiguration:RemoteConfiguration] <RCEndpointOperation D2D8431941E3D60A> failed with error: Error Domain=NSURLErrorDomain Code=-1001 "The request timed out." UserInfo={_kCFStreamErrorCodeKey=-2102, NSUnderlyingError=0x600000f74b10 {Error Domain=kCFErrorDomainCFNetwork Code=-1001 "(null)" UserInfo={_kCFStreamErrorCodeKey=-2102, _kCFStreamErrorDomainKey=4}}, _NSURLErrorFailingURLSessionTaskErrorKey=LocalDataTask <39EA3679-9B84-4A52-9380-D07CE45BA17A>.<1>, _NSURLErrorRelatedURLSessionTaskErrorKey=(
227392	2023-06-21 04:04:13.284 E  weatherd[26871:16505] [com.apple.remoteconfiguration:RemoteConfiguration] endpoint operation failed with error: Error Domain=NSURLErrorDomain Code=-1001 "The request timed out." UserInfo={_kCFStreamErrorCodeKey=-2102, NSUnderlyingError=0x600000f74b10 {Error Domain=kCFErrorDomainCFNetwork Code=-1001 "(null)" UserInfo={_kCFStreamErrorCodeKey=-2102, _kCFStreamErrorDomainKey=4}}, _NSURLErrorFailingURLSessionTaskErrorKey=LocalDataTask <39EA3679-9B84-4A52-9380-D07CE45BA17A>.<1>, _NSURLErrorRelatedURLSessionTaskErrorKey=(
271553	2023-06-21 04:04:31.157 Db weatherd[26871:164fc] [com.apple.remoteconfiguration:RemoteConfiguration] <RCURLFetchOperation 1049A1553AD06E4B> finished with total time: 17.030199
271566	2023-06-21 04:04:31.157 Df weatherd[26871:164fc] [com.apple.remoteconfiguration:RemoteConfiguration] <RCURLFetchOperation 1049A1553AD06E4B> successfully received configuration https://c.apple.news/AgEdY29uZmlndXJhdGlvbi13ZWF0aGVyMi0xNDM0NDEAMTc with size: 2 KB, total time: 17.030124
271567	2023-06-21 04:04:31.158 E  weatherd[26871:164fc] [com.apple.remoteconfiguration:RemoteConfiguration] missing integer value for key: appConfigRefreshRate defaultValue: 300
271568	2023-06-21 04:04:31.158 E  weatherd[26871:164fc] [com.apple.remoteconfiguration:RemoteConfiguration] missing string value for key: widgetConfigurationEndpointUrl defaultValue: (null)
271569	2023-06-21 04:04:31.158 E  weatherd[26871:164fc] [com.apple.remoteconfiguration:RemoteConfiguration] missing string value for key: todayConfigurationEndpointUrl defaultValue: (null)
271570	2023-06-21 04:04:31.158 E  weatherd[26871:164fc] [com.apple.remoteconfiguration:RemoteConfiguration] missing integer value for key: userSegmentationBackgroundRefreshRate defaultValue: 3600
271571	2023-06-21 04:04:31.158 E  weatherd[26871:164fc] [com.apple.remoteconfiguration:RemoteConfiguration] missing dictionary value for key: widgetConfiguration
271572	2023-06-21 04:04:31.158 Df weatherd[26871:164fc] [com.apple.remoteconfiguration:RemoteConfiguration] creating user segmentation config with foreground refresh rate: 86400 background refresh rate: 3600 modMax: 1000 modThreshold: 1000
271573	2023-06-21 04:04:31.158 Df weatherd[26871:164fc] [com.apple.remoteconfiguration:RemoteConfiguration] creating user segmentation config with endpointURL: https://weather-edge.apple.com/v1/configs widgetEndpointURL: (null) todayEndpointURL: (null)
272535	2023-06-21 04:04:31.465 Df weatherd[26871:162d9] [com.apple.remoteconfiguration:RemoteConfiguration] <RCFallbackOperation E84920C18692A131> fallback: received configuration with requestKey: weather2ConfigRequest lastFetchedDate: Wed Jun 21 04:04:31 2023 maxAge: 600 etag: "303138346534646135633365393335323430613536333735363238333731343031383331373539663165" lastModified: Mon, 12 Jun 2023 22:48:17 GMT treatmentIDs: (null) segmentSetIDs: (null)
272536	2023-06-21 04:04:31.465 Db weatherd[26871:162d9] [com.apple.remoteconfiguration:RemoteConfiguration] <RCFallbackOperation E84920C18692A131> finished with total time: 18.169503
272954	2023-06-21 04:04:31.649 Df weatherd[26871:164fc] [com.apple.remoteconfiguration:RemoteConfiguration] <RCFallbackOperation 35DE5C1B36A80C47> fallback: received configuration with requestKey: weather2ConfigRequest lastFetchedDate: Wed Jun 21 04:04:31 2023 maxAge: 600 etag: "303134333036333536326433666336313862396234646361346166363331383135363365396563646530" lastModified: Mon, 12 Jun 2023 22:38:57 GMT treatmentIDs: (null) segmentSetIDs: (null)
272956	2023-06-21 04:04:31.649 Db weatherd[26871:164fc] [com.apple.remoteconfiguration:RemoteConfiguration] <RCFallbackOperation 35DE5C1B36A80C47> finished with total time: 17.523711
371739	2023-06-21 04:05:23.474 Df NewsToday2[27539:17d96] [com.apple.remoteconfiguration:RemoteConfiguration] returning the cached configuration for requestKeys: appConfigRequest treatmentIDs: (null) segmentSetIDs: (null)
397360	2023-06-21 04:05:33.121 Df testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000072] New config database created. Resetting user defaults.
434166	2023-06-21 04:05:51.623 Db testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000015] Received config update message on stream.
461694	2023-06-21 04:06:02.787 Df testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000053] A fetch is already in progress. Ignoring duplicate request.
465251	2023-06-21 04:06:04.384 Db testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000016] Fetched config's template version is outdated, re-fetching
486640	2023-06-21 04:06:14.175 Db testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000016] Fetched config's template version is outdated, re-fetching
508629	2023-06-21 04:06:24.554 Df testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000053] A fetch is already in progress. Ignoring duplicate request.
529494	2023-06-21 04:06:34.074 Df testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000053] A fetch is already in progress. Ignoring duplicate request.
532656	2023-06-21 04:06:35.631 Db testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000066] Successfully read configSettings. Minimum Fetch Interval:43200.000000, Fetch timeout: 60.000000
539941	2023-06-21 04:06:39.184 Db testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000016] Fetched config's template version is outdated, re-fetching
543206	2023-06-21 04:06:40.687 Df testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000053] A fetch is already in progress. Ignoring duplicate request.
554491	2023-06-21 04:06:46.289 Df testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000053] A fetch is already in progress. Ignoring duplicate request.
564592	2023-06-21 04:06:53.005 Db testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000016] Fetched config's template version is outdated, re-fetching
574855	2023-06-21 04:06:58.225 Db testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000066] Successfully read configSettings. Minimum Fetch Interval:43200.000000, Fetch timeout: 60.000000
574975	2023-06-21 04:06:58.275 Db testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000015] Received config update message on stream.
575261	2023-06-21 04:06:58.374 Db testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000016] Fetched config's template version is outdated, re-fetching
576804	2023-06-21 04:06:59.041 Df testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000053] A fetch is already in progress. Ignoring duplicate request.
578588	2023-06-21 04:06:59.890 Df testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000053] A fetch is already in progress. Ignoring duplicate request.
578778	2023-06-21 04:07:00.021 Db testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000016] Fetched config's template version is outdated, re-fetching
579848	2023-06-21 04:07:00.509 Df testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000011] Ran out of fetch attempts, cannot find target config version.
580011	2023-06-21 04:07:00.610 Db testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000066] Successfully read configSettings. Minimum Fetch Interval:43200.000000, Fetch timeout: 60.000000
580442	2023-06-21 04:07:00.781 Db weatherd[26871:164f5] [com.apple.remoteconfiguration:RemoteConfiguration] Loaded remote-configuration cache in 4.552859 ms
580443	2023-06-21 04:07:00.784 Db weatherd[26871:164f5] [com.apple.remoteconfiguration:RemoteConfiguration] loaded configuration resource: <RCConfigurationResource: 0x600002a596c0; requestKey: weather2ConfigRequest configurationID: (null) contentHash: (null) lastModified: (null), etag: "303134333036333536326433666336313862396234646361346166363331383135363365396563646530" lastModifiedFallback: Mon, 12 Jun 2023 22:38:57 GMT lastFetched: 2023-06-21 04:04:31 +0000 fallbackMaxAge: 600 endpointMaxAge: (null) userSegmentationConfig: <RCUserSegmentationConfiguration: 0x600001441b80; foregroundRefreshRate: 86400
582096	2023-06-21 04:07:01.486 Db testing[28484:175f3] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000066] Successfully read configSettings. Minimum Fetch Interval:43200.000000, Fetch timeout: 60.000000
614353	2023-06-21 04:07:16.574 Db testing[28484:176dd] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000016] Fetched config's template version is outdated, re-fetching
618288	2023-06-21 04:07:18.155 Df testing[28484:176dd] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000053] A fetch is already in progress. Ignoring duplicate request.
621566	2023-06-21 04:07:19.373 Df testing[28484:176dd] (Detox) 10.11.0 - [FirebaseRemoteConfig][I-RCN000011] Ran out of fetch attempts, cannot find target config version.

It looks to me like it is somehow confused on the target version to fetch, perhaps it is attempting to fetch an outdated template version, or if it has the correct / new version to fetch it is somehow retrieving an outdated one via caching or, similar.

My template-update cloud function returns the new template version, perhaps instrumenting the firebase-ios-sdk code with more information about the version it is trying to fetch when it gets an update notice on the realtime socket would be informative

[mikehardy]

@paulb777 you may be interested in this personally because of the e2e testing style I chose while doing realtime remote-config for react-native-firebase vs the one chosen for FlutterFire. I wasn't comfortable releasing the feature without truly testing it and I realized firebase-admin-sdk in a cloud function could generate template updates on demand. This is how I'm able to beat up on these APIs and see this as well as the listener removal one.

Not sure how I could have probed the API otherwise since there's no remote-config emulator to POST to trigger changes. I think at the SDK level you could maybe set up some test infra to simulate it though with mocked out stream event generators / mocked out fetch server that can send incremented templates etc. It is kind of hard to test!

[qdpham13]

Hey @mikehardy looking into this issue now. For this situation, based on your logs, I think the issue that is happening is that the real-time fetch runs into a isFetchInProgress check and essentially wastes a real-time initiated fetch if it coincides with a previous fetch. Android does not have a isFetchInProgress check so that would explain why iOS only sees this issue. One thing we could do is increase the number of fetchAttempts and see if that fixes your issue temporarily while we work on a longer term fix.

[mikehardy]

Okay, if you have a proposal for the change I can test pretty quickly

[qdpham13]

#11465

If this doesn't work, we can remove the check for real-time fetches only

[mikehardy]

I will try bumping it from 3 to 5 as per the PR but it makes me a bit anxious since it is likely network latency dependent and I think it will just lower vs eliminate the issue. I know it isn't a democracy, but if I had a vote, I think there's reasonable technical argument to remove the check so it works similar to android sdk where I have 0% incidence of this problem...

[qdpham13]

I understand your reasoning but I would like to see if this smaller change might possibly fix the issue before we move directly to this larger, possibly more impactful change. The isFetchInProgress check has been in this SDK pre-realtime so we're not sure if it might have any unintended affects. So it would also require more time on our side to test and check this change. I'll look into removing the check but for now if this fix unblocks you I think it would make sense to use it in the meantime.

[mikehardy]

sure sure :-) - it's in progress just now: https://github.com/invertase/react-native-firebase/actions/runs/5338881748

I brutally hacked it in via an in-place sed in the workflow (since we use cocoapods and install the pods in CI) with this chunk of bash script in yaml: invertase/react-native-firebase@742786a#diff-44ad6c65525e95d58b775ffb43411bea2d1fc6c53b07a8b4bccfc74975a8caa1R140-R147

The in-place edit is an opportunity for an unrelated failure but I print out the value of gFetchAttempts before and after the edit attempt which should show up in the workflow log for positive confirmation we are testing what we think we are testing.

edit: patch worked, gFetchAttempts is 5 now in the test run currently happening https://github.com/invertase/react-native-firebase/actions/runs/5338881748/jobs/9676863650#step:18:16

ETA for results is around 20 minutes from now

[mikehardy]

Ran successful first time. I'll rerun a few times in an effort to get statistical significance