dump与strace命令实战之分析keystore死锁导致watchdog问题

本文主要是介绍dump与strace命令实战之分析keystore死锁导致watchdog问题，希望对大家解决编程问题提供一定的参考价值，需要的开发者们随着小编来一起学习吧！

一、问题描述

近期发生一个系统卡死的问题。推测是system_server出现watchdog。查看watchdog文件，是PackageManager卡在了KeyStore.clearUid()接口：


----- pid 1091 at 2023-10-26 09:40:10 -----
Cmd line: system_server
ABI: 'arm64'"PackageManager" sysTid=1352#00 pc 000000000006e1c4  /system/lib64/libc.so (__ioctl+4)#01 pc 00000000000290d0  /system/lib64/libc.so (ioctl+136)#02 pc 000000000005a5e4  /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+256)#03 pc 000000000005b48c  /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+340)#04 pc 000000000005b1c0  /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+176)#05 pc 0000000000051318  /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+72)#06 pc 000000000012f72c  /system/lib64/libandroid_runtime.so (android_os_BinderProxy_transact(_JNIEnv*, _jobject*, int, _jobject*, _jobject*, int)+152)#07 pc 0000000000406e34  /system/framework/arm64/boot-framework.oat (offset 0x3d2000) (android.os.BinderProxy.transactNative+196)#08 pc 0000000000c00d5c  /system/framework/arm64/boot-framework.oat (offset 0x3d2000) (android.os.BinderProxy.transact+748)#09 pc 000000000065e4e8  /system/framework/arm64/boot-framework.oat (offset 0x3d2000) (android.security.IKeystoreService$Stub$Proxy.clear_uid+216)#10 pc 0000000000556578  /system/framework/arm64/boot-framework.oat (offset 0x3d2000) (android.security.KeyStore.clearUid+88)#11 pc 00000000014bdba4  /system/framework/oat/arm64/services.odex (offset 0x64d000) (com.android.server.pm.PackageManagerService.removeKeystoreDataIfNeeded+244)#12 pc 00000000014bea94  /system/framework/oat/arm64/services.odex (offset 0x64d000) (com.android.server.pm.PackageManagerService.removePackageDataLIF+2836)#13 pc 00000000014900b0  /system/framework/oat/arm64/services.odex (offset 0x64d000) (com.android.server.pm.PackageManagerService.deleteInstalledPackageLIF+688)#14 pc 000000000149161c  /system/framework/oat/arm64/services.odex (offset 0x64d000) (com.android.server.pm.PackageManagerService.deletePackageLIF+3532)#15 pc 00000000014dd554  /system/framework/oat/arm64/services.odex (offset 0x64d000) (com.android.server.pm.PackageManagerService.deletePackageX+2724)#16 pc 0000000000d9735c  /system/framework/oat/arm64/services.odex (offset 0x64d000) (com.android.server.pm.PackageManagerService$12.run+476)#17 pc 0000000000ab737c  /system/framework/arm64/boot-framework.oat (offset 0x3d2000) (android.os.Handler.dispatchMessage+76)#18 pc 0000000000aba4e0  /system/framework/arm64/boot-framework.oat (offset 0x3d2000) (android.os.Looper.loop+1264)#19 pc 0000000000ab9380  /system/framework/arm64/boot-framework.oat (offset 0x3d2000) (android.os.HandlerThread.run+544)#20 pc 00000000007d57b4  /system/framework/oat/arm64/services.odex (offset 0x64d000) (com.android.server.ServiceThread.run+100)#21 pc 0000000000554d88  /system/lib64/libart.so (art_quick_invoke_stub+584)#22 pc 00000000000cf6c8  /system/lib64/libart.so (art::ArtMethod::Invoke(art::Thread*, unsigned int*, unsigned int, art::JValue*, char const*)+200)#23 pc 000000000045c840  /system/lib64/libart.so (art::(anonymous namespace)::InvokeWithArgArray(art::ScopedObjectAccessAlreadyRunnable const&, art::ArtMethod*, art::(anonymous namespace)::ArgArray*, art::JValue*, char const*)+104)#24 pc 000000000045d8fc  /system/lib64/libart.so (art::InvokeVirtualOrInterfaceWithJValues(art::ScopedObjectAccessAlreadyRunnable const&, _jobject*, _jmethodID*, jvalue*)+424)#25 pc 0000000000488a94  /system/lib64/libart.so (art::Thread::CreateCallback(void*)+1120)#26 pc 00000000000819b4  /system/lib64/libc.so (__pthread_start(void*)+36)#27 pc 0000000000023478  /system/lib64/libc.so (__start_thread+68)

出现问题的场景是在应用商店安装卸载某些应用。经过后面调查，在安装删除某个应用后，即出现这个问题。使用adb uninstall 该应用可以发现命令行一直卡在卸载中，没有正常返回。

经过代码走读，keystore服务注册的线程池为1。删除这个应用时候如果keystoreservice卡住了，则后面调用keystoreservice接口的模块也必定会卡住。

二，使用strace命令

8155平台keystoreservice是android的。keymaster是高通的qtikeymaster。于是写下面三个批处理命令，跟踪system_server, keystoreservice, qtikeymaster的系统调用情况。

1，写一个如下的批处理程序 strace_keystore.bat，开始捕获keystore与keymaster的系统调用。

echo "enable adb connecting first..."adb wait-for-device
adb rootecho Wscript.sleep Wscript.Arguments(0)>Delay.vbs
Delay.vbs 5000
del Delay.vbsadb shell mkdir /data/stracemd d:\stracelogadb shell "echo 512 > /sys/module/binder/parameters/debug_mask"adb shell pidof android.hardware.keymaster@4.0-service-qti > d:\stracelog\keymaster.pidadb shell pidof keystore > d:\stracelog\keystore.pidadb shell "strace -p `pidof keystore` -p `pidof  android.hardware.keymaster@4.0-service-qti` -o /data/strace/process -ff -tt"

上面命令会把trace log保存在系统/data/strace目录。本地windows目录d:\stracelog文件夹保存出现问题时候keystore与keymaster的进程后，便于后面导出/data/strace/目录LOG后确认进程。

2，通过adb uninstall com.xxx.car复现该问题。

3，写一个 export_strace_logs.bat 批处理程序导出LOG。

adb pull /data/strace/ d:\stracelog
adb shell "rm /data/strace/*"

4，同时导出adb log。

5，分析strace log看，最后keystore卡在了：

09:47:17.190694 ioctl(4, BINDER_WRITE_READ, 0x7ff422e268) = 0
09:47:17.199964 ioctl(7, BINDER_WRITE_READ, 0x7ff4236a78) = 0
09:47:17.200665 futex(0x7339a462c8, FUTEX_WAKE_PRIVATE, 2147483647) = 0
09:47:17.200762 ioctl(7, BINDER_WRITE_READ, 0x7ff4236ca8) = 0
09:47:17.200844 futex(0x7339a462c8, FUTEX_WAKE_PRIVATE, 2147483647) = 0
09:47:17.200929 newfstatat(AT_FDCWD, "timestamp", {st_mode=S_IFREG|0600, st_size=0, ...}, 0) = 0
09:47:17.201304 ioctl(7, BINDER_WRITE_READ, 0x7ff422e138) = 0
09:47:17.201724 mprotect(0x73bbd6e000, 4096, PROT_READ|PROT_WRITE) = 0
09:47:17.201806 mprotect(0x73bbd6e000, 4096, PROT_READ) = 0
09:47:17.202226 futex(0x73bb575080, FUTEX_WAKE_PRIVATE, 2147483647) = 0
09:47:17.202310 ioctl(7, BINDER_WRITE_READ, 0x7ff422e208) = 0
09:47:17.203316 faccessat(AT_FDCWD, "user_0/10041_USRPKEY_no506b3822wb", R_OK|W_OK) = 0
09:47:17.203436 openat(AT_FDCWD, "user_0/10041_USRPKEY_no506b3822wb", O_RDONLY) = 9
09:47:17.203536 read(9, "\3\4\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 32824) = 823
09:47:17.203612 read(9, "", 32001)      = 0
09:47:17.203670 close(9)                = 0
09:47:17.203756 ioctl(4, BINDER_WRITE_READ

这个是不正常的，这种情况预示这正在等待binder对端的返回。如果是平时的空闲态，则进程的最后打印应该阻塞在如下代码：

00:05:07.682578 ioctl(7, BINDER_WRITE_READ <detached ...>

继续查看qtikeymaster的strace log:

9:47:17.205302 close(6)                = 0
09:47:17.205372 madvise(0x765dcb4000, 102400, MADV_DONTNEED) = 0
09:47:17.205447 madvise(0x765dc92000, 102400, MADV_DONTNEED) = 0
09:47:17.205526 openat(AT_FDCWD, "/dev/hab", O_RDWR) = 6
09:47:17.205613 ioctl(6, _IOC(_IOC_READ|_IOC_WRITE, 0xa, 0x4, 0x10), 0x7fe6247b68) = 0
09:47:17.206340 getuid()                = 1000
09:47:17.206412 writev(5, [{iov_base="\0a\1\245s8e\351,J\f", iov_len=11}, {iov_base="\4", iov_len=1}, {iov_base="uhab\0", iov_len=5}, {iov_base="habmm_socket_open: opened fd 6, "..., iov_len=67}], 4) = 84
09:47:17.206709 ioctl(6, _IOC(_IOC_WRITE, 0xa, 0x2, 0x18), 0x7fe6247b70) = 0
09:47:17.206960 ioctl(6, _IOC(_IOC_READ|_IOC_WRITE, 0xa, 0x3, 0x18)

最后也是卡在ioctl接口的一个read函数。这个函数没有返回值，说明在卡着。由于keystoreservice也是qtikeymaster的一个client，security环境是厂家实现的。卡在了qtikeymaster。

三、确认卡在哪个接口

通过在system/security/keystore/key_store_service.cpp 加LOG，最后确认了，问题APP在联网与不联网情况下初始化时候调用的keystore接口是不一样的：

可联网场景安装：

keystore: del USRPKEY_CMCC_SDK
keystore: del USRCERT_CMCC_SDK
keystore: del CACERT_CMCC_SDK
keystore: del USRPKEY_no506b3822wb
keystore: del USRCERT_no506b3822wb
keystore: del CACERT_no506b3822wb
keystore: attestKey
keystore: del USRPKEY_sec506b3822
keystore: del USRCERT_sec506b3822
keystore: del CACERT_sec506b3822

有网络卸载：

keystore: clear_uid

无网络安装：

keystore: del USRPKEY_CMCC_SDK
keystore: del USRCERT_CMCC_SDK
keystore: del CACERT_CMCC_SDK

无网络卸载：

keystore: clear_uid

最后卡住的接口是keystore: attestKey。问了确认调用函数栈，我们需要命令来在卡住时候打印调用栈：

dump1_system_server.bat

adb shell "debuggerd -b  `pidof system_server`" >d:\stracelog\dump_system_server.txt

dump2_keystore.bat

adb shell "debuggerd -b  `pidof keystore`" >d:\stracelog\dump_keystore.txt

dump3_keymaster.bat

adb shell "debuggerd -b `pidof  android.hardware.keymaster@4.0-service-qti` " >d:\stracelog\dump_keymaster.txt

注意，debuggerd -b 命令是会让当前进程退出block状态继续往下进行的。所以如果锁有嵌套关系，要先dump出来外层的应该用，后dump根层的应用。所以本例中dump的顺序是先system_server，最后是qtikeymaster.

dump的结果是：

----- pid 962 at 2023-10-26 20:47:27 -----
Cmd line: system_server
ABI: 'arm64'"PackageManager" sysTid=1121#00 pc 000000000006e1c4  /system/lib64/libc.so (__ioctl+4)#01 pc 00000000000290d0  /system/lib64/libc.so (ioctl+136)#02 pc 000000000005a5e4  /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+256)#03 pc 000000000005b48c  /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+340)#04 pc 000000000005b1c0  /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+176)#05 pc 0000000000051318  /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+72)#06 pc 000000000012f72c  /system/lib64/libandroid_runtime.so (android_os_BinderProxy_transact(_JNIEnv*, _jobject*, int, _jobject*, _jobject*, int)+152)#07 pc 0000000000406e34  /system/framework/arm64/boot-framework.oat (offset 0x3d2000) (android.os.BinderProxy.transactNative+196)#08 pc 0000000000c00d5c  /system/framework/arm64/boot-framework.oat (offset 0x3d2000) (android.os.BinderProxy.transact+748)#09 pc 000000000065e4e8  /system/framework/arm64/boot-framework.oat (offset 0x3d2000) (android.security.IKeystoreService$Stub$Proxy.clear_uid+216)#10 pc 0000000000556578  /system/framework/arm64/boot-framework.oat (offset 0x3d2000) (android.security.KeyStore.clearUid+88)#11 pc 00000000014bdba4  /system/framework/oat/arm64/services.odex (offset 0x64d000) (com.android.server.pm.PackageManagerService.removeKeystoreDataIfNeeded+244)#12 pc 00000000014bea94  /system/framework/oat/arm64/services.odex (offset 0x64d000) (com.android.server.pm.PackageManagerService.removePackageDataLIF+2836)#13 pc 00000000014900b0  /system/framework/oat/arm64/services.odex (offset 0x64d000) (com.android.server.pm.PackageManagerService.deleteInstalledPackageLIF+688)#14 pc 000000000149161c  /system/framework/oat/arm64/services.odex (offset 0x64d000) (com.android.server.pm.PackageManagerService.deletePackageLIF+3532)#15 pc 00000000014dd554  /system/framework/oat/arm64/services.odex (offset 0x64d000) (com.android.server.pm.PackageManagerService.deletePackageX+2724)#16 pc 0000000000d97634  /system/framework/oat/arm64/services.odex (offset 0x64d000) (com.android.server.pm.PackageManagerService$12.run+1204)#17 pc 0000000000ab737c  /system/framework/arm64/boot-framework.oat (offset 0x3d2000) (android.os.Handler.dispatchMessage+76)#18 pc 0000000000aba4e0  /system/framework/arm64/boot-framework.oat (offset 0x3d2000) (android.os.Looper.loop+1264)#19 pc 0000000000ab9380  /system/framework/arm64/boot-framework.oat (offset 0x3d2000) (android.os.HandlerThread.run+544)#20 pc 00000000007d57b4  /system/framework/oat/arm64/services.odex (offset 0x64d000) (com.android.server.ServiceThread.run+100)#21 pc 0000000000554d88  /system/lib64/libart.so (art_quick_invoke_stub+584)#22 pc 00000000000cf6c8  /system/lib64/libart.so (art::ArtMethod::Invoke(art::Thread*, unsigned int*, unsigned int, art::JValue*, char const*)+200)#23 pc 000000000045c840  /system/lib64/libart.so (art::(anonymous namespace)::InvokeWithArgArray(art::ScopedObjectAccessAlreadyRunnable const&, art::ArtMethod*, art::(anonymous namespace)::ArgArray*, art::JValue*, char const*)+104)#24 pc 000000000045d8fc  /system/lib64/libart.so (art::InvokeVirtualOrInterfaceWithJValues(art::ScopedObjectAccessAlreadyRunnable const&, _jobject*, _jmethodID*, jvalue*)+424)#25 pc 0000000000488a94  /system/lib64/libart.so (art::Thread::CreateCallback(void*)+1120)#26 pc 00000000000819b4  /system/lib64/libc.so (__pthread_start(void*)+36)#27 pc 0000000000023478  /system/lib64/libc.so (__start_thread+68)----- pid 904 at 2023-10-26 20:47:30 -----
Cmd line: /system/bin/keystore
ABI: 'arm64'"keystore" sysTid=904#00 pc 000000000006e1c4  /system/lib64/libc.so (__ioctl+4)#01 pc 00000000000290d0  /system/lib64/libc.so (ioctl+136)#02 pc 000000000001cfdc  /system/lib64/libhwbinder.so (android::hardware::IPCThreadState::talkWithDriver(bool)+240)#03 pc 000000000001e018  /system/lib64/libhwbinder.so (android::hardware::IPCThreadState::waitForResponse(android::hardware::Parcel*, int*)+60)#04 pc 000000000001cce4  /system/lib64/libhwbinder.so (android::hardware::BpHwBinder::transact(unsigned int, android::hardware::Parcel const&, android::hardware::Parcel*, unsigned int, std::__1::function<void (android::hardware::Parcel&)>)+132)#05 pc 00000000000148e8  /system/lib64/android.hardware.keymaster@4.0.so (android::hardware::keymaster::V4_0::BpHwKeymasterDevice::_hidl_attestKey(android::hardware::IInterface*, android::hardware::details::HidlInstrumentor*, android::hardware::hidl_vec<unsigned char> const&, android::hardware::hidl_vec<android::hardware::keymaster::V4_0::KeyParameter> const&, std::__1::function<void (android::hardware::keymaster::V4_0::ErrorCode, android::hardware::hidl_vec<android::hardware::hidl_vec<unsigned char>> co  #06 pc 00000000000184d8  /system/lib64/android.hardware.keymaster@4.0.so (android::hardware::keymaster::V4_0::BpHwKeymasterDevice::attestKey(android::hardware::hidl_vec<unsigned char> const&, android::hardware::hidl_vec<android::hardware::keymaster::V4_0::KeyParameter> const&, std::__1::function<void (android::hardware::keymaster::V4_0::ErrorCode, android::hardware::hidl_vec<android::hardware::hidl_vec<unsigned char>> const&)>)+160)#07 pc 00000000000482c4  /system/bin/keystore (android::hardware::keymaster::V4_0::support::Keymaster4::attestKey(android::hardware::hidl_vec<unsigned char> const&, android::hardware::hidl_vec<android::hardware::keymaster::V4_0::KeyParameter> const&, std::__1::function<void (android::hardware::keymaster::V4_0::ErrorCode, android::hardware::hidl_vec<android::hardware::hidl_vec<unsigned char>> const&)>)+212)#08 pc 000000000003d604  /system/bin/keystore (keystore::KeyStoreService::attestKey(android::String16 const&, android::security::keymaster::KeymasterArguments const&, android::security::keymaster::KeymasterCertificateChain*, int*)+832)#09 pc 0000000000016554  /system/lib64/libkeystore_aidl.so (android::security::BnKeystoreService::onTransact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+1432)#10 pc 000000000004fa60  /system/lib64/libbinder.so (android::BBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+136)#11 pc 000000000005ab00  /system/lib64/libbinder.so (android::IPCThreadState::executeCommand(int)+520)#12 pc 000000000005a83c  /system/lib64/libbinder.so (android::IPCThreadState::getAndExecuteCommand()+156)#13 pc 000000000005af04  /system/lib64/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+60)#14 pc 0000000000049484  /system/bin/keystore (main.cfi+1364)#15 pc 00000000000acac8  /system/lib64/libc.so (__libc_init+88)"HwBinder:904_1" sysTid=941#00 pc 000000000006e1c4  /system/lib64/libc.so (__ioctl+4)#01 pc 00000000000290d0  /system/lib64/libc.so (ioctl+136)#02 pc 000000000001cfdc  /system/lib64/libhwbinder.so (android::hardware::IPCThreadState::talkWithDriver(bool)+240)#03 pc 000000000001425c  /system/lib64/libhwbinder.so (android::hardware::IPCThreadState::getAndExecuteCommand()+20)#04 pc 0000000000014588  /system/lib64/libhwbinder.so (android::hardware::IPCThreadState::joinThreadPool(bool)+268)#05 pc 000000000001c1ac  /system/lib64/libhwbinder.so (android::hardware::PoolThread::threadLoop()+24)#06 pc 000000000000f9d8  /system/lib64/libutils.so (android::Thread::_threadLoop(void*)+280)#07 pc 00000000000819b4  /system/lib64/libc.so (__pthread_start(void*)+36)#08 pc 0000000000023478  /system/lib64/libc.so (__start_thread+68)----- end 904 ---------- pid 354 at 2023-10-26 20:47:33 -----
Cmd line: /vendor/bin/hw/android.hardware.keymaster@4.0-service-qti
ABI: 'arm64'"keymaster@4.0-s" sysTid=354#00 pc 000000000006e1c8  /system/lib64/libc.so (__ioctl+8)#01 pc 00000000000290d0  /system/lib64/libc.so (ioctl+136)#02 pc 0000000000001260  /vendor/lib64/libuhab.so (habmm_socket_recv+96)#03 pc 0000000000002150  /vendor/lib64/libkeymasterdeviceutils.so (km_comm_send_cmd+444)#04 pc 000000000000cd00  /vendor/lib64/libqtikeymaster4.so (keymasterdevice::KeymasterHalDevice::attest_key(keymaster_key_blob_t const*, keymaster_key_param_set_t const*, keymaster_cert_chain_t*)+892)#05 pc 000000000000919c  /vendor/lib64/libqtikeymaster4.so (keymaster::V4_0::Keymaster4Device::attestKey(android::hardware::hidl_vec<unsigned char> const&, android::hardware::hidl_vec<android::hardware::keymaster::V4_0::KeyParameter> const&, std::__1::function<void (android::hardware::keymaster::V4_0::ErrorCode, android::hardware::hidl_vec<android::hardware::hidl_vec<unsigned char>> const&)>)+132)#06 pc 000000000001bf18  /system/lib64/vndk-28/android.hardware.keymaster@4.0.so (android::hardware::keymaster::V4_0::BnHwKeymasterDevice::_hidl_attestKey(android::hidl::base::V1_0::BnHwBase*, android::hardware::Parcel const&, android::hardware::Parcel*, std::__1::function<void (android::hardware::Parcel&)>)+484)#07 pc 000000000001e820  /system/lib64/vndk-28/android.hardware.keymaster@4.0.so (android::hardware::keymaster::V4_0::BnHwKeymasterDevice::onTransact(unsigned int, android::hardware::Parcel const&, android::hardware::Parcel*, unsigned int, std::__1::function<void (android::hardware::Parcel&)>)+2048)#08 pc 000000000001d334  /system/lib64/vndk-sp-28/libhwbinder.so (android::hardware::IPCThreadState::executeCommand(int)+640)#09 pc 000000000001430c  /system/lib64/vndk-sp-28/libhwbinder.so (android::hardware::IPCThreadState::getAndExecuteCommand()+196)#10 pc 0000000000014588  /system/lib64/vndk-sp-28/libhwbinder.so (android::hardware::IPCThreadState::joinThreadPool(bool)+268)#11 pc 0000000000000f64  /vendor/bin/hw/android.hardware.keymaster@4.0-service-qti (main+128)#12 pc 00000000000acac8  /system/lib64/libc.so (__libc_init+88)----- end 354 -----

最后就是让qtikeymaster查:

keymasterdevice::KeymasterHalDevice::attest_key