PN7160 NfcService: Watchdog triggered

dx1 · ‎03-13-2023

I use PN7160 to work on Android 10. Sometimes a watchdog reset is triggered, and then the device does not work normally until the app is restarted。

M11B104 01-13 09:31:52.758 433 433 D NxpExtns: find found MIFARE_READER_ENABLE=(0x1)

M11B105 01-13 09:31:52.758 433 433 D NfccPowerTracker: NfccPowerTracker::ProcessCmd: Enter,Recieved len :7

M11B106 01-13 09:31:52.758 433 2200 D NxpTml : PN54X - Write requested.....

M11B107 01-13 09:31:52.758 433 2200 D NxpTml : PN54X - Invoking I2C Write.....

M11B108 01-13 09:31:52.759 433 2200 D NxpNciX : len = 7 > 2F3304400040D8

M11B109 01-13 09:31:52.760 433 2200 D NxpTml : PN54X - I2C Write successful.....

M11B10A 01-13 09:31:52.760 433 2200 D NxpTml : PN54X - Posting Fresh Write message.....

M11B10B 01-13 09:31:52.760 433 2200 D NxpTml : PN54X - Tml Writer Thread Running................

M11B10C 01-13 09:31:52.760 433 2202 D NxpHal : write successful status = 0x0

M11B10D 01-13 09:31:52.763 433 2199 D NxpTml : PN54X - I2C Read successful.....

M11B10E 01-13 09:31:52.763 433 2199 D NxpNciR : len = 7 > 4F330490010000

M11B10F 01-13 09:31:52.763 433 2199 D NxpTml : PN54X - Posting read message.....

M11B110 01-13 09:31:52.764 433 2202 D NxpHal : read successful status = 0x0

M11B111 01-13 09:31:52.764 1976 2194 I libnfc_nci: [INFO:nfc_ncif.cc(1747)] nfc_ncif_proc_proprietary_rsp: mt=2, gid=15, oid=51

M11B112 01-13 09:31:52.764 1976 2194 I libnfc_nci: [INFO:nfc_ncif.cc(1780)] nfc_ncif_proc_proprietary_rsp: exit status=1

M11B113 01-13 09:31:52.764 1976 2194 I libnfc_nci: [INFO:phNxpExtns_DebugAgc.cpp(237)] nfcManagerAgcDebugCb: Received length data = 0x7

M11B114 01-13 09:31:52.765 1976 16323 I libnfc_nci: [INFO:phNxpExtns_DebugAgc.cpp(212)] printDataByte: AGC Dynamic RSSI values =

M11B115 01-13 09:31:52.765 1976 16323 I libnfc_nci: [INFO:phNxpExtns_DebugAgc.cpp(294)] sendAgcDebugCmd: Exit

M11B116 01-13 09:31:52.765 1976 16323 I libnfc_nci: [INFO:phNxpExtns_DebugAgc.cpp(147)] enableAgcThread: enable success exit

M11B117 01-13 09:31:52.765 433 2199 D NxpTml : PN54X - Read requested.....

M11B118 01-13 09:31:52.765 433 2199 D NxpTml : PN54X - Invoking I2C Read.....

M11B119 01-13 09:31:52.884 1976 17216 E NfcService: Watchdog triggered, release lock before aborting.

M11B11A 01-13 09:31:52.886 1976 17216 E NfcService: Watchdog triggered, aborting.

M11B11B 01-13 09:31:52.913 1976 17216 F com.android.nf: jni_internal.cc:893] JNI FatalError called: applyRouting

M11B11C 01-13 09:31:53.024 636 1450 D GNSSMGT : watchdog: PowerState[CP SLEEP], gps_flag[3], readcount[256], idle time = 0, HeartCount = 0

M11B11D 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] Runtime aborting...

M11B11E 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] Dumping all threads without mutator lock held

M11B11F 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] All threads:

M11B120 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] DALVIK THREADS (20

M11B121 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] "applyRouting" prio=5 tid=3 Runnable

M11B122 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] | group="" sCount=0 dsCount=0 flags=0 obj=0x12c43200 self=0x725d90f400

M11B123 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] | sysTid=17216 nice=0 cgrp=default sched=0/0 handle=0x725ec7ed50

M11B124 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] | state=R schedstat=( 42795232 374886 8 ) utm=1 stm=2 core=4 HZ=100

M11B125 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] | stack=0x725eb7c000-0x725eb7e000 stackSize=1039KB

M11B126 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] | held mutexes= "abort lock" "mutator lock"(shared held)

M11B127 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #00 pc 000000000040c5bc /apex/com.android.runtime/lib64/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, int, BacktraceMap*, char const*, art::ArtMethod*, void*, bool)+140)

M11B128 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #01 pc 00000000004f1610 /apex/com.android.runtime/lib64/libart.so (art::Thread::DumpStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool, BacktraceMap*, bool) const+508)

M11B129 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #02 pc 000000000050b6fc /apex/com.android.runtime/lib64/libart.so (art::DumpCheckpoint::Run(art::Thread*)+820)

M11B12A 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #03 pc 0000000000504ae4 /apex/com.android.runtime/lib64/libart.so (art::ThreadList::RunCheckpoint(art::Closure*, art::Closure*)+552)

M11B12B 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #04 pc 0000000000503edc /apex/com.android.runtime/lib64/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool)+1816)

M11B12C 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #05 pc 00000000004b1ef4 /apex/com.android.runtime/lib64/libart.so (art::Runtime::Abort(char const*)+1456)

M11B12D 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #06 pc 000000000000c5b4 /system/lib64/libbase.so (android::base::LogMessage::~LogMessage()+608)

M11B12E 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #07 pc 0000000000380d7c /apex/com.android.runtime/lib64/libart.so (art::JNI::FatalError(_JNIEnv*, char const*)+196)

M11B12F 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #08 pc 0000000000033700 /system/lib64/libnfc_nci_jni.so (android::nfcManager_doAbort(_JNIEnv*, _jobject*, _jstring*)+48)

M11B130 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #09 pc 0000000000009dd8 /data/dalvik-cache/arm64/system@app@NfcNci@NfcNci.apk@classes.dex (art_jni_trampoline+152)

M11B131 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #10 pc 0000000000136334 /apex/com.android.runtime/lib64/libart.so (art_quick_invoke_stub+548)

M11B132 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #11 pc 000000000014506c /apex/com.android.runtime/lib64/libart.so (art::ArtMethod::Invoke(art::Thread*, unsigned int*, unsigned int, art::JValue*, char const*)+244)

M11B133 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #12 pc 00000000002df75c /apex/com.android.runtime/lib64/libart.so (art::interpreter::ArtInterpreterToCompiledCodeBridge(art::Thread*, art::ArtMethod*, art::ShadowFrame*, unsigned short, art::JValue*)+384)

M11B134 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #13 pc 00000000002daa3c /apex/com.android.runtime/lib64/libart.so (bool art::interpreter::DoCall<false, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*)+912)

M11B135 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #14 pc 0000000000599a38 /apex/com.android.runtime/lib64/libart.so (MterpInvokeInterface+868)

M11B136 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #15 pc 0000000000130a14 /apex/com.android.runtime/lib64/libart.so (mterp_op_invoke_interface+20)

M11B137 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #16 pc 00000000000f56be /system/app/NfcNci/NfcNci.apk (com.android.nfc.NfcService$WatchDogThread.run+178)

M11B138 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #17 pc 00000000002b03a8 /apex/com.android.runtime/lib64/libart.so (_ZN3art11interpreterL7ExecuteEPNS_6ThreadERKNS_20CodeItemDataAccessorERNS_11ShadowFrameENS_6JValueEbb.llvm.242360688288835721+240)

M11B139 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #18 pc 00000000005898a4 /apex/com.android.runtime/lib64/libart.so (artQuickToInterpreterBridge+1012)

M11B13A 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #19 pc 000000000013f468 /apex/com.android.runtime/lib64/libart.so (art_quick_to_interpreter_bridge+88)

M11B13B 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #20 pc 0000000000136334 /apex/com.android.runtime/lib64/libart.so (art_quick_invoke_stub+548)

M11B13C 01-13 09:31:53.152 1976 17216 F com.android.nf: runtime.cc:630] native: #21 pc 000000000014506c /apex/com.android.runtime/lib64/libart.so (art::ArtMethod::Invoke(art::Thread*, unsigned int*, unsigned int, art::JValue*, char const*)+244)

M11B13D 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] native: #22 pc 00000000004a9e8c /apex/com.android.runtime/lib64/libart.so (art::(anonymous namespace)::InvokeWithArgArray(art::ScopedObjectAccessAlreadyRunnable const&, art::ArtMethod*, art::(anonymous namespace)::ArgArray*, art::JValue*, char const*)+104)

M11B13E 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] native: #23 pc 00000000004aaf20 /apex/com.android.runtime/lib64/libart.so (art::InvokeVirtualOrInterfaceWithJValues(art::ScopedObjectAccessAlreadyRunnable const&, _jobject*, _jmethodID*, jvalue const*)+416)

M11B13F 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] native: #24 pc 00000000004eacbc /apex/com.android.runtime/lib64/libart.so (art::Thread::CreateCallback(void*)+1176)

M11B140 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] native: #25 pc 00000000000e1100 /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+36)

M11B141 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] native: #26 pc 0000000000083ab0 /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64)

M11B142 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] at com.android.nfc.dhimpl.NativeNfcManager.doAbort(Native method)

M11B143 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] at com.android.nfc.NfcService$WatchDogThread.run(NfcService.java:1743)

M11B144 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630]

M11B145 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] "main" prio=5 tid=1 Blocked

M11B146 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] | group="" sCount=1 dsCount=0 flags=1 obj=0x763d32d8 self=0x72f31bf000

M11B147 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] | sysTid=1976 nice=0 cgrp=default sched=0/0 handle=0x72f4719ed0

M11B148 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] | state=S schedstat=( 647664867 360049289 1391 ) utm=37 stm=27 core=1 HZ=100

M11B149 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] | stack=0x7fe5246000-0x7fe5248000 stackSize=8192KB

M11B14A 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] | held mutexes=

M11B14B 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] kernel: (couldn't read /proc/self/task/1976/stack)

M11B14C 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] native: #00 pc 000000000007f23c /apex/com.android.runtime/lib64/bionic/libc.so (syscall+28)

M11B14D 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] native: #01 pc 000000000014af34 /apex/com.android.runtime/lib64/libart.so (art::ConditionVariable::WaitHoldingLocks(art::Thread*)+148)

M11B14E 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] native: #02 pc 00000000004037d8 /apex/com.android.runtime/lib64/libart.so (_ZN3art7Monitor4LockILNS_10LockReasonE1EEEvPNS_6ThreadE+1880)

M11B14F 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] native: #03 pc 00000000004090bc /apex/com.android.runtime/lib64/libart.so (art::Monitor::MonitorEnter(art::Thread*, art::ObjPtr<art::mirror::Object>, bool)+696)

M11B150 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] native: #04 pc 000000000058882c /apex/com.android.runtime/lib64/libart.so (artLockObjectFromCode+32)

M11B151 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] native: #05 pc 00000000001367e4 /apex/com.android.runtime/lib64/libart.so (art_quick_lock_object_no_inline+52)

M11B152 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] native: #06 pc 000000000200063c /memfd:/jit-cache (deleted) (com.android.nfc.NfcService$NfcServiceHandler.handleMessage+620)

M11B153 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] at com.android.nfc.NfcService$NfcServiceHandler.handleMessage(NfcService.java:2318)

M11B154 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] - waiting to lock <0x08ba0bd6> (a com.android.nfc.NfcService) held by thread 17

M11B155 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] at android.os.Handler.dispatchMessage(Handler.java:107)

M11B156 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] at android.os.Looper.loop(Looper.java:214)

M11B157 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] at android.app.ActivityThread.main(ActivityThread.java:7626)

M11B158 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] at java.lang.reflect.Method.invoke(Native method)

M11B159 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:503)

M11B15A 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:936)

M11B15B 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630]

M11B15C 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] "Jit thread pool worker thread 0" prio=5 tid=2 Native

M11B15D 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] | group="" sCount=1 dsCount=0 flags=1 obj=0x140401a8 self=0x7262400000

M11B15E 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] | sysTid=1992 nice=0 cgrp=default sched=0/0 handle=0x726378ad40

M11B15F 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] | state=S schedstat=( 80856122 21839844 37 ) utm=6 stm=1 core=4 HZ=100

M11B160 01-13 09:31:53.153 1976 17216 F com.android.nf: runtime.cc:630] | stack=0x726368c000-0x726368e000 stackSize=1023KB

danielchen · ‎03-16-2023

Hi @dx1 :

The first supported version for PN7160 is Android 11. Are you sure you are using PN7160 + Android10?

Regards

Daniel

dx1 · ‎03-16-2023

Hi danielchen :

Sorry，It's PN7150

danielchen · ‎03-19-2023

Hi

Could you please provide us logs with initial setup, so we can see what is send before we start discovery.

Did you use our patches => https://github.com/NXPNFCLinux/nxpnfc_android_q ?

When watchdog is triggered, is there still polling on PN7150? since watchdog can be triggered only on Device host, so could be some code which is creating problems.

Regards

Daniel