forcedotcom / SalesforceMobileSDK-iOS

iOS SDK for Salesforce
Other
538 stars 421 forks source link

iOS 15 wakes the app up in the background, and SFDefaultUserAccountPersister deletes the UserAccount.plist #3437

Closed az-oolloow closed 2 years ago

az-oolloow commented 3 years ago

Please fill out the following details:

  1. Version of Mobile SDK Used: 9.2.0 using recommended forceios npm package method, 8.3.0 with legacy migration removed (also confirmed the code is the same in latest dev branch)
  2. Issue found in Native App or Hybrid App: Native App
  3. OS Version: 15.0 + (so also 15.0.1 and 15.0.2)
  4. Device: iPad (all sorts of iPad devices, new iPad mini 6, iPad Pro 9.7", iPad Pro 2018 etc.)
  5. Steps to reproduce:

Connect the device to the mac Open Console In the console, filter by Any AppName Build an app using SF SDK Login Make sure device has passcode/faceid/touch id Kill the app Lock the screen Wait until iOS wakes up your app in the background (typically under 30 minutes, I found no way to speed this up, sometimes launching and killing the app rapidly a few times causes iOS to decide to re-launch it just 1 minute after you killed it and sometimes it does take over 30 minutes). The symbol of this is the following log:

2247    default 14:14:22.847892+1100    logoutRepro Initializing connection

(you can see full log below, basically there will be a lot of messages, > 20 with the specified filter settings) Open the app again

  1. Actual behavior: User is logged out and is presented with a 'please log in'

  2. Expected Behavior: User is not logged out

  3. Analysis:

This issue stems from the fact that SFDefaultUserAccountPersister saves UserAccount.plist using NSFileProtectionType.NSFileProtectionComplete (which is really weird because on top of OS encryption SDK already uses it's own AES encryption so this like... extra protection?)

It seems that Apple made some changes in iOS 15 that cause the app to be launched more frequently in the background (?) and this happens.

You can see it clearly in the log here: 2247 default 14:14:22.961899+1100 logoutRepro CLASS: SFDefaultUserAccountPersister User account data could not be decrypted. Can't load account.

Here's where the protection is specified for the file: https://github.com/forcedotcom/SalesforceMobileSDK-iOS/blob/dev/libs/SalesforceSDKCore/SalesforceSDKCore/Classes/UserAccount/SFDefaultUserAccountPersister.m#L219

Here's where the encrypted file is actually nil when you do MobileSyncSDKManager.initializeSDK() in the background: https://github.com/forcedotcom/SalesforceMobileSDK-iOS/blob/dev/libs/SalesforceSDKCore/SalesforceSDKCore/Classes/UserAccount/SFDefaultUserAccountPersister.m#L233

When this happens, SFDefaultUserAccountPersister simply deletes UserAccount.plist file, which is then not found on next app launch, and so user is prompted to log in again.

Note: we didn't even need to specify any background modes for this to happen

  1. Error Log:
    2247    default 14:14:22.847892+1100    logoutRepro Initializing connection
    2247    default 14:14:22.848134+1100    logoutRepro Removing all cached process handles
    2247    default 14:14:22.848730+1100    logoutRepro Sending handshake request attempt #1 to server
    2247    default 14:14:22.848929+1100    logoutRepro Creating connection to com.apple.runningboard
    2247    default 14:14:22.853348+1100    logoutRepro Handshake succeeded
    2247    default 14:14:22.855139+1100    logoutRepro Cache loaded with 4797 pre-cached in CacheData and 48 items in CacheExtra.
    2247    default 14:14:22.856277+1100    logoutRepro Identity resolved as application<com.myteamid.testme>
    0   default 14:14:22.859311+1100    kernel  memorystatus: set assertion priority(4) target logoutRepro:2247
    2247    default 14:14:22.866750+1100    logoutRepro activating monitor for service com.apple.frontboard.open
    63  default 14:14:22.866777+1100    backboardd  Connection added: IOHIDEventSystemConnection uuid:0E4F8FCC-AC63-450C-976A-FD02233C0249 pid:2247 process:logoutRepro type:Passive entitlements:0x0 caller:BackBoardServices: <redacted> + 340 attributes:{
    HighFrequency = 1;
    bundleID = "com.myteamid.testme";
    pid = 2247;
    } state:0x0 events:0 mask:0x0
    63  default 14:14:22.866880+1100    backboardd  Adding client connection: <BKHIDClientConnection: 0x141d72140; IOHIDEventSystemConnectionRef: 0x141dc62d0; vpid: 2247(v18D9); taskPort: 0x57A5F; bundleID: com.myteamid.testme> for client: IOHIDEventSystemConnection uuid:0E4F8FCC-AC63-450C-976A-FD02233C0249 pid:2247 process:logoutRepro type:Passive entitlements:0x0 caller:BackBoardServices: <redacted> + 340 attributes:{
    HighFrequency = 1;
    bundleID = "com.myteamid.testme";
    pid = 2247;
    } state:0x0 events:0 mask:0x0
    2247    default 14:14:22.867223+1100    logoutRepro activating monitor for service com.apple.frontboard.workspace-service
    2247    default 14:14:22.867275+1100    logoutRepro FBSWorkspace connecting to endpoint : <private>
    2247    default 14:14:22.867357+1100    logoutRepro FBSWorkspace registering source: <private>
    2247    default 14:14:22.868598+1100    logoutRepro FBSWorkspace connected to endpoint : <private>
    2247    default 14:14:22.868993+1100    logoutRepro Added observer for process assertions expiration warning: <_RBSExpirationWarningClient: 0x28228a540>
    2247    default 14:14:22.870392+1100    logoutRepro Read CategoryName: per-app = 1, category name = (null)
    2247    default 14:14:22.870589+1100    logoutRepro Read CategoryName: per-app = 0, category name = (null)
    2247    default 14:14:22.873075+1100    logoutRepro TestMeApp launched
    42  default 14:14:22.876841+1100    tccd    AUTHREQ_ATTRIBUTION: msgID=2247.1, attribution={requesting={identifier=com.myteamid.testme, pid=2247, auid=501, euid=501, binary_path=/private/var/containers/Bundle/Application/0EFADC4B-AABB-46BB-9901-6EEE18F097E3/logoutRepro.app/logoutRepro}, },
    42  default 14:14:22.879017+1100    tccd    AUTHREQ_ATTRIBUTION: msgID=2247.2, attribution={requesting={identifier=com.myteamid.testme, pid=2247, auid=501, euid=501, binary_path=/private/var/containers/Bundle/Application/0EFADC4B-AABB-46BB-9901-6EEE18F097E3/logoutRepro.app/logoutRepro}, },
    2247    default 14:14:22.881433+1100    logoutRepro container_system_group_path_for_identifier: success
    2247    default 14:14:22.881464+1100    logoutRepro Got system group container path from MCM for systemgroup.com.apple.configurationprofiles: /private/var/containers/Shared/SystemGroup/systemgroup.com.apple.configurationprofiles
    2247    default 14:14:22.890580+1100    logoutRepro 0x109bf7950 - [PID=0] WebProcessCache::updateCapacity: Cache is disabled because process swap on navigation is disabled
    2247    default 14:14:22.895750+1100    logoutRepro -[SOAuthorization init]  on <private>
    2247    default 14:14:22.896137+1100    logoutRepro -[SOAuthorizationCore init]  on <private>
    2247    default 14:14:22.896625+1100    logoutRepro <SOServiceConnection: 0x28228d3a0>: new XPC connection
    2247    default 14:14:22.900999+1100    logoutRepro 0x109bcc600 - [PID=0] WebProcessProxy::constructor:
    2247    default 14:14:22.901823+1100    logoutRepro 0x109be53e0 - [PID=0, throttler=0x109bcc770] ProcessThrottler::Activity::Activity: Starting background activity / 'WebProcess initialization'
    2247    default 14:14:22.902318+1100    logoutRepro Activating Connection: <(null):0x280188280>
    2247    default 14:14:22.906879+1100    logoutRepro +[AVPictureInPicturePlatformAdapter isPictureInPictureSupported] isPictureInPictureSupported YES
    2247    default 14:14:22.912018+1100    logoutRepro Writing analzed variants.
    2247    default 14:14:22.914118+1100    logoutRepro 0x10b009818 - [pageProxyID=5, webPageID=6, PID=0] WebPageProxy::constructor:
    2247    default 14:14:22.914563+1100    logoutRepro 0x109bcc600 - [PID=0] WebProcessProxy::addExistingWebPage: webPage=0x10b009818, pageProxyID=5, webPageID=6
    2247    default 14:14:22.914633+1100    logoutRepro 0x109bf7950 - [PID=0] WebProcessCache::updateCapacity: Cache is disabled by client
    2247    default 14:14:22.917460+1100    logoutRepro 0x10b009818 - [pageProxyID=5, webPageID=6, PID=0] WebPageProxy::loadData:
    2247    default 14:14:22.918438+1100    logoutRepro Creating side-channel connection to com.apple.runningboard
    2247    default 14:14:22.920191+1100    logoutRepro Hit the server for a process handle 18d9c665000008c7 that resolved to: [application<com.myteamid.testme>:2247]
    2247    default 14:14:22.920597+1100    logoutRepro 0x10b009818 - [pageProxyID=5, webPageID=6, PID=0] WebPageProxy::WebPageProxy::shouldForceForegroundPriorityForClientNavigation() returns 1 based on PageClient::canTakeForegroundAssertions()
    2247    default 14:14:22.920633+1100    logoutRepro 0x109be56b0 - [PID=0, throttler=0x109bcc770] ProcessThrottler::Activity::Activity: Starting foreground activity / 'Client navigation'
    2247    default 14:14:22.920672+1100    logoutRepro 0x10b009818 - [pageProxyID=5, webPageID=6, PID=0] WebPageProxy::loadDataWithNavigation
    2247    default 14:14:22.920928+1100    logoutRepro networkd_settings_read_from_file initialized networkd settings by reading plist directly
    2247    default 14:14:22.921133+1100    logoutRepro networkd_settings_read_from_file initialized networkd settings by reading plist directly
    2247    default 14:14:22.921993+1100    logoutRepro nw_path_evaluator_start [BCE09DDD-38F7-4AE9-9D66-0333CF03E731 <NULL> generic, attribution: developer]
    path: satisfied (Path is satisfied), interface: en0, ipv4, ipv6, dns
    2247    default 14:14:22.922821+1100    logoutRepro 0x109bf88a0 - NavigationState is taking a process network assertion because a page load started
    2247    default 14:14:22.922859+1100    logoutRepro 0x109be56c0 - [PID=0, throttler=0x109bcc770] ProcessThrottler::Activity::Activity: Starting background activity / 'Page Load'
    2247    default 14:14:22.923289+1100    logoutRepro 0x109be56e0 - [PID=0, throttler=0x109bcc770] ProcessThrottler::Activity::Activity: Starting foreground activity / 'WebPageProxy::runJavaScriptInFrameInScriptWorld'
    2247    default 14:14:22.929701+1100    logoutRepro Not internal release, disabling SIRL
    2247    default 14:14:22.929876+1100    logoutRepro Adding securityd connection to pool, total now 1
    115 default 14:14:22.933655+1100    securityd   logoutRepro[2247]/1#4 LF=0 copy_matching Error Domain=NSOSStatusErrorDomain Code=-25308 "ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked." UserInfo={numberOfErrorsDeep=0, NSDescription=ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked.}
    115 default 14:14:22.934883+1100    securityd   logoutRepro[2247]/1#4 LF=0 copy_matching Error Domain=NSOSStatusErrorDomain Code=-25308 "ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked." UserInfo={numberOfErrorsDeep=0, NSDescription=ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked.}
    115 default 14:14:22.936181+1100    securityd   logoutRepro[2247]/1#4 LF=0 copy_matching Error Domain=NSOSStatusErrorDomain Code=-25308 "ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked." UserInfo={numberOfErrorsDeep=0, NSDescription=ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked.}
    115 default 14:14:22.936753+1100    securityd   logoutRepro[2247]/1#4 LF=0 copy_matching Error Domain=NSOSStatusErrorDomain Code=-25308 "ks_crypt: e00002e2 failed to 'od' item (class 6, bag: 0) Access to item attempted while keychain is locked." UserInfo={numberOfErrorsDeep=0, NSDescription=ks_crypt: e00002e2 failed to 'od' item (class 6, bag: 0) Access to item attempted while keychain is locked.}
    115 default 14:14:22.944797+1100    securityd   logoutRepro[2247]/1#4 LF=0 copy_matching Error Domain=NSOSStatusErrorDomain Code=-25308 "ks_crypt: e00002e2 failed to 'od' item (class 6, bag: 0) Access to item attempted while keychain is locked." UserInfo={numberOfErrorsDeep=0, NSDescription=ks_crypt: e00002e2 failed to 'od' item (class 6, bag: 0) Access to item attempted while keychain is locked.}
    115 default 14:14:22.949368+1100    securityd   logoutRepro[2247]/1#4 LF=0 copy_matching Error Domain=NSOSStatusErrorDomain Code=-25308 "ks_crypt: e00002e2 failed to 'od' item (class 6, bag: 0) Access to item attempted while keychain is locked." UserInfo={numberOfErrorsDeep=0, NSDescription=ks_crypt: e00002e2 failed to 'od' item (class 6, bag: 0) Access to item attempted while keychain is locked.}
    115 default 14:14:22.958236+1100    securityd   logoutRepro[2247]/1#4 LF=0 copy_matching Error Domain=NSOSStatusErrorDomain Code=-25308 "ks_crypt: e00002e2 failed to 'od' item (class 6, bag: 0) Access to item attempted while keychain is locked." UserInfo={numberOfErrorsDeep=0, NSDescription=ks_crypt: e00002e2 failed to 'od' item (class 6, bag: 0) Access to item attempted while keychain is locked.}
    115 default 14:14:22.961760+1100    securityd   logoutRepro[2247]/1#4 LF=0 copy_matching Error Domain=NSOSStatusErrorDomain Code=-25308 "ks_crypt: e00002e2 failed to 'od' item (class 6, bag: 0) Access to item attempted while keychain is locked." UserInfo={numberOfErrorsDeep=0, NSDescription=ks_crypt: e00002e2 failed to 'od' item (class 6, bag: 0) Access to item attempted while keychain is locked.}
    2247    default 14:14:22.961899+1100    logoutRepro CLASS: SFDefaultUserAccountPersister User account data could not be decrypted. Can't load account.
    2247    default 14:14:22.963885+1100    logoutRepro Establish daemon connection; interrupted: 0
    2247    default 14:14:22.964416+1100    logoutRepro Registering for test daemon availability notify post.
    2247    default 14:14:22.964498+1100    logoutRepro notify_get_state check indicated test daemon not ready.
    2247    default 14:14:22.964639+1100    logoutRepro notify_get_state check indicated test daemon not ready.
    2247    default 14:14:22.969019+1100    logoutRepro 0x109bcc600 - [PID=2248] WebProcessProxy::didFinishLaunching:
    2247    default 14:14:22.972389+1100    logoutRepro Faulting in CFHTTPCookieStorage singleton
    2247    default 14:14:22.972419+1100    logoutRepro Creating default cookie storage with default identifier
    2247    default 14:14:22.973346+1100    logoutRepro 0x109bcc770 - [PID=2248] ProcessThrottler::didConnectToProcess:
    2247    default 14:14:22.973375+1100    logoutRepro 0x109bcc770 - [PID=2248] ProcessThrottler::setAssertionType: Updating process assertion type to 3 (foregroundActivities=2, backgroundActivities=4)
    2247    default 14:14:22.973659+1100    logoutRepro 0x282cbcb70 - WKProcessAssertionBackgroundTaskManager: beginBackgroundTaskWithName
    2247    default 14:14:22.973690+1100    logoutRepro WKProcessAssertionBackgroundTaskManager: Took a FinishTaskInterruptable assertion for own process
    2247    default 14:14:22.973723+1100    logoutRepro 0x109bcc600 - [PID=2248] WebProcessProxy::didSetAssertionType: type=3
    2247    default 14:14:22.973777+1100    logoutRepro 0x109bcc600 - [PID=2248] WebProcessProxy::didSetAssertionType(Foreground) Taking foreground assertion for network process
    2247    default 14:14:22.973802+1100    logoutRepro 0x109be5cd0 - [PID=0, throttler=0x109b68268] ProcessThrottler::Activity::Activity: Starting foreground activity / 'Networking for foreground view(s)'
    2247    default 14:14:22.973952+1100    logoutRepro 0x109b68190 - NetworkProcessProxy is taking a background assertion because a web process is requesting a connection
    2247    default 14:14:22.977324+1100    logoutRepro 0x109b68268 - [PID=2249] ProcessThrottler::didConnectToProcess:
    2247    default 14:14:22.977354+1100    logoutRepro 0x109b68268 - [PID=2249] ProcessThrottler::setAssertionType: Updating process assertion type to 3 (foregroundActivities=1, backgroundActivities=1)
    2247    default 14:14:22.977412+1100    logoutRepro 0x109bf8900 - ProcessAssertion: Successfully took RBS assertion 'WebProcess Foreground Assertion' for process with PID=2248
    2247    default 14:14:22.980036+1100    logoutRepro 0x109bf8960 - ProcessAssertion: Successfully took RBS assertion 'NetworkProcess Foreground Assertion' for process with PID=2249
    2247    default 14:14:22.987719+1100    logoutRepro 0x109be53e0 - [PID=2248, throttler=0x109bcc770] ProcessThrottler::Activity::invalidate: Ending background activity / 'WebProcess initialization'
    2247    default 14:14:22.996256+1100    logoutRepro Created visibility propagation view 0x109a0c390 (contextID=3776598909) for WebContent process with PID=2248
    2247    default 14:14:22.996397+1100    logoutRepro 0x10b009818 - [pageProxyID=5, webPageID=6, PID=2248] WebPageProxy::decidePolicyForNavigationAction: frameID=3, navigationID=1
    2247    default 14:14:22.996604+1100    logoutRepro 0x109be5310 - SOAuthorizationCoordinator::tryAuthorize
    2247    default 14:14:22.997077+1100    logoutRepro -[SOConfigurationClient init]  on <private>
    2247    default 14:14:22.997159+1100    logoutRepro <SOServiceConnection: 0x28229fe60>: new XPC connection
    2247    default 14:14:22.997435+1100    logoutRepro 0x109be5310 - SOAuthorizationCoordinator::tryAuthorize: Cannot authorize the requested URL.
    2247    default 14:14:22.998322+1100    logoutRepro 0x10b009818 - [pageProxyID=5, webPageID=6, PID=2248] WebPageProxy::close:
    2247    default 14:14:22.998373+1100    logoutRepro 0x10b009818 - [pageProxyID=5, webPageID=6, PID=2248] WebPageProxy::decidePolicyForNavigationAction: listener called: frameID=3, navigationID=1, policyAction=2, safeBrowsingWarning=0, isAppBoundDomain=0
    2247    default 14:14:22.998399+1100    logoutRepro 0x10b009818 - [pageProxyID=5, webPageID=6, PID=2248] WebPageProxy::receivedNavigationPolicyDecision: frameID=3, navigationID=1, policyAction=2
    2247    default 14:14:22.998459+1100    logoutRepro 0x109bcc600 - [PID=2248] WebProcessProxy::removeWebPage: webPage=0x10b009818, pageProxyID=5, webPageID=6
    2247    default 14:14:22.998521+1100    logoutRepro 0x109bcc600 - [PID=2248] WebProcessProxy::canTerminateAuxiliaryProcess: returns false (pageCount=0, provisionalPageCount=0, m_suspendedPageCount=0, m_isInProcessCache=0, m_shutdownPreventingScopeCounter=1)
    2247    default 14:14:22.998816+1100    logoutRepro 0x109be56c0 - [PID=2248, throttler=0x109bcc770] ProcessThrottler::Activity::invalidate: Ending background activity / 'Page Load'
    2247    default 14:14:22.998847+1100    logoutRepro 0x10b009818 - [pageProxyID=5, webPageID=6, PID=2248] WebPageProxy::destructor:
    2247    default 14:14:22.998910+1100    logoutRepro 0x109be56b0 - [PID=2248, throttler=0x109bcc770] ProcessThrottler::Activity::invalidate: Ending foreground activity / 'Client navigation'
    2247    default 14:14:22.998939+1100    logoutRepro 0x109be56e0 - [PID=2248, throttler=0x109bcc770] ProcessThrottler::Activity::invalidate: Ending foreground activity / 'WebPageProxy::runJavaScriptInFrameInScriptWorld'
    2247    default 14:14:22.998967+1100    logoutRepro 0x109bcc770 - [PID=2248] ProcessThrottler::setAssertionType: Updating process assertion type to 1 (foregroundActivities=0, backgroundActivities=2)
    2247    default 14:14:22.999022+1100    logoutRepro 0x109bcc600 - [PID=2248] WebProcessProxy::didSetAssertionType: type=1
    2247    default 14:14:22.999046+1100    logoutRepro 0x109bcc600 - [PID=2248] WebProcessProxy::didSetAssertionType(Background) Taking background assertion for network process
    2247    default 14:14:22.999119+1100    logoutRepro 0x109be61e0 - [PID=2249, throttler=0x109b68268] ProcessThrottler::Activity::Activity: Starting background activity / 'Networking for background view(s)'
    2247    default 14:14:22.999144+1100    logoutRepro 0x109be5cd0 - [PID=2249, throttler=0x109b68268] ProcessThrottler::Activity::invalidate: Ending foreground activity / 'Networking for foreground view(s)'
    2247    default 14:14:22.999279+1100    logoutRepro 0x109b68268 - [PID=2249] ProcessThrottler::setAssertionType: Updating process assertion type to 1 (foregroundActivities=0, backgroundActivities=1)
    2247    default 14:14:22.999320+1100    logoutRepro 0x109bcc770 - [PID=2248] ProcessThrottler::sendPrepareToSuspendIPC: isSuspensionImminent=0
    2247    default 14:14:22.999351+1100    logoutRepro 0x109bcc770 - [PID=2248] ProcessThrottler::sendPrepareToSuspendIPC: Sending PrepareToSuspend(1, isSuspensionImminent=0) IPC
    2247    default 14:14:22.999380+1100    logoutRepro 0x109bcc600 - [PID=2248] WebProcessProxy::sendPrepareToSuspend: isSuspensionImminent=0
    2247    default 14:14:22.999408+1100    logoutRepro 0x109bcc600 - [PID=2248] WebProcessProxy::canTerminateAuxiliaryProcess: returns true
    2247    default 14:14:22.999490+1100    logoutRepro 0x109bf7950 - [PID=2248] WebProcessCache::canCacheProcess: Not caching process because the cache has no capacity
    2247    default 14:14:23.999525+1100    logoutRepro 0x109bcc600 - [PID=2248] WebProcessProxy::shutDown:
    2247    default 14:14:23.999557+1100    logoutRepro 0x109bcc600 - [PID=2248] WebProcessProxy::processWillShutDown:
    2247    default 14:14:23.999584+1100    logoutRepro 0x109bcc600 - [PID=2248] WebProcessProxy::destructor:
    2247    default 14:14:23.999623+1100    logoutRepro 0x109be61e0 - [PID=2249, throttler=0x109b68268] ProcessThrottler::Activity::invalidate: Ending background activity / 'Networking for background view(s)'
    2247    default 14:14:23.999648+1100    logoutRepro 0x109b68268 - [PID=2249] ProcessThrottler::sendPrepareToSuspendIPC: isSuspensionImminent=0
    2247    default 14:14:23.999766+1100    logoutRepro 0x109b68268 - [PID=2249] ProcessThrottler::sendPrepareToSuspendIPC: Sending PrepareToSuspend(2, isSuspensionImminent=0) IPC
    2247    default 14:14:23.999797+1100    logoutRepro 0x109bcc770 - [PID=2248] ProcessThrottler::invalidateAllActivities: BEGIN (foregroundActivityCount: 0, backgroundActivityCount: 0)
    2247    default 14:14:23.999861+1100    logoutRepro 0x109bcc770 - [PID=2248] ProcessThrottler::invalidateAllActivities: END
    2247    default 14:14:23.000122+1100    logoutRepro WebBackForwardCache::clear
    2247    error   14:14:23.008399+1100    logoutRepro Error acquiring assertion: <Error Domain=RBSServiceErrorDomain Code=1 "target is not running or doesn't have entitlement com.apple.runningboard.assertions.webkit" UserInfo={NSLocalizedFailureReason=target is not running or doesn't have entitlement com.apple.runningboard.assertions.webkit}>
    2247    error   14:14:23.008512+1100    logoutRepro 0x109bf9080 - ProcessAssertion: Failed to acquire RBS assertion 'WebProcess Background Assertion' for process with PID=2248, error: Error Domain=RBSServiceErrorDomain Code=1 "target is not running or doesn't have entitlement com.apple.runningboard.assertions.webkit" UserInfo={NSLocalizedFailureReason=target is not running or doesn't have entitlement com.apple.runningboard.assertions.webkit}
    2247    default 14:14:23.009335+1100    logoutRepro 0x109bf9080 - ProcessAssertion::processAssertionWasInvalidated() PID=2248
    2247    default 14:14:23.009380+1100    logoutRepro 0x109bf8900 - ~ProcessAssertion: Releasing process assertion 'WebProcess Foreground Assertion' for process with PID=2248
    2247    default 14:14:23.009679+1100    logoutRepro 0x109bf9080 - ~ProcessAssertion: Releasing process assertion 'WebProcess Background Assertion' for process with PID=2248
    2247    default 14:14:23.010368+1100    logoutRepro 0x109bf90e0 - ProcessAssertion: Successfully took RBS assertion 'NetworkProcess Background Assertion' for process with PID=2249
    2247    default 14:14:23.010474+1100    logoutRepro 0x109bf8960 - ~ProcessAssertion: Releasing process assertion 'NetworkProcess Foreground Assertion' for process with PID=2249
    2247    error   14:14:23.011861+1100    logoutRepro Error acquiring assertion: <Error Domain=RBSAssertionErrorDomain Code=2 "Specified target process does not exist" UserInfo={NSLocalizedFailureReason=Specified target process does not exist}>
    2247    error   14:14:23.011913+1100    logoutRepro 0x109bf9140 - ProcessAssertion: Failed to acquire RBS assertion 'ConnectionTerminationWatchdog' for process with PID=2248, error: Error Domain=RBSAssertionErrorDomain Code=2 "Specified target process does not exist" UserInfo={NSLocalizedFailureReason=Specified target process does not exist}
    2247    default 14:14:23.011971+1100    logoutRepro 0x109bf9140 - ProcessAssertion::processAssertionWasInvalidated() PID=2248
    2247    default 14:14:23.023015+1100    logoutRepro 0x109b68268 - [PID=2249] ProcessThrottler::processReadyToSuspend: Updating process assertion to allow suspension
    2247    default 14:14:23.023049+1100    logoutRepro 0x109b68268 - [PID=2249] ProcessThrottler::setAssertionType: Updating process assertion type to 0 (foregroundActivities=0, backgroundActivities=0)
    2247    default 14:14:23.023423+1100    logoutRepro 0x109bf91a0 - ProcessAssertion: Successfully took RBS assertion 'NetworkProcess Suspended Assertion' for process with PID=2249
    2247    default 14:14:23.023566+1100    logoutRepro 0x109bf90e0 - ~ProcessAssertion: Releasing process assertion 'NetworkProcess Background Assertion' for process with PID=2249
    2247    default 14:14:23.023617+1100    logoutRepro 0x282cbcb70 - WKProcessAssertionBackgroundTaskManager: endBackgroundTask
    0   default 14:14:24.137355+1100    kernel  memorystatus: set assertion priority(0) target logoutRepro:2247
    34  default 14:14:24.160398+1100    mediaserverd              SSServerImp.cpp:1250  pid 2247(logoutRepro)
az-oolloow commented 3 years ago

I tried working around this by changing init() like so:

       FileProtectionHelper.shared.defaultMode = FileProtectionType.completeUntilFirstUserAuthentication.rawValue
        KeychainHelper.setAccessibleAttribute(.afterFirstUnlock)
        SFKeychainItemWrapper.setAccessibleAttribute(kSecAttrAccessibleAfterFirstUnlock)
        MobileSyncSDKManager.initializeSDK()

(just changing FileProtectionHelper.shared.defaultMode is not enough because then SmartStore can't access keychain to get decryption key and it promptly deletes the sqlite file 🤦‍♂️)

However, this causes the following log when app is launched in the background:

2391    error   17:14:23.220890+1100    logoutRepro CLASS: SFGeneratedKeyStore Error saving key com.salesforce.keystore.generatedKeystoreKeychainId_store to the keychain.
115 default 17:14:23.221796+1100    securityd   insert failed for item <genp,acct=3MVG9G9pzCUSkzZsYYhywRx6_tAGvwMYaCWnrEbAtcEhExreYyj7nOrfHua1fw9Bs9AN8zJxbOxmsQ4_l4Il6-203134478,svce=com.salesforce.oauth.access,agrp=8498Z5DRCR.com.myteamid.testme.logoutRepro,sync=0,musr=, |otherAttr,tomb=0,cdat=2021-10-20 06:14:23 +0000,mdat=2021-10-20 06:14:23 +0000,crtr=com.salesforce.mobilesdk,pdmn=aku,sha1=C8228E03E0ABF46AD1AFC8DE5163C9CBFA079EF6,UUID=64965DEB-6B05-475A-B001-40137364CFB3,persistref=7AB2C6315E7E490197B7132D6ED8AE0C,clip=0> with Error Domain=NSOSStatusErrorDomain Code=-25308 "ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked." UserInfo={numberOfErrorsDeep=0, NSDescription=ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked.}
115 default 17:14:23.221848+1100    securityd   logoutRepro[2391]/1#4 LF=0 add Error Domain=NSOSStatusErrorDomain Code=-25308 "ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked." UserInfo={numberOfErrorsDeep=0, NSDescription=ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked.}
2391    error   17:14:23.222042+1100    logoutRepro CLASS: SFOAuthKeychainCredentials Could not read com.salesforce.oauth.access from keychain, Error Domain=com.salesforce.security.keychainException Code=-25308 "User interaction is not allowed." UserInfo={NSLocalizedDescription=User interaction is not allowed., com.salesforce.security.keychainException.errorCode=-25308}
115 default 17:14:23.224015+1100    securityd   logoutRepro[2391]/1#4 LF=0 update Error Domain=NSOSStatusErrorDomain Code=-25308 "ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked." UserInfo={numberOfErrorsDeep=0, NSDescription=ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked.}
2391    error   17:14:23.224128+1100    logoutRepro CLASS: SFGeneratedKeyStore Error saving key com.salesforce.keystore.generatedKeystoreKeychainId_store to the keychain.
115 default 17:14:23.225025+1100    securityd   insert failed for item <genp,acct=3MVG9G9pzCUSkzZsYYhywRx6_tAGvwMYaCWnrEbAtcEhExreYyj7nOrfHua1fw9Bs9AN8zJxbOxmsQ4_l4Il6-203134478,svce=com.salesforce.oauth.refresh,agrp=8498Z5DRCR.com.myteamid.testme.logoutRepro,sync=0,musr=, |otherAttr,tomb=0,cdat=2021-10-20 06:14:23 +0000,mdat=2021-10-20 06:14:23 +0000,crtr=com.salesforce.mobilesdk,pdmn=aku,sha1=54EB5DAD11FFBA978517ED6DEA2F846F21DEA55E,UUID=D15EC88E-F349-4ECB-BA58-8C438F34A78C,persistref=9FF4E3D021E94BFB93C2ECB3379D23A6,clip=0> with Error Domain=NSOSStatusErrorDomain Code=-25308 "ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked." UserInfo={numberOfErrorsDeep=0, NSDescription=ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked.}
115 default 17:14:23.225267+1100    securityd   logoutRepro[2391]/1#4 LF=0 add Error Domain=NSOSStatusErrorDomain Code=-25308 "ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked." UserInfo={numberOfErrorsDeep=0, NSDescription=ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked.}
2391    error   17:14:23.225399+1100    logoutRepro CLASS: SFOAuthKeychainCredentials Could not read com.salesforce.oauth.refresh from keychain, Error Domain=com.salesforce.security.keychainException Code=-25308 "User interaction is not allowed." UserInfo={NSLocalizedDescription=User interaction is not allowed., com.salesforce.security.keychainException.errorCode=-25308}
115 default 17:14:23.255494+1100    securityd   logoutRepro[2391]/1#4 LF=0 update Error Domain=NSOSStatusErrorDomain Code=-25308 "ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked." UserInfo={numberOfErrorsDeep=0, NSDescription=ks_crypt: e00002e2 failed to 'od' item (class 9, bag: 0) Access to item attempted while keychain is locked.}
2391    error   17:14:23.255548+1100    logoutRepro CLASS: SFGeneratedKeyStore Error saving key com.salesforce.keystore.generatedKeystoreKeychainId_store to the keychain.

This is using the same default forceios app with 9.2.0 SDK.

Interestingly pdmn=aku in the log suggests that even despite my changes, somewhere in the SDK the default access level is used (kSecAttrAccessibleAfterFirstUnlock would be ck)

dLiubchenko commented 3 years ago

Having the same error. Any updates?

bbirman commented 3 years ago

@dLiubchenko we're working on this now and will post when we have more info

dLiubchenko commented 3 years ago

@bbirman, thank you for answer! BTW, we are facing with this problem on Hybrid application too

az-oolloow commented 3 years ago

FWIW until we hear back from @bbirman or the team we are staying on our fork of 8.3 SDK where the new keychain class doesn't exist so this can be worked around via:

  1. Upgrade flag to reset the file protection to e.g. completeUntilFirstUserAuthentication like so:

    if let r = SFDirectoryManager.shared().directory(forUser: nil, type: .libraryDirectory, components: nil) {
    SFPathUtil.secureFile(atPath: r, recursive: true, fileProtection: FileProtectionType.completeUntilFirstUserAuthentication.rawValue)
    }
    1. Setting the FileProtectionHelper default mode to match BEFORE you init the SDK
      FileProtectionHelper.shared.defaultMode = FileProtectionType.completeUntilFirstUserAuthentication.rawValue
    2. Updating SFKeychainItemWrapper accessible attribute like so
      SFKeychainItemWrapper.setAccessibleAttribute(kSecAttrAccessibleAfterFirstUnlock)

    After this we have no issues with the app launching in the background.

pushp1010 commented 2 years ago

@bbirman @az-oolloow any ETA for this issue to be fixed?

MattSynaptic commented 2 years ago

@az-oolloow Could you please provide more detail about in which files you made these changes? We are using 9.1 and so I don't know if that makes a difference.

az-oolloow commented 2 years ago

@pushp1010 I do not work for Salesforce, so can only suggest workarounds like I did for the above, and as mentioned I could not get it to work with 9.2.0.

@MattSynaptic I am on 8.3 so I don't know whether my fix will work for you. It did not solve the issue fully in 9.2 as the new Keychain access class written in Swift by the SDK team just doesn't behave.

Basically, somewhere in your app you would have MobileSyncSDKManager.initializeSDK() or equivalent (e.g. in AppDelegate)

You would add the code I specified before you init the SDK.

If you already have users in the field it is prudent to do the steps 1 (where we call secureFile ) and 3 (where we call setAccessibleAttribute) when UIApplication.shared.isProtectedDataAvailable

The best way to migrate (for OUR app, not sure it this applies to yours)

  1. In AppDelegate declare a variable to hold whether sdk is init
  2. When AppDelegate init is called, check if we have a flag in UserDefaults that says we've applied file and keychain permissions. If yes, init sdk and set the flag. (this is normal flow for all our users NOW)
  3. If flag is NOT set, check if UIApplication.shared.isProtectedDataAvailable. If not, exit the app delegate init. If isProtectedDataAvailable is true, migrate file and keychain permissions, set flag in userdefaults, init sdk, set the variable to true.
  4. In application: didFinishLaunchingWithOptions check if the variable is set. If yes, do nothing other than whatever your app normally does. If sdk has not been inited, check if UIApplication.shared.isProtectedDataAvailable. If not, throw a hissy fit. (this is a dead end, but I never had anyone hit it. I just display an empty VC here). If isProtectedDataAvailable is true, migrate file and keychain permissions, set flag in userdefaults, init sdk, set the variable to true. (this is same as what you'd do in AppDelegate init).

This logic handles cases where you have new installs as well as people upgrading to new version of your app and makes sure all the things are accessible correctly.

az-oolloow commented 2 years ago

FYI @bbirman has merged a PR fix and I have made a clarifying comment there: https://github.com/forcedotcom/SalesforceMobileSDK-iOS/pull/3447#issuecomment-982654888

wmathurin commented 2 years ago

The just released patch 9.2.1 should address this issue.