[BUG] crash in libCHipcontroller.so

[netscell]

Reproduction steps

android app encouters this crash sometimes:

android crash log:

PID: 18374
UID: 10239
Frozen: false
Flags: 0x20c83e46
Foreground: No
Process-Runtime: 439568
Lifetime: 439s
Loading-Progress: 1.0
Wakefulness: Awake 2023-09-04 18:16:31.611
KeyguardShowing: false 2023-09-04 18:16:32.464
Dropped-Count: 0

---

Revision: '0'
ABI: 'arm64'
Timestamp: 2023-09-04 18:19:09.155291074+0800
Process uptime: 300s
pid: 18374, tid: 19037, name: CHIP Device Con
uid: 10239
tagged_addr_ctrl: 0000000000000001 (PR_TAGGED_ADDR_ENABLE)
pac_enabled_keys: 000000000000000f (PR_PAC_APIAKEY, PR_PAC_APIBKEY, PR_PAC_APDAKEY, PR_PAC_APDBKEY)
signal 6 (SIGABRT), code -1 (SI_QUEUE), fault addr --------
Abort message: 'JNI DETECTED ERROR IN APPLICATION: mid == null
in call to NewObjectV'
x0 0000000000000000 x1 0000000000004a5d x2 0000000000000006 x3 000000712eeba180
x4 ff6d6e6873606268 x5 ff6d6e6873606268 x6 ff6d6e6873606268 x7 7f7f7f7f7f7f7f7f
x8 00000000000000f0 x9 00000074022bb398 x10 0000000000000001 x11 00000074022fb5b8
x12 00000000000050fe x13 ffffffffffffffff x14 ff00000000000000 x15 ffffffffffffffff
x16 000000740235ff88 x17 000000740233d450 x18 000000712a8c2000 x19 00000000000047c6
x20 0000000000004a5d x21 00000000ffffffff x22 0000000000000000 x23 000000712eeba3b8
x24 0000000000000000 x25 000000712eeba3b0 x26 000000712eebb000 x27 0000007141a16000
x28 000000714180b418 x29 000000712eeba200
lr 00000074022ed044 sp 000000712eeba160 pc 00000074022ed070 pst 0000000000001000
backtrace:
NOTE: Function names and BuildId information is missing for some frames due
NOTE: to unreadable libraries. For unwinds of apps, only shared libraries
NOTE: found under the lib/ directory are readable.
NOTE: On this device, run setenforce 0 to make the libraries readable.
NOTE: Unreadable libraries:
NOTE: /lib/arm64-v8a/libCHIPController.so
#00 pc 0000000000054070 /apex/com.android.runtime/lib64/bionic/libc.so (abort+164) (BuildId: 25eadd32a5b6753e7e58e01ae8014530)
#1 pc 0000000000616b9c /apex/com.android.art/lib64/libart.so (art::Runtime::Abort(char const*)+1248) (BuildId: d53f2ad8deb01876e35b599a414617a1)
#2 pc 0000000000016ea8 /apex/com.android.art/lib64/libbase.so (android::base::SetAborter(std::__1::function<void (char const*)>&&)::$_3::__invoke(char const*)+80) (BuildId: 5965f2954d5067bd4a154d2af88c3f5b)
#3 pc 0000000000016450 /apex/com.android.art/lib64/libbase.so (android::base::LogMessage::~LogMessage()+352) (BuildId: 5965f2954d5067bd4a154d2af88c3f5b)
#4 pc 0000000000453004 /apex/com.android.art/lib64/libart.so (art::JavaVMExt::JniAbort(char const*, char const*)+2360) (BuildId: d53f2ad8deb01876e35b599a414617a1)
#5 pc 00000000004c80b4 /apex/com.android.art/lib64/libart.so (art::JNI::NewObjectV(_JNIEnv*, _jclass*, _jmethodID*, std::__va_list)+860) (BuildId: d53f2ad8deb01876e35b599a414617a1)
#6 pc 00000000002d26f0 /lib/arm64-v8a/libCHIPController.so
#7 pc 00000000002d6704 /lib/arm64-v8a/libCHIPController.so
#8 pc 00000000002d1fc4 /lib/arm64-v8a/libCHIPController.so
#9 pc 00000000008fee6c /lib/arm64-v8a/libCHIPController.so
#10 pc 00000000008fead4 /lib/arm64-v8a/libCHIPController.so
#11 pc 00000000008fefb0 /lib/arm64-v8a/libCHIPController.so
#12 pc 00000000009bffd8 /lib/arm64-v8a/libCHIPController.so
#13 pc 00000000009b67cc /lib/arm64-v8a/libCHIPController.so
#14 pc 000000000091a2cc /lib/arm64-v8a/libCHIPController.so
#15 pc 00000000009207c4 /lib/arm64-v8a/libCHIPController.so
#16 pc 000000000099a780 /lib/arm64-v8a/libCHIPController.so
#17 pc 00000000002dcfa8 /lib/arm64-v8a/libCHIPController.so
#18 pc 00000000000b8b98 /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+208) (BuildId: 25eadd32a5b6753e7e58e01ae8014530)
#19 pc 0000000000055794 /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64) (BuildId: 25eadd32a5b6753e7e58e01ae8014530)

Bug prevalence

3-7times a week

GitHub hash of the SDK that was being used

sdk version 1.0.0.2

Platform

android

Platform Version(s)

No response

Anything else?

No response

[joonhaengHeo]

@netscell
Please upload full log and libCHIPController.so file after building.

[netscell]

some app log ：
09-05 14:57:26.961 14428 14646 D DIS : Checking node lookup status after 45013 ms
09-05 14:57:26.961 14428 14646 E DIS : OperationalSessionSetup[1:00000000000000C7]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
09-05 14:57:26.967 14428 14646 F e:communication: java_vm_ext.cc:594] JNI DETECTED ERROR IN APPLICATION: mid == null
09-05 14:57:26.967 14428 14646 F e:communication: java_vm_ext.cc:594] in call to NewObjectV

09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] Runtime aborting...
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] Dumping all threads without mutator lock held
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] All threads:
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] DALVIK THREADS (186):
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] "CHIP Device Controller IO Thread" prio=5 tid=114 Runnable
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] | group="" sCount=0 ucsCount=0 flags=0 obj=0x17a066a0 self=0x714bb82550
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] | sysTid=14646 nice=0 cgrp=foreground sched=0/0 handle=0x6efa732cb0
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] | state=R schedstat=( 364850124931 107259245136 404916 ) utm=30672 stm=5812 core=2 HZ=100
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] | stack=0x6efa63b000-0x6efa63d000 stackSize=991KB
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] | held mutexes= "abort lock" "mutator lock"(shared held)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #00 pc 000000000055c840 /apex/com.android.art/lib64/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits >&, int, BacktraceMap*, char const*, art::ArtMethod*, void*, bool)+148) (BuildId: d53f2ad8deb01876e35b599a414617a1)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #1 pc 000000000065ec74 /apex/com.android.art/lib64/libart.so (art::Thread::DumpStack(std::__1::basic_ostream<char, std::__1::char_traits >&, bool, BacktraceMap*, bool) const+340) (BuildId: d53f2ad8deb01876e35b599a414617a1)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #2 pc 000000000067b808 /apex/com.android.art/lib64/libart.so (art::DumpCheckpoint::Run(art::Thread*)+908) (BuildId: d53f2ad8deb01876e35b599a414617a1)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #3 pc 0000000000675744 /apex/com.android.art/lib64/libart.so (art::ThreadList::RunCheckpoint(art::Closure*, art::Closure*)+504) (BuildId: d53f2ad8deb01876e35b599a414617a1)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #4 pc 0000000000674a24 /apex/com.android.art/lib64/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits >&, bool)+1820) (BuildId: d53f2ad8deb01876e35b599a414617a1)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #5 pc 000000000062c118 /apex/com.android.art/lib64/libart.so (art::AbortState::Dump(std::__1::basic_ostream<char, std::__1::char_traits >&) const+212) (BuildId: d53f2ad8deb01876e35b599a414617a1)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #6 pc 0000000000616cb0 /apex/com.android.art/lib64/libart.so (art::Runtime::Abort(char const*)+1524) (BuildId: d53f2ad8deb01876e35b599a414617a1)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #7 pc 0000000000016ea8 /apex/com.android.art/lib64/libbase.so (android::base::SetAborter(std::__1::function<void (char const*)>&&)::$_3::__invoke(char const*)+80) (BuildId: 5965f2954d5067bd4a154d2af88c3f5b)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #8 pc 0000000000016450 /apex/com.android.art/lib64/libbase.so (android::base::LogMessage::~LogMessage()+352) (BuildId: 5965f2954d5067bd4a154d2af88c3f5b)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #9 pc 0000000000453004 /apex/com.android.art/lib64/libart.so (art::JavaVMExt::JniAbort(char const*, char const*)+2360) (BuildId: d53f2ad8deb01876e35b599a414617a1)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #10 pc 00000000004c80b4 /apex/com.android.art/lib64/libart.so (art::JNI::NewObjectV(_JNIEnv*, _jclass*, _jmethodID*, std::__va_list)+860) (BuildId: d53f2ad8deb01876e35b599a414617a1)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #11 pc 00000000002d26f0 /data/data/app/lib/arm64-v8a/libCHIPController.so (???)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #12 pc 00000000002d6704 /data/data/app/lib/arm64-v8a/libCHIPController.so (???)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #13 pc 00000000002d1fc4 /data/data/app/lib/arm64-v8a/libCHIPController.so (???)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #14 pc 00000000008fee6c /data/data/app/lib/arm64-v8a/libCHIPController.so (chip::OperationalSessionSetup::NotifyConnectionCallbacks(chip::Callback::Cancelable&, chip::Callback::Cancelable&, chip::ChipError, chip::ScopedNodeId const&, bool, chip::Messaging::ExchangeManager*, chip::Optionalchip::SessionHandle const&)+128)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #15 pc 00000000008fead4 /data/data/app/lib/arm64-v8a/libCHIPController.so (chip::OperationalSessionSetup::DequeueConnectionCallbacks(chip::ChipError, chip::OperationalSessionSetup::ReleaseBehavior)+332)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #16 pc 00000000008ff6cc /data/data/app/lib/arm64-v8a/libCHIPController.so (chip::OperationalSessionSetup::OnNodeAddressResolutionFailed(chip::PeerId const&, chip::ChipError)+224)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #17 pc 000000000099c848 /data/data/app/lib/arm64-v8a/libCHIPController.so (???)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #18 pc 000000000099c8b4 /data/data/app/lib/arm64-v8a/libCHIPController.so (???)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #19 pc 00000000009207c4 /data/data/app/lib/arm64-v8a/libCHIPController.so (???)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #20 pc 000000000099a780 /data/data/app/lib/arm64-v8a/libCHIPController.so (???)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #21 pc 00000000002dcfa8 /data/data/app/lib/arm64-v8a/libCHIPController.so (???)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #22 pc 00000000000b8b98 /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+208) (BuildId: 25eadd32a5b6753e7e58e01ae8014530)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] native: #23 pc 0000000000055794 /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64) (BuildId: 25eadd32a5b6753e7e58e01ae8014530)
09-05 14:57:27.187 14428 14646 F e:communication: runtime.cc:695] (no managed stack frames)

[joonhaengHeo]

The libCHIPController.so file is required to accurately analyze the dump log.
There are limits to accurate analysis with only some logs.

[netscell]

libCHIPController.zip

[joonhaengHeo]

It is difficult to determine the exact situation as there is no full log for the previous situation, but it is believed that an exception occurred in the code below.

reason :
Log :
09-05 14:57:26.961 14428 14646 E DIS : OperationalSessionSetup[1:00000000000000C7]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
-> The only situations where this log may occur in ChipTool are below.
Here, when an exception occurs, the app crashes because the app is handled as an IllegalStateException. (There is no part where IllegalStateException is handled.)

connectedhomeip/examples/android/CHIPTool/app/src/main/java/com/google/chip/chiptool/ChipClient.kt

Line 85 in ecba41d

suspend fun getConnectedDevicePointer(context: Context, nodeId: Long): Long {

connectedhomeip/examples/android/CHIPTool/app/src/main/java/com/google/chip/chiptool/ChipClient.kt

Line 106 in ecba41d

continuation.resumeWithException(IllegalStateException(errorMessage))

To prevent this, it seems that exception handling should be added on the calling side, but it is necessary to review whether this approach is correct.

[netscell]

no use android chiptool application；

[yunhanw-google]

@netscell is this still issue? have you tried the suggestion from @joonhaengHeo ? thanks

[netscell]

also encouter the same error log:
11-14 20:01:37.129 24933 25089 D DIS : Checking node lookup status after 45022 ms
11-14 20:01:37.130 24933 25089 E DIS : OperationalSessionSetup[1:0000000000000006]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
11-14 20:01:37.130 24933 25089 E DMG : Failed to establish CASE for re-subscription with error 'src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout'
11-14 20:01:37.130 24933 25089 D DMG : MoveToState ReadClient[0x71e8de3450]: Moving to [ Idle]
11-14 20:01:37.130 24933 25089 D DMG : Will try to resubscribe to 01:0000000000000006 at retry index 1 after 4633ms due to error src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
11-14 20:01:37.131 24933 25089 D IN : SecureSession[0x71ccde3d30]: MarkAsDefunct Type:2 LSID:12098
11-14 20:01:37.133 24933 25089 F e:communication: java_vm_ext.cc:594] JNI DETECTED ERROR IN APPLICATION: mid == null
11-14 20:01:37.133 24933 25089 F e:communication: java_vm_ext.cc:594] in call to NewObjectV