PN7160 NfcService: Watchdog triggered

[dx1]

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]

Hi @dx1 :

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

Regards

Daniel

[dx1]

Hi danielchen :

Sorry，It's PN7150

[danielchen]

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