NXP547 Android Read Block Returning Success When Tag Is Removed

[matt2]

We've come across a strange nuance with the android drivers for the NXP547 series. We were seeing on occasion the following bytes being returned from the NXP drivers when the tag had been removed.

To test this we wrote a small application to continuous read the same block over and over again and then removed the tag from the device while it was running. Checking logcat the following can be seen.

Expected Read
[66, 55, 44, 4, 44, 66, 66, 66, 77, 10, 11, 66, 13, 14, 15, 16]

Bad Bytes
[-78, 0, 44, 4, 44, 66, 66, 66, 77, 10, 11, 66, 13, 14, 15, 16]

The driver however returns a success for the blocks with the bad data - on newer android phones Galaxy s8 we don't see this same result (it returns an exception rather than read success).

Any help would be appreciated.

12-31 02:04:08.415 2220-2240/com.example.antonskutov.testnfcapp D/ClassicCardOperations: Read block success 5 [66, 55, 44, 4, 44, 66, 66, 66, 77, 10, 11, 66, 13, 14, 15, 16]
12-31 02:04:08.415 2220-2240/com.example.antonskutov.testnfcapp D/ClassicCardOperations: Read block 5
12-31 02:04:08.415 2220-2240/com.example.antonskutov.testnfcapp W/System.err: java.lang.NullPointerException: null reference
12-31 02:04:08.416 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.google.android.gms.common.internal.Preconditions.checkNotNull(Unknown Source)
12-31 02:04:08.416 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.google.android.gms.internal.measurement.zzat.zzc(Unknown Source)
12-31 02:04:08.416 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.google.android.gms.analytics.GoogleAnalytics.getInstance(Unknown Source)
12-31 02:04:08.416 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.nxp.nfclib.analytics.AnalyticsTracker.ˏ(:51)
12-31 02:04:08.416 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.nxp.nfclib.analytics.AnalyticsTracker.sendEvent(:3119)
12-31 02:04:08.416 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.nxp.nfclib.classic.MFClassic.readBlock(:360)
12-31 02:04:08.416 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.example.antonskutov.testnfcapp.ClassicCardOperations.readBlock(ClassicCardOperations.java:81)
12-31 02:04:08.416 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.example.antonskutov.testnfcapp.MyActivity.onNewIntent(MyActivity.java:43)
12-31 02:04:08.416 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.example.antonskutov.testnfcapp.MyActivity.lambda$onResume$0(MyActivity.java:26)
12-31 02:04:08.416 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.example.antonskutov.testnfcapp.-$$Lambda$MyActivity$yBB6ulhqtt4N518nw2BcvPs4GLI.onTagDiscovered(lambda)
12-31 02:04:08.416 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at android.nfc.NfcActivityManager.onTagDiscovered(NfcActivityManager.java:403)
12-31 02:04:08.416 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at android.nfc.IAppCallback$Stub.onTransact(IAppCallback.java:79)
12-31 02:04:08.416 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at android.os.Binder.execTransact(Binder.java:404)
12-31 02:04:08.416 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at dalvik.system.NativeStart.run(Native Method)
12-31 02:04:08.417 893-893/? D/BrcmNfcJni: nativeNfcTag_doTransceive: enter; raw=0; timeout = 618
12-31 02:04:08.417 893-893/? I/BrcmNfcNfa: NFA_SendRawFrame () data_len:3
12-31 02:04:08.417 893-1816/? I/BrcmNfcNfa: NFA got event 0x010C
12-31 02:04:08.417 893-1816/? I/BrcmNfcNfa: nfa_dm_evt_hdlr event: NFA_DM_API_RAW_FRAME_EVT (0x0c)
12-31 02:04:08.417 893-1816/? I/BrcmNfcNfa: nfa_dm_act_send_raw_frame ()
12-31 02:04:08.417 893-1816/? I/BrcmNfcNfa: nfc_ncif_send_data :0, num_buff:1 qc:0
12-31 02:04:08.417 893-1816/? D/NfcAdaptation: NfcAdaptation::HalWrite
12-31 02:04:08.417 893-1816/? D/NxpExtns: const CNfcParam* CNfcConfig::find(const char*) const found MIFARE_READER_ENABLE=(0x1)
12-31 02:04:08.417 893-1819/? D/NxpTml: PN54X - Write requested.....
12-31 02:04:08.417 893-1819/? D/NxpTml: PN54X - Invoking I2C Write.....
12-31 02:04:08.417 893-1819/? D/NxpNciX: len = 6 > 000003103005
12-31 02:04:08.417 893-1819/? D/NxpTml: PN54X - I2C Write successful.....
12-31 02:04:08.417 893-1819/? D/NxpTml: PN54X - Posting Fresh Write message.....
12-31 02:04:08.417 893-1819/? D/NxpTml: PN54X - Tml Writer Thread Running................
12-31 02:04:08.417 893-1821/? D/NxpHal: write successful status = 0x0
12-31 02:04:08.418 893-1818/? D/NxpTml: PN54X - I2C Read successful.....
12-31 02:04:08.418 893-1818/? D/NxpNciR: len = 6 > 600603010001
12-31 02:04:08.418 893-1818/? D/NxpTml: PN54X - Posting read message.....
12-31 02:04:08.418 893-1821/? D/NxpHal: read successful status = 0x0
12-31 02:04:08.418 893-1821/? D/NfcAdaptation: NfcAdaptation::HalDeviceContextDataCallback: len=6
12-31 02:04:08.418 893-1818/? D/NxpTml: PN54X - Read requested.....
12-31 02:04:08.418 893-1818/? D/NxpTml: PN54X - Invoking I2C Read.....
12-31 02:04:08.418 893-1816/? I/BrcmNfcNfa: NFC received ntf gid:0
12-31 02:04:08.418 893-1816/? I/BrcmNfcNfa: nci_proc_core_ntf opcode:0x6
12-31 02:04:08.418 893-1816/? I/BrcmNfcNfa: nfc_ncif_send_data :0, num_buff:1 qc:0
12-31 02:04:08.420 893-1818/? D/NxpTml: PN54X - I2C Read successful.....
12-31 02:04:08.420 893-1818/? D/NxpNciR: len = 21 > 0000121042372C042C4242424D0A0B420D0E0F1000
12-31 02:04:08.420 893-1818/? D/NxpTml: PN54X - Posting read message.....
12-31 02:04:08.421 893-1821/? D/NxpHal: read successful status = 0x0
12-31 02:04:08.421 893-1821/? D/NfcAdaptation: NfcAdaptation::HalDeviceContextDataCallback: len=21
12-31 02:04:08.421 893-1818/? D/NxpTml: PN54X - Read requested.....
12-31 02:04:08.421 893-1818/? D/NxpTml: PN54X - Invoking I2C Read.....
12-31 02:04:08.421 893-1816/? I/BrcmNfcNfa: NFC received data
12-31 02:04:08.421 893-1816/? I/BrcmNfcNfa: nfc_ncif_proc_data 0x000012
12-31 02:04:08.421 893-1816/? I/BrcmNfcNfa: nfc_ncif_proc_data len:18
12-31 02:04:08.421 893-1816/? I/BrcmNfcNfa: nfa_rw_raw_mode_data_cback(): event = 0x6003
12-31 02:04:08.421 893-1816/? D/BrcmNfcJni: nfaConnectionCallback: event= 9
12-31 02:04:08.421 893-1816/? E/BrcmNfcJni: ________________________nfaConnectionCallback NdefMap!=NULL
12-31 02:04:08.421 893-1816/? D/BrcmNfcJni: nfaConnectionCallback: NFA_DATA_EVT: len = 18
12-31 02:04:08.421 893-1816/? D/BrcmNfcJni: nativeNfcTag_doTransceiveStatus: data len=18, waiting for transceive: 1
12-31 02:04:08.421 893-893/? D/BrcmNfcJni: nativeNfcTag_doTransceive: response 18 bytes
12-31 02:04:08.421 893-893/? D/BrcmNfcJni: nativeNfcTag_doTransceive: exit
12-31 02:04:08.421 893-893/? W/dalvikvm: JNI: unpinPrimitiveArray(0x41c47ca8) failed to find entry (valid=1)
12-31 02:04:08.421 2220-2240/com.example.antonskutov.testnfcapp D/ClassicCardOperations: Read block success 5 [66, 55, 44, 4, 44, 66, 66, 66, 77, 10, 11, 66, 13, 14, 15, 16]
12-31 02:04:08.421 2220-2240/com.example.antonskutov.testnfcapp D/ClassicCardOperations: Read block 5
12-31 02:04:08.421 2220-2240/com.example.antonskutov.testnfcapp W/System.err: java.lang.NullPointerException: null reference
12-31 02:04:08.421 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.google.android.gms.common.internal.Preconditions.checkNotNull(Unknown Source)
12-31 02:04:08.421 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.google.android.gms.internal.measurement.zzat.zzc(Unknown Source)
12-31 02:04:08.421 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.google.android.gms.analytics.GoogleAnalytics.getInstance(Unknown Source)
12-31 02:04:08.422 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.nxp.nfclib.analytics.AnalyticsTracker.ˏ(:51)
12-31 02:04:08.422 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.nxp.nfclib.analytics.AnalyticsTracker.sendEvent(:3119)
12-31 02:04:08.422 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.nxp.nfclib.classic.MFClassic.readBlock(:360)
12-31 02:04:08.422 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.example.antonskutov.testnfcapp.ClassicCardOperations.readBlock(ClassicCardOperations.java:81)
12-31 02:04:08.422 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.example.antonskutov.testnfcapp.MyActivity.onNewIntent(MyActivity.java:43)
12-31 02:04:08.422 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.example.antonskutov.testnfcapp.MyActivity.lambda$onResume$0(MyActivity.java:26)
12-31 02:04:08.422 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at com.example.antonskutov.testnfcapp.-$$Lambda$MyActivity$yBB6ulhqtt4N518nw2BcvPs4GLI.onTagDiscovered(lambda)
12-31 02:04:08.422 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at android.nfc.NfcActivityManager.onTagDiscovered(NfcActivityManager.java:403)
12-31 02:04:08.422 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at android.nfc.IAppCallback$Stub.onTransact(IAppCallback.java:79)
12-31 02:04:08.422 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at android.os.Binder.execTransact(Binder.java:404)
12-31 02:04:08.422 2220-2240/com.example.antonskutov.testnfcapp W/System.err: at dalvik.system.NativeStart.run(Native Method)
12-31 02:04:08.422 893-893/? D/BrcmNfcJni: nativeNfcTag_doTransceive: enter; raw=0; timeout = 618
12-31 02:04:08.423 893-893/? I/BrcmNfcNfa: NFA_SendRawFrame () data_len:3
12-31 02:04:08.423 893-1816/? I/BrcmNfcNfa: NFA got event 0x010C
12-31 02:04:08.423 893-1816/? I/BrcmNfcNfa: nfa_dm_evt_hdlr event: NFA_DM_API_RAW_FRAME_EVT (0x0c)
12-31 02:04:08.423 893-1816/? I/BrcmNfcNfa: nfa_dm_act_send_raw_frame ()
12-31 02:04:08.423 893-1816/? I/BrcmNfcNfa: nfc_ncif_send_data :0, num_buff:1 qc:0
12-31 02:04:08.423 893-1816/? D/NfcAdaptation: NfcAdaptation::HalWrite
12-31 02:04:08.423 893-1816/? D/NxpExtns: const CNfcParam* CNfcConfig::find(const char*) const found MIFARE_READER_ENABLE=(0x1)
12-31 02:04:08.423 893-1819/? D/NxpTml: PN54X - Write requested.....
12-31 02:04:08.423 893-1819/? D/NxpTml: PN54X - Invoking I2C Write.....
12-31 02:04:08.423 893-1819/? D/NxpNciX: len = 6 > 000003103005
12-31 02:04:08.423 893-1819/? D/NxpTml: PN54X - I2C Write successful.....
12-31 02:04:08.423 893-1819/? D/NxpTml: PN54X - Posting Fresh Write message.....
12-31 02:04:08.423 893-1819/? D/NxpTml: PN54X - Tml Writer Thread Running................
12-31 02:04:08.423 893-1821/? D/NxpHal: write successful status = 0x0
12-31 02:04:08.424 893-1818/? D/NxpTml: PN54X - I2C Read successful.....
12-31 02:04:08.424 893-1818/? D/NxpNciR: len = 6 > 600603010001
12-31 02:04:08.424 893-1818/? D/NxpTml: PN54X - Posting read message.....
12-31 02:04:08.424 893-1821/? D/NxpHal: read successful status = 0x0
12-31 02:04:08.424 893-1821/? D/NfcAdaptation: NfcAdaptation::HalDeviceContextDataCallback: len=6
12-31 02:04:08.424 893-1818/? D/NxpTml: PN54X - Read requested.....
12-31 02:04:08.424 893-1818/? D/NxpTml: PN54X - Invoking I2C Read.....
12-31 02:04:08.424 893-1816/? I/BrcmNfcNfa: NFC received ntf gid:0
12-31 02:04:08.424 893-1816/? I/BrcmNfcNfa: nci_proc_core_ntf opcode:0x6
12-31 02:04:08.424 893-1816/? I/BrcmNfcNfa: nfc_ncif_send_data :0, num_buff:1 qc:0
12-31 02:04:08.434 893-1818/? D/NxpTml: PN54X - I2C Read successful.....
12-31 02:04:08.434 893-1818/? D/NxpNciR: len = 5 > 00000210B2
12-31 02:04:08.434 893-1818/? D/NxpTml: PN54X - Posting read message.....
12-31 02:04:08.434 893-1821/? D/NxpHal: read successful status = 0x0
12-31 02:04:08.434 893-1821/? D/NfcAdaptation: NfcAdaptation::HalDeviceContextDataCallback: len=5
12-31 02:04:08.434 893-1818/? D/NxpTml: PN54X - Read requested.....
12-31 02:04:08.434 893-1818/? D/NxpTml: PN54X - Invoking I2C Read.....
12-31 02:04:08.434 893-1816/? I/BrcmNfcNfa: NFC received data
12-31 02:04:08.434 893-1816/? I/BrcmNfcNfa: nfc_ncif_proc_data 0x000002
12-31 02:04:08.434 893-1816/? I/BrcmNfcNfa: nfc_ncif_proc_data len:2
12-31 02:04:08.434 893-1816/? I/BrcmNfcNfa: nfa_rw_raw_mode_data_cback(): event = 0x6003
12-31 02:04:08.435 893-1816/? D/BrcmNfcJni: nfaConnectionCallback: event= 9
12-31 02:04:08.435 893-1816/? E/BrcmNfcJni: ________________________nfaConnectionCallback NdefMap!=NULL
12-31 02:04:08.435 893-1816/? D/BrcmNfcJni: nfaConnectionCallback: NFA_DATA_EVT: len = 2
12-31 02:04:08.435 893-1816/? D/BrcmNfcJni: nativeNfcTag_doTransceiveStatus: data len=2, waiting for transceive: 1
12-31 02:04:08.435 893-893/? D/BrcmNfcJni: nativeNfcTag_doTransceive: response 2 bytes
12-31 02:04:08.435 893-893/? D/BrcmNfcJni: nativeNfcTag_doTransceive: exit
12-31 02:04:08.435 893-893/? W/dalvikvm: JNI: unpinPrimitiveArray(0x41c47d18) failed to find entry (valid=1)
12-31 02:04:08.435 2220-2240/com.example.antonskutov.testnfcapp D/ClassicCardOperations: Read block success 5 [-78, 0, 44, 4, 44, 66, 66, 66, 77, 10, 11, 66, 13, 14, 15, 16]
12-31 02:04:08.435 2220-2240/com.example.antonskutov.testnfcapp D/ClassicCardOperations: Read block 5

[anton8900]

Code and logs here

nfc tests.zip - Google Drive 

[IvanRuiz]

Hello,

Please provide the full ADB log in text file and the Tag you are working with, if possible Part number.

Regards,

Ivan.