Keychain not always ready to read encrypted key on startup

[JoniVR]

Follow-up issue from #231.

I left in the automatic detection of this issue and I'm still getting this sometimes in production. This automatic detection in production also gives a better sense of the amount of times the issue was actually occurring.

I've received 18 reports from 11 different users (with around 1400 iOS users in total) just today and yesterday combined.

Some of these reports clearly showcase the workaround working, for example:

0 | Thu Apr 21 2022 00:58:52 | DEBUG | ios | MMKV:encryptedStorage.getString | undefined
1 | Thu Apr 21 2022 00:58:52 | ERROR | ios | MMKV:encryptedStorage.getString | Expected null is not null
2 | Thu Apr 21 2022 00:58:58 | DEBUG | ios | persistErrorHandlerMiddleware | Rehydrating auth, token: eyJhbG...byZ3LY
3 | Thu Apr 21 2022 00:58:58 | DEBUG | ios | AuthService:refreshAuthToken | Attempting token refresh with: PQTUZ1...KdN9o=

Notice how there's a 6s delay between line 1 -> 2 => indicates the delay worked

Other reports don't show a delay and also seem to still log the user out:

0 | Wed Apr 20 2022 21:13:31 | DEBUG | ios | MMKV:encryptedStorage.getString | undefined
1 | Wed Apr 20 2022 21:13:31 | ERROR | ios | MMKV:encryptedStorage.getString | Expected null is not null
2 | Wed Apr 20 2022 21:13:31 | DEBUG | ios | persistErrorHandlerMiddleware | Rehydrating auth, token: null
3 | Wed Apr 20 2022 21:13:31 | DEBUG | ios | App | Notification permission status: 1
4 | Wed Apr 20 2022 21:13:31 | DEBUG | ios | setMessagingToken | OS: ios, Token: cJyUje...7-QCo4
5 | Wed Apr 20 2022 21:13:31 | DEBUG | ios | httpInterceptor:responseHandler | {
"requestUrl": "/endpoints.emergency.json",
"responseCode": 200,
"bearer": null
}

So, for some reason the delay isn't always happening.. any ideas as to why?

edit: a third kind of log:

0 | Thu Apr 21 2022 14:28:47 | DEBUG | ios | MMKV:encryptedStorage.getString | undefined
1 | Thu Apr 21 2022 14:28:47 | ERROR | ios | MMKV:encryptedStorage.getString | Expected null is not null
2 | Thu Apr 21 2022 16:45:38 | DEBUG | ios | persistErrorHandlerMiddleware | Rehydrating auth, token: null

Here the timing between the "read" and actual re-hydration seems to be +2hrs, which I think indicates that the app launched in the background?

Originally posted by @JoniVR in https://github.com/ammarahm-ed/react-native-mmkv-storage/issues/195#issuecomment-1105169137

[JoniVR]

About one week later, stats on this issue are: 49/1400 users affected, 98 times occurrence, with around 30-40% (rough guess) where the new workaround works.

[JoniVR]

Are there any other workarounds that might work better? For example setting accessibility level to kSecAttrAccessibleAlways (not as secure though)?

[ammarahm-ed]

Hey @JoniVR Another way would be to not block the main thread and instead wait asynchronously in JS using a simple getItem function that the setItem function from MMKV. Something like this:

const MMKV = MMKV.storage.initialize();
const PersistStorage = {
    setItem:MMKV.setItem,
    removeItem:MMKV.removeItem,
   getAllKeys: MMKV.indexer.getKeys,
    getItem:async (key) => {

return new Promise(resolve => {
 // Fetch the value from storage
       const value = MMKV.getItem(key);
// Check if value is undefined
      if (value === undefined) {
// Set a timeout and retry getting the key after a delay
       setTimeout(() => { 
// Add some logging here if needed to check instance is ready etc as we did earlier.
resolve(PersistStorage.getItem(key)) 

},500);
} else {
// Value is found, resolve promise.
  resolve(value);
}
})

}
}

Let me know if this looks ok

[JoniVR]

@ammarahm-ed Looks okay to me, will be patching out the native fix for now...

edit: seems like I needed to tweak it a bit:

const PersistStorage = {
  setItem: encryptedStorage.setItem,
  removeItem: encryptedStorage.removeItem,
  getAllKeys: encryptedStorage.indexer.getKeys,
  setStringAsync: encryptedStorage.setStringAsync,
  setString: encryptedStorage.setString,
  getItem: async (key: any) => {
    return new Promise(resolve => {
      // Fetch the value from storage
      const value = encryptedStorage.getItem(key);
      // Check if value is undefined
      if (value === undefined) {
        // Set a timeout and retry getting the key after a delay
        setTimeout(() => {
          // Add some logging here if needed to check instance is ready etc as we did earlier.
          resolve(PersistStorage.getItem(key));
        }, 200);
      } else {
        // Value is found, resolve promise.
        resolve(value);
      }
    });
  },
};

[ammarahm-ed]

@ammarahm-ed Looks okay to me, will be patching out the native fix for now...

edit: seems like I needed to tweak it a bit:

const PersistStorage = {
  setItem: encryptedStorage.setItem,
  removeItem: encryptedStorage.removeItem,
  getAllKeys: encryptedStorage.indexer.getKeys,
  setStringAsync: encryptedStorage.setStringAsync,
  setString: encryptedStorage.setString,
  getItem: async (key: any) => {
    return new Promise(resolve => {
      // Fetch the value from storage
      const value = encryptedStorage.getItem(key);
      // Check if value is undefined
      if (value === undefined) {
        // Set a timeout and retry getting the key after a delay
        setTimeout(() => {
          // Add some logging here if needed to check instance is ready etc as we did earlier.
          resolve(PersistStorage.getItem(key));
        }, 200);
      } else {
        // Value is found, resolve promise.
        resolve(value);
      }
    });
  },
};

Any new reports

[jaltin]

We are also still seeing this issue in our app after we updated to v 0.7.0 (related to issue #231).

We will also try with the setTimeout fix you suggest @JoniVR, and will let you know how that goes.

[JoniVR]

@jaltin Good! We're currently not in beta testing phase yet for the next version so I can only start testing in a few weeks unfortunately..

[jaltin]

@jaltin Good! We're currently not in beta testing phase yet for the next version so I can only start testing in a few weeks unfortunately..

Did you also have a native fix in the pipeline for this or is the js fix the way to go long term?

[JoniVR]

I personally patched out the native fix since it wasn't fully solving the issue anyways and the JS method should do something similar (hopefully better).

Here's my patch file contents:

diff --git a/node_modules/react-native-mmkv-storage/ios/SecureStorage.m b/node_modules/react-native-mmkv-storage/ios/SecureStorage.m
index 1c4e1c2..92ec0e7 100644
--- a/node_modules/react-native-mmkv-storage/ios/SecureStorage.m
+++ b/node_modules/react-native-mmkv-storage/ios/SecureStorage.m
@@ -45,14 +45,6 @@ - (NSString *) getSecureKey:(NSString *)key
     @try {
         [self handleAppUninstallation];
         NSString *value = [self searchKeychainCopyMatching:key];
-        dispatch_sync(dispatch_get_main_queue(), ^{
-            int readAttempts = 0;
-            // See: https://github.com/ammarahm-ed/react-native-mmkv-storage/issues/195
-            while (![[UIApplication sharedApplication] isProtectedDataAvailable] && readAttempts++ < 100) {
-                // sleep 25ms before another attempt
-                usleep(25000);
-            }
-        });
         if (value == nil) {
             NSString* errorMessage = @"key does not present";

You could also revert to the version before the fix, might be easier.

My thinking was the reason the native fix might not work could be because we're blocking the main thread (and thus all app execution) which prevents the protected data from becoming available too.. Though I'm not 100% sure that's the issue, just my best guess.

Could also be that it's really an Apple related bug where the protected data just doesn't become available at all.... in which case the JS way of patching it currently will let the user wait forever, so perhaps it still needs some sort of max attempt limit. Or would redux-persist time-out in this case?

[jaltin]

Could also be that it's really an Apple related bug where the protected data just doesn't become available at all.... in which case the JS way of patching it currently will let the user wait forever, so perhaps it still needs some sort of max attempt limit. Or would redux-persist time-out in this case?

We thought the same, so we are waiting 200 ms between tries and only tries 5 times. If it still fails we show an alert asking the user to restart the app (which often solves the issue for us). Dirty hack but hoping it will duct tape the issue for now.

[JoniVR]

Yes, that sounds like a pretty good temporary mitigation, usually restarting will resolve the issue.. might actually implement that too for the time being :)

[jaltin]

@JoniVR , an update on the fix we have applied. We released it in production a few days ago and we are seeing the fix being applied for some users.

For some it works ok to wait 200 ms a few times, but for others it still doesn't work (so they get the alert asking them to restart the app).

@ammarahm-ed do you have any idea if this is fixable in the native part?

[JoniVR]

@jaltin The previous fix did the same thing in the native side. I'm not sure what's going wrong. Seems weird to have to wait 200ms in any case.

The native fix in some cases waited the full 10s before still failing. Could be that the value simply doesn't become available at all.

This feels like an Apple bug to me, unless I'm missing something.

[JoniVR]

I have a new theory.

I think the reason we're still seeing errors despite the workaround might be due to the fact that isProtectedDataAvailable always returns false in the background. Our app supports background refresh, meaning the app will launch itself in the background occasionally, in this case we will always get this error.

I haven't had any actual manual user reports on the issues since the fix (though it could just be that nobody bothered to report it yet). I've added an extra log line to the next beta build to log the AppState.currentState to confirm this suspicion. Will keep you updated!

@jaltin, does your app also happen to use/support background app refresh?

[ammarahm-ed]

@JoniVR That could be the case. What if the app enters from background to foreground? at the point is there a way to make protected data available again to the user?

But yes, if for example that app wakes up in background through a silent notification or something and it checks for the info in key chain to send a request to the API, that won't work since that data can't be accessed in background state.

[JoniVR]

@ammarahm-ed Yes, I'm still collecting more logging from beta users but from the 5 reports I got in latest build, 4 recovered the token correctly, example below:

0 | Sat May 21 2022 00:58:52 GMT+0200 | DEBUG | MMKV:encryptedStorage.getString | undefined
1 | Sat May 21 2022 00:58:52 GMT+0200 | DEBUG | configureStore:debugStorageIssue | App state: background
2 | Sat May 21 2022 00:58:52 GMT+0200 | ERROR | MMKV:encryptedStorage.getString | Expected null is not null
3 | Sat May 21 2022 00:59:40 GMT+0200 | DEBUG | persistErrorHandlerMiddleware | Rehydrating auth, token: eyJhbG...6VEWc0
4 | Sat May 21 2022 00:59:40 GMT+0200 | DEBUG | AuthService:refreshAuthToken | Attempting token refresh with: c6k53/...n/aFM=

And one failed recovering the token:

0 | Mon May 23 2022 02:50:08 GMT+0200 | DEBUG | MMKV:encryptedStorage.getString | undefined
1 | Mon May 23 2022 02:50:08 GMT+0200 | DEBUG | configureStore:debugStorageIssue | App state: background
2 | Mon May 23 2022 02:50:08 GMT+0200 | ERROR | MMKV:encryptedStorage.getString | Expected null is not null
3 | Mon May 23 2022 04:11:38 GMT+0200 | DEBUG | persistErrorHandlerMiddleware | Rehydrating auth, token: null
4 | Mon May 23 2022 04:11:38 GMT+0200 | DEBUG | App | Notification permission status: 1
5 | Mon May 23 2022 04:11:38 GMT+0200 | DEBUG | setMessagingToken | OS: ios, Token: cr5hJb...5x9KLv
6 | Mon May 23 2022 04:11:38 GMT+0200 | DEBUG | httpInterceptor:responseHandler | {
"requestUrl": "/endpoints.emergency.json",
"responseCode": 200,
"bearer": null
}

In all 5 cases, app state was background, so that's probably it.

The app is launched in the background (can indeed be multiple reasons: notification, background app refresh, ...) and then the store is instantiated and key is read, which then fails.

What probably happens after is that the app remains "frozen" in the background until the user opens it, the store is already instantiated but without key, so re-hydration fails?

You can see in the second example the persistErrorHandlerMiddleware is basically a redux middelware that only logs when auth is rehydrated. Also notice the big time difference between that line and the one before it.

Any ideas or suggestions on how we can work around this? An extra internal variable in the native side that remembers the isProtectedDataAvailablevariable and then retries instantiation on getString or something like that? Or perhaps in combination with checking if the app is in the background?

edit: what does confuse me though, by default the code seems to use kSecAttrAccessibleAfterFirstUnlock as keychain kSecAttrAccessible value, which should work in the background, so why isn't it working in the background then?

[JoniVR]

@ammarahm-ed Perhaps we can detect in the app if:

1. The app is in foreground
2. If the app is in the foreground and the storageKey == '' => reinitialize storage
3. Trigger manual redux-persist rehydrate somehow? (pretty sure this is possible)

Or just to simplify listen to the HYDRATE redux action and then check the key and reinit if necessary.

Doesn't fix the issue for non redux-persist cases but those can probably be worked around in a similar way.

[JoniVR]

@ammarahm-ed I think I may have found something, but I'm not sure and I'd really like a confirmation:

Is it possible that the JS side instantiates storage with IOSAccessibleStates.WHEN_UNLOCKED by default?

I'm asking this because this could be why (when the app is launched in the background due to a notification), the storage can't be read. It should be using IOSAccessibleStates.AFTER_FIRST_UNLOCK for that.

At first I thought (based on the native iOS code, which defaults no Accessibility value to AFTER_FIRST_UNLOCK) that this value was set correctly but after looking at the JS code I'm not really sure anymore. could you provide more info on this?

Am I correct in assuming that if this value is defaulted incorrectly, I should change my storage instantiation to:

export const encryptedStorage = new MMKVLoader()
  .setAccessibleIOS(IOSAccessibleStates.AFTER_FIRST_UNLOCK)
  .withInstanceID('encrypted') // different name causes storage to be recreated with correct AccessibleState
  .withEncryption()
  .initialize();