Hi sir:
Sometime happen fail to unlock screen when O80 upgrade to P90. and check code(system/vold), seem possible reason is the below:
the current case is blocked system/vold/Ext4Crypt.cpp/e4crypt_prepare_user_storage which is caused by RestoreconRecursive which will take long time.
prepareUserStorage and addUserKeyAuth share same lock(CRYPT_LOCK), so addUserKeyAuth is blocked if prepareUserStorage take long time.
locksetting service will call addUserKeyAuth during DB create and after watchdog timeout happen and system server reset and lockscreen DB is not create successfully and cause fail to unlock screen.
Question:
1.seem Google original design not consider the case that prepareUserStorage is block for long time(more than 60S) and cause watchdog timeout, how to resolve this case
2.under FDE mode, seem addUserKeyAuth should be directly return and modify is as the below
896binder::Status VoldNativeService::addUserKeyAuth(int32_t userId, int32_t userSerial,
897 const std::string& token, const std::string& secret) {
898 ENFORCE_UID(AID_SYSTEM);
//directly return if under FDE mode
if (!e4crypt_is_native()) return translateBool(true);
899 ACQUIRE_CRYPT_LOCK;
900
901 return translateBool(e4crypt_add_user_key_auth(userId, userSerial, token, secret));
902}
Orignal Source code: (system/vold)
e4crypt_prepare_user_storage {
......
874 android::vold::RestoreconRecursive(system_ce_path);
875 android::vold::RestoreconRecursive(misc_ce_path);
.....
}
934binder::Status VoldNativeService::prepareUserStorage(const std::unique_ptr<std::string>& uuid,
935 int32_t userId, int32_t userSerial, int32_t flags) {
936 ENFORCE_UID(AID_SYSTEM);
937 std::string empty_string = "";
938 auto uuid_ = uuid ? *uuid : empty_string;
939 CHECK_ARGUMENT_HEX(uuid_);
940
941 ACQUIRE_CRYPT_LOCK;
942 return translateBool(e4crypt_prepare_user_storage(uuid_, userId, userSerial, flags));
943}
896binder::Status VoldNativeService::addUserKeyAuth(int32_t userId, int32_t userSerial,
897 const std::string& token, const std::string& secret) {
898 ENFORCE_UID(AID_SYSTEM);
899 ACQUIRE_CRYPT_LOCK;
900
901 return translateBool(e4crypt_add_user_key_auth(userId, userSerial, token, secret));
902}
log is as the below:
07-16 13:55:33.079 3554 3658 E LockSettingsStorage: new: /data/system_de/0/spblob/cf4adca75bc8d192.secdis
07-16 13:55:33.092 3554 3658 E LockSettingsStorage: new: /data/system_de/0/spblob/cf4adca75bc8d192.pwd
07-16 13:55:33.120 3554 3658 E LockSettingsStorage: new: /data/system_de/0/spblob/cf4adca75bc8d192.spblob
07-16 13:56:05.065 3554 4841 W ActivityManager: dumpStackTraces end, 1729ms
07-16 13:56:07.202 3554 4841 W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in handler on foreground thread (android.fg), Blocked in handler on ActivityManager (ActivityManager)
07-16 13:56:07.205 3554 4841 W Watchdog: android.fg annotated stack trace:
07-16 13:56:07.205 3554 4841 W Watchdog: at android.os.BinderProxy.transactNative(Native Method)
07-16 13:56:07.205 3554 4841 W Watchdog: at android.os.BinderProxy.transact(Binder.java:1136)
07-16 13:56:07.205 3554 4841 W Watchdog: at android.os.IVold$Stub$Proxy.prepareUserStorage(IVold.java:1498)
07-16 13:56:07.205 3554 4841 W Watchdog: at com.android.server.StorageManagerService.prepareUserStorage(StorageManagerService.java:2787)
07-16 13:56:07.205 3554 4841 W Watchdog: at android.os.storage.StorageManager.prepareUserStorage(StorageManager.java:1348)
07-16 13:56:07.205 3554 4841 W Watchdog: at com.android.server.pm.UserDataPreparer.prepareUserDataLI(UserDataPreparer.java:85)
07-16 13:56:07.205 3554 4841 W Watchdog: at com.android.server.pm.UserDataPreparer.prepareUserData(UserDataPreparer.java:74)
07-16 13:56:07.205 3554 4841 W Watchdog: - locked <0x069af9ca> (a java.lang.Object)
07-16 13:56:07.205 3554 4841 W Watchdog: at com.android.server.pm.UserManagerService.onBeforeUnlockUser(UserManagerService.java:3408)
07-16 13:56:07.205 3554 4841 W Watchdog: at com.android.server.am.UserController.lambda$finishUserUnlocking$0(UserController.java:408)
07-16 13:56:07.205 3554 4841 W Watchdog: at com.android.server.am.-$$Lambda$UserController$o6oQFjGYYIfx-I94cSakTLPLt6s.run(Unknown Source:6)
07-16 13:56:07.205 3554 4841 W Watchdog: at android.os.Handler.handleCallback(Handler.java:873)
07-16 13:56:07.205 3554 4841 W Watchdog: at android.os.Handler.dispatchMessage(Handler.java:99)
07-16 13:56:07.205 3554 4841 W Watchdog: at android.os.Looper.loop(Looper.java:210)
07-16 13:56:07.205 3554 4841 W Watchdog: at android.os.HandlerThread.run(HandlerThread.java:65)
07-16 13:56:07.205 3554 4841 W Watchdog: at com.android.server.ServiceThread.run(ServiceThread.java:44)
07-16 13:56:07.209 3554 4841 W Watchdog: ActivityManager annotated stack trace:
07-16 13:56:07.209 3554 4841 W Watchdog: at android.os.BinderProxy.transactNative(Native Method)
07-16 13:56:07.209 3554 4841 W Watchdog: at android.os.BinderProxy.transact(Binder.java:1136)
07-16 13:56:07.209 3554 4841 W Watchdog: at android.os.IVold$Stub$Proxy.onSecureKeyguardStateChanged(IVold.java:786)
07-16 13:56:07.209 3554 4841 W Watchdog: at com.android.server.StorageManagerService.onKeyguardStateChanged(StorageManagerService.java:1032)
07-16 13:56:07.210 3554 4841 W Watchdog: at com.android.server.am.ActivityManagerService$MainHandler.handleMessage(ActivityManagerService.java:2687)
07-16 13:56:07.210 3554 4841 W Watchdog: at android.os.Handler.dispatchMessage(Handler.java:106)
07-16 13:56:07.210 3554 4841 W Watchdog: at android.os.Looper.loop(Looper.java:210)
07-16 13:56:07.210 3554 4841 W Watchdog: at android.os.HandlerThread.run(HandlerThread.java:65)
07-16 13:56:07.210 3554 4841 W Watchdog: at com.android.server.ServiceThread.run(ServiceThread.java:44)
07-16 13:56:07.210 3554 4841 W Watchdog: dump registered receivers++
07-16 13:56:07.216 3554 4841 W ActivityManager: No abnormal package found.
07-16 13:56:07.216 3554 4841 W Watchdog: dump registered receivers--