phhusson / treble_experimentations

Notes about tinkering with Android Project Treble
3.36k stars 658 forks source link

[Razer Phone 2 / Android 11] NFC doesn't work correctly (crashing). #1699

Open lss4 opened 3 years ago

lss4 commented 3 years ago

GSI: Nusantara 2.5.1 (Android 11, January security patch)

NFC doesn't work correctly on my device with this GSI. Since I don't really know a good means to report the issue directly to Igor-s7 I'm putting this here.

Simply put, the NFC service works upon startup, but after some NFC operations, or simply a few minutes after boot, the service would crash and never recover.

The following can be found in the logcat.

01-16 16:32:35.361  5286  5778 F libc    : Fatal signal 6 (SIGABRT), code -1 (SI_QUEUE) in tid 5778 (AsyncTask #1), pid 5286 (com.android.nfc)
01-16 16:32:35.443 10257 10257 F DEBUG   : *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
01-16 16:32:35.443 10257 10257 F DEBUG   : Build fingerprint: 'google/redfin/redfin:11/RQ1A.210105.003/7005429:user/release-keys'
01-16 16:32:35.443 10257 10257 F DEBUG   : Revision: '0'
01-16 16:32:35.443 10257 10257 F DEBUG   : ABI: 'arm64'
01-16 16:32:35.444 10257 10257 F DEBUG   : Timestamp: 2021-01-16 16:32:35+0800
01-16 16:32:35.444 10257 10257 F DEBUG   : pid: 5286, tid: 5778, name: AsyncTask #1  >>> com.android.nfc <<<
01-16 16:32:35.444 10257 10257 F DEBUG   : uid: 1027
01-16 16:32:35.444 10257 10257 F DEBUG   : signal 6 (SIGABRT), code -1 (SI_QUEUE), fault addr --------
01-16 16:32:35.444 10257 10257 F DEBUG   :     x0  0000000000000000  x1  0000000000001692  x2  0000000000000006  x3  000000745c1b9d00
01-16 16:32:35.444 10257 10257 F DEBUG   :     x4  00000000341555ac  x5  00000000341555ac  x6  00000000341555ac  x7  000000006002a4a3
01-16 16:32:35.444 10257 10257 F DEBUG   :     x8  00000000000000f0  x9  624e11654da4c8b7  x10 0000000000000000  x11 ffffffc0fffffbdf
01-16 16:32:35.444 10257 10257 F DEBUG   :     x12 0000000000000001  x13 0000000000000052  x14 0000000000000000  x15 0000000000000001
01-16 16:32:35.444 10257 10257 F DEBUG   :     x16 000000775b785c80  x17 000000775b765dc0  x18 000000745bbb2000  x19 00000000000014a6
01-16 16:32:35.444 10257 10257 F DEBUG   :     x20 0000000000001692  x21 00000000ffffffff  x22 000000745c1bb000  x23 00000074626393f0
01-16 16:32:35.444 10257 10257 F DEBUG   :     x24 00000074627d2810  x25 00000074627d2810  x26 00000000ffffc400  x27 0000007462719f22
01-16 16:32:35.444 10257 10257 F DEBUG   :     x28 000000745c1ba921  x29 000000745c1b9d80
01-16 16:32:35.444 10257 10257 F DEBUG   :     lr  000000775b7184c0  sp  000000745c1b9ce0  pc  000000775b7184ec  pst 0000000000000000
01-16 16:32:35.449 10257 10257 F DEBUG   : backtrace:
01-16 16:32:35.449 10257 10257 F DEBUG   :       #00 pc 000000000004e4ec  /apex/com.android.runtime/lib64/bionic/libc.so (abort+164) (BuildId: c3a808d6bcb758a52262da65e82eadeb)
01-16 16:32:35.449 10257 10257 F DEBUG   :       #01 pc 0000000000035d4c  /system/lib64/libnfc_nci_jni.so (android::nfaDeviceManagementCallback(unsigned char, tNFA_DM_CBACK_DATA*)+2724) (BuildId: f595c0bf4eee746223d5c907dfbea9a8)
01-16 16:32:35.449 10257 10257 F DEBUG   :       #02 pc 000000000004278c  /system/lib64/libnfc-nci.so (nfa_dm_nfc_response_cback(unsigned short, tNFC_RESPONSE*) (.cfi)+560) (BuildId: ae2b85c6fb4559be38b4763812b37de2)
01-16 16:32:35.449 10257 10257 F DEBUG   :       #03 pc 000000000008a438  /system/lib64/libnfc-nci.so (nfc_ncif_cmd_timeout() (.cfi)+368) (BuildId: ae2b85c6fb4559be38b4763812b37de2)
01-16 16:32:35.449 10257 10257 F DEBUG   :       #04 pc 000000000008e14c  /system/lib64/libnfc-nci.so (nfc_ncif_proc_reset_rsp(unsigned char*, bool) (.cfi)+856) (BuildId: ae2b85c6fb4559be38b4763812b37de2)
01-16 16:32:35.449 10257 10257 F DEBUG   :       #05 pc 0000000000084a88  /system/lib64/libnfc-nci.so (nci_proc_core_ntf(NFC_HDR*) (.cfi)+348) (BuildId: ae2b85c6fb4559be38b4763812b37de2)
01-16 16:32:35.449 10257 10257 F DEBUG   :       #06 pc 000000000008adac  /system/lib64/libnfc-nci.so (nfc_ncif_process_event(NFC_HDR*) (.cfi)+792) (BuildId: ae2b85c6fb4559be38b4763812b37de2)
01-16 16:32:35.449 10257 10257 F DEBUG   :       #07 pc 000000000008f028  /system/lib64/libnfc-nci.so (nfc_task(unsigned int) (.cfi)+760) (BuildId: ae2b85c6fb4559be38b4763812b37de2)
01-16 16:32:35.449 10257 10257 F DEBUG   :       #08 pc 00000000000c13ec  /system/lib64/libnfc-nci.so (gki_task_entry(void*) (.cfi)+280) (BuildId: ae2b85c6fb4559be38b4763812b37de2)
01-16 16:32:35.449 10257 10257 F DEBUG   :       #09 pc 00000000000b2c3c  /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+64) (BuildId: c3a808d6bcb758a52262da65e82eadeb)
01-16 16:32:35.449 10257 10257 F DEBUG   :       #10 pc 00000000000504a8  /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64) (BuildId: c3a808d6bcb758a52262da65e82eadeb)

Also, I'm attaching the tombstone related to the logcat error messages here. tombstone_05.gz

Reznor7 commented 3 years ago

I'm having the same exact issue on my RP2 using Lineage OS 18.1 (Android 11) GSI.

lss4 commented 3 years ago

It seems you can simply reproduce the issue by placing an NFC tag for reading.

You'll hear the NFC tag detection sound but it'll be interrupted shortly after as the NFC service crashes.

02-22 10:51:07.514  5543  5543 D NativeNfcTag: Connect to a tech with a different handle
02-22 10:51:07.597  5543  5543 D NativeNfcTag: Check NDEF Failed - status = 3
02-22 10:51:07.607  5543  5543 D NativeNfcTag: Check NDEF Failed - status = 3
02-22 10:51:07.607  5543  5543 D NativeNfcTag: Check NDEF Failed - status = 3
02-22 10:51:07.607  5543  5543 D NativeNfcTag: Connect to a tech with a different handle
02-22 10:51:07.628  5543  6037 E libnfc_nci: [ERROR:rw_mfc.cc(527)] RW_MfcDetectNDef
02-22 10:51:07.630  5543  6037 E libnfc_nci: [ERROR:rw_mfc.cc(876)] rw_mfc_readBlock: RW_MFC_SUBSTATE_WAIT_ACK
...
02-22 10:51:08.535  1095  6063 E NxpTml  : _i2c_write() errno : 5
02-22 10:51:08.536  1095  6063 E NxpTml  : PN54X - Error in I2C Write.....
02-22 10:51:08.536  1095  6065 E NxpHal  : write error status = 0x1ff
02-22 10:51:08.536  1095  1095 E NxpHal  : write_unlocked failed - PN54X Maybe in Standby Mode - Retry
02-22 10:51:08.542  1095  6063 E NxpTml  : _i2c_write() errno : 5
02-22 10:51:08.542  1095  6063 E NxpTml  : PN54X - Error in I2C Write.....
02-22 10:51:08.542  1095  6065 E NxpHal  : write error status = 0x1ff
02-22 10:51:08.542  1095  1095 E NxpHal  : write_unlocked failed - PN54X Maybe in Standby Mode - Retry
02-22 10:51:08.547  1095  6063 E NxpTml  : _i2c_write() errno : 5
02-22 10:51:08.547  1095  6063 E NxpTml  : PN54X - Error in I2C Write.....
02-22 10:51:08.547  1095  6065 E NxpHal  : write error status = 0x1ff
02-22 10:51:08.547  1095  1095 E NxpHal  : write_unlocked failed - PN54X Maybe in Standby Mode - Retry
02-22 10:51:08.553  1095  6063 E NxpTml  : _i2c_write() errno : 5
02-22 10:51:08.553  1095  6063 E NxpTml  : PN54X - Error in I2C Write.....
02-22 10:51:08.553  1095  6065 E NxpHal  : write error status = 0x1ff
02-22 10:51:08.553  1095  1095 E NxpHal  : write_unlocked failed - PN54X Maybe in Standby Mode - Retry
02-22 10:51:08.558  1095  6063 E NxpTml  : _i2c_write() errno : 5
02-22 10:51:08.558  1095  6063 E NxpTml  : PN54X - Error in I2C Write.....
02-22 10:51:08.558  1095  6065 E NxpHal  : write error status = 0x1ff
02-22 10:51:08.559  1095  1095 E NxpHal  : write_unlocked failed - PN54X Maybe in Standby Mode - Retry
02-22 10:51:08.564  1095  6063 E NxpTml  : _i2c_write() errno : 5
02-22 10:51:08.564  1095  6063 E NxpTml  : PN54X - Error in I2C Write.....
02-22 10:51:08.564  1095  6065 E NxpHal  : write error status = 0x1ff
02-22 10:51:08.564  1095  1095 E NxpHal  : write_unlocked failed - PN54X Maybe in Standby Mode (max count = 0x6)
02-22 10:51:08.716  5543  6037 E libnfc_nci: [ERROR:nfc_ncif.cc(1689)] reset notification!!:0xa0 
02-22 10:51:08.716  5543  6037 E libnfc_nci: [ERROR:nfc_ncif.cc(137)] nfc_ncif_cmd_timeout
02-22 10:51:08.729  5543  6037 E libnfc_nci: [ERROR:NativeNfcManager.cpp(819)] nfaDeviceManagementCallback: NFA_DM_NFCC_TIMEOUT_EVT; abort
02-22 10:51:08.729  5543  6037 E libnfc_nci: [ERROR:NativeNfcManager.cpp(860)] nfaDeviceManagementCallback: crash NFC service
02-22 10:51:08.731  5543  5543 D NativeNfcTag: Check NDEF Failed - status = 3
02-22 10:51:08.735  5543  6037 F libc    : Fatal signal 6 (SIGABRT), code -1 (SI_QUEUE) in tid 6037 (Thread-3), pid 5543 (com.android.nfc)
02-22 10:51:08.737  5543 16226 D NativeNfcTag: Starting background presence check
...
02-22 10:51:08.795  5543  5596 D NativeNfcTag: Connect to a tech with a different handle
...

Then the same crash log as above.

The NFC service would attempt to recover but it'll eventually fail. The logcat seems to point to the QS tile handler...

And here's the question: Aside from the recovery failure I saw no other mentions of NFC in the logcat so it's possible the recovery never happened at all...

02-22 10:51:13.082  3219  3401 E NFC     : NFC service dead - attempting to recover
02-22 10:51:13.082  3219  3401 E NFC     : android.os.DeadObjectException
02-22 10:51:13.082  3219  3401 E NFC     :  at android.os.BinderProxy.transactNative(Native Method)
02-22 10:51:13.082  3219  3401 E NFC     :  at android.os.BinderProxy.transact(BinderProxy.java:550)
02-22 10:51:13.082  3219  3401 E NFC     :  at android.nfc.INfcAdapter$Stub$Proxy.getState(INfcAdapter.java:718)
02-22 10:51:13.082  3219  3401 E NFC     :  at android.nfc.NfcAdapter.isEnabled(NfcAdapter.java:851)
02-22 10:51:13.082  3219  3401 E NFC     :  at com.android.systemui.qs.tiles.NfcTile.handleUpdateState(NfcTile.java:136)
02-22 10:51:13.082  3219  3401 E NFC     :  at com.android.systemui.qs.tiles.NfcTile.handleUpdateState(NfcTile.java:42)
02-22 10:51:13.082  3219  3401 E NFC     :  at com.android.systemui.qs.tileimpl.QSTileImpl.handleRefreshState(QSTileImpl.java:378)
02-22 10:51:13.082  3219  3401 E NFC     :  at com.android.systemui.qs.tileimpl.QSTileImpl$H.handleMessage(QSTileImpl.java:603)
02-22 10:51:13.082  3219  3401 E NFC     :  at android.os.Handler.dispatchMessage(Handler.java:106)
02-22 10:51:13.082  3219  3401 E NFC     :  at android.os.Looper.loop(Looper.java:223)
02-22 10:51:13.082  3219  3401 E NFC     :  at android.os.HandlerThread.run(HandlerThread.java:67)
02-22 10:51:13.084  3219  3401 E NFC     : could not retrieve NFC service during service recovery
02-22 10:51:13.085  3219  3401 E NFC     : Failed to recover NFC Service.
lss4 commented 3 years ago

UPDATE: Don't know if this might be relevant. This is on master. The actual code in GSI build may differ.

It's possible the NFC is having a transport error or is timing out for some reason. This particular case block is the same for NFA_DM_NFCC_TRANSPORT_ERR_EVT and NFA_DM_NFCC_TIMEOUT_EVT, and is the only place where abort() appears in this function.

Supposedly the system should be trying to recover the NFC service afterwards. However, either that never happened or that the recovery attempts failed without emitting any logs, the only logcat relevant to NFC was the DeadObjectException that came from the QS tiles, and NFC no longer works. (EDIT: It's possible this issue was known, and this particular commit appears to be a fix...)

lss4 commented 3 years ago

This issue persists on v304. NFC still crashes and would not recover.

Don't know if there is anything else helpful I could provide to help investigating...

Reznor7 commented 3 years ago

This issue persists on v304. NFC still crashes and would not recover.

Don't know if there is anything else helpful I could provide to help investigating...

I'm guessing this is still an issue?

lss4 commented 3 years ago

This issue persists on v304. NFC still crashes and would not recover. Don't know if there is anything else helpful I could provide to help investigating...

I'm guessing this is still an issue?

As of the April build of PalladiumOS GSI, yes. Which GSI are you currently on?

Reznor7 commented 3 years ago

This issue persists on v304. NFC still crashes and would not recover. Don't know if there is anything else helpful I could provide to help investigating...

I'm guessing this is still an issue?

As of the April build of PalladiumOS GSI, yes. Which GSI are you currently on?

I've been trying Lineage 18.1 with each release. Still no luck after the May update.

lss4 commented 3 years ago

This issue persists on v304. NFC still crashes and would not recover. Don't know if there is anything else helpful I could provide to help investigating...

I'm guessing this is still an issue?

As of the April build of PalladiumOS GSI, yes. Which GSI are you currently on?

I've been trying Lineage 18.1 with each release. Still no luck after the May update.

Does the phenomenon similar?

The current phenomenon is, upon system startup, NFC appears to be present and initialized, but as soon as you try to use it or after a couple of minutes, NFC service dies (due to an abort() call, which can be found in the source code as there is only a single occurrence of it) and never recovers.

Maybe try getting a kernel dmesg when that happens, to see what exactly happened. You can type dmesg after entering a root shell (after rooted using Magisk).

Reznor7 commented 3 years ago

This issue persists on v304. NFC still crashes and would not recover. Don't know if there is anything else helpful I could provide to help investigating...

I'm guessing this is still an issue?

As of the April build of PalladiumOS GSI, yes. Which GSI are you currently on?

I've been trying Lineage 18.1 with each release. Still no luck after the May update.

Does the phenomenon similar?

The current phenomenon is, upon system startup, NFC appears to be present and initialized, but as soon as you try to use it or after a couple of minutes, NFC service dies (due to an abort() call, which can be found in the source code as there is only a single occurrence of it) and never recovers.

Maybe try getting a kernel dmesg when that happens, to see what exactly happened. You can type dmesg after entering a root shell (after rooted using Magisk).

I have switched back to 17.1 as my daily driver, so I unfortunately can not check.

lss4 commented 3 years ago

I took a kernel dmesg the moment when I touched a NFC card which would cause NFC service to die.

[  210.917780] i2c_geni 88c000.i2c: i2c error :-107
[  210.917814] nq-nci 1-0028: nfc_write: failed to write -107
[  210.925683] i2c_geni 88c000.i2c: i2c error :-107
[  210.925698] nq-nci 1-0028: nfc_write: failed to write -107
[  210.931351] i2c_geni 88c000.i2c: i2c error :-107
[  210.931366] nq-nci 1-0028: nfc_write: failed to write -107
[  210.936986] i2c_geni 88c000.i2c: i2c error :-107
[  210.936997] nq-nci 1-0028: nfc_write: failed to write -107
[  210.942649] i2c_geni 88c000.i2c: i2c error :-107
[  210.942666] nq-nci 1-0028: nfc_write: failed to write -107
[  210.948182] i2c_geni 88c000.i2c: i2c error :-107
[  210.948200] nq-nci 1-0028: nfc_write: failed to write -107

Actually similar messages appear before this, but NFC service is still alive at that moment.

[   76.440220] i2c_geni 88c000.i2c: i2c error :-107
[   76.440235] nq-nci 1-0028: nfc_write: failed to write -107

NFC is not recovering at all as nothing related shows up in the logcat, except the QS panel keeps complaining about unable to obtain NFC status due to DeadObjectException, since NFC service recovery never really happened.

Reznor7 commented 3 years ago

Has any progress been made on this bug? It seems to be the only major one affecting our device.

lss4 commented 2 years ago

I don't think I could continue following the issue, as I might have broken the NFC contact when I replaced the phone's swollen battery (nothing happens when I touched a card on it). I didn't really see anything that looked like a NFC contact when I was replacing the battery, so I'm not sure.

However, it seems the issue persists as of the latest OctaviOS build. After a while NFC service dies and disappears from Connected Devices options.

It doesn't seem to be GSI specific, as my new phone, Motorola Edge S Pro (pstar), has working NFC with recent GSI builds (including OctaviOS). It's probably vendor-related.

mikalovtch commented 2 years ago

You can try to add LEGACY_MIFARE_READER=1 in your libnfc-nci.conf (usually it's placed in /vendor/etc/). It has fixed issue with reading Mifare on HTC U12+.

theAkito commented 2 years ago

However, it seems the issue persists as of the latest OctaviOS build.

Same here. Still suffering from this issue...

You can try to add LEGACY_MIFARE_READER=1 in your libnfc-nci.conf (usually it's placed in /vendor/etc/).

This sounds so tempting and amazingly easy. I tried to apply it, but I cannot get my /vendor/etc/ folder or the underlying vendor partition to be remounted with read-write permissions, in any common way.

It seems like the only way is to create an entire Magisk module for the sake of appending a single line to a configuration file, just to try out if it even works at all.

theAkito commented 2 years ago

Out of desperation, I created a Magisk Module, just to append this single line LEGACY_MIFARE_READER=1.

And it actually worked. 🥳 🎉 Still can't believe, this is not a given.

However, now the SIM service does not work at all. I cannot imagine in what way NFC is related to SIM service, but smartphones gonna smartphone, always break from the tiniest modifications, possible....

Update

Another reboot of the device seems to have fixed the disabled SIM service issue.

I cannot believe, this issue is finally fixed.

I will test a while, if it will keep working.