PN548 Throws Tag Lost Exception after few reads

[matt2]

When testing on several android devices we've seen the PN548 tag seems to throw "Tag Lost Exceptions" after only a few authentication requests when communicating with a mifare classic card (see logcat below) when testing almost the same phones iwth the older 547 we see no issue. I'm not sure if there was a patch or updated firmware and with such limited information on these chipset i was hoping to get some more detail if this is a known issue with android?

2019-01-02 16:29:02.694 1686-1922/? I/BrcmNfcNfa: nfa_dm_disc_discovery_cback (): event:0x4000
2019-01-02 16:29:02.694 1686-1922/? I/BrcmNfcNfa: nfa_dm_disc_sm_execute (): state: IDLE (0), event: DISCOVER_RSP(1) disc_flags: 0x21
2019-01-02 16:29:02.694 1686-1922/? I/BrcmNfcNfa: nfa_dm_disc_new_state (): old_state: IDLE (0), new_state: DISCOVERY (1) disc_flags: 0x1
2019-01-02 16:29:02.694 1686-1922/? I/BrcmNfcNfa: nfa_dm_disc_sm_execute (): new state: DISCOVERY (1), disc_flags: 0x1
2019-01-02 16:29:02.694 351-1947/? D/NxpTml: PN54X - Read requested.....
2019-01-02 16:29:02.694 351-1947/? D/NxpTml: PN54X - Invoking I2C Read.....
2019-01-02 16:29:02.714 351-1947/? D/NxpTml: PN54X - I2C Read successful.....len = 4
2019-01-02 16:29:02.714 351-1947/? D/NxpTml: PN54X - Posting read message.....
2019-01-02 16:29:02.714 351-1947/? D/NxpNciR: len = 4 <= 600701A1
2019-01-02 16:29:02.714 351-1950/? D/NxpHal: read successful status = 0x0
2019-01-02 16:29:02.714 1686-1922/? I/BrcmNfcNfa: NFC received ntf gid:0
2019-01-02 16:29:02.714 1686-1922/? I/BrcmNfcNfa: nci_proc_core_ntf opcode:0x7
2019-01-02 16:29:02.714 1686-1922/? I/BrcmNfcNfa: nfa_dm_nfc_response_cback () NFC_GEN_ERROR_REVT(0x500d)
2019-01-02 16:29:02.715 1686-1922/? I/BrcmNfcNfa: nfa_dm_disc_data_cback ()
2019-01-02 16:29:02.715 1686-1922/? I/BrcmNfcNfa: nfa_dm_disc_sm_execute (): state: DISCOVERY (1), event: INTF_ERROR_NTF(10) disc_flags: 0x1
2019-01-02 16:29:02.715 1686-1922/? I/BrcmNfcNfa: nfa_dm_disc_sm_execute (): new state: DISCOVERY (1), disc_flags: 0x1
2019-01-02 16:29:02.715 351-1947/? D/NxpTml: PN54X - Read requested.....
2019-01-02 16:29:02.715 351-1947/? D/NxpTml: PN54X - Invoking I2C Read.....
2019-01-02 16:29:02.736 1686-5530/? D/BrcmNfcJni: nativeNfcTag_doPresenceCheck
2019-01-02 16:29:02.737 1686-5530/? D/BrcmNfcJni: nativeNfcTag_doPresenceCheck: tag already deactivated
2019-01-02 16:29:02.737 1686-5530/? D/NativeNfcTag: Tag lost, restarting polling loop
2019-01-02 16:29:02.737 1686-5530/? D/BrcmNfcJni: nativeNfcTag_doDisconnect: enter
2019-01-02 16:29:02.737 1686-5530/? E/BrcmNfcJni: nativeNfcTag_doDisconnect: tag already deactivated
2019-01-02 16:29:02.737 1686-5530/? D/BrcmNfcJni: nativeNfcTag_doDisconnect: exit
2019-01-02 16:29:02.737 1686-5530/? D/NfcService: applyRouting - enter force = false mScreenState = 8
2019-01-02 16:29:02.738 1686-5530/? D/NfcService: Discovery configuration equal, not updating.
2019-01-02 16:29:02.738 1686-5530/? D/NativeNfcTag: Stopping background presence check
2019-01-02 16:29:02.782 1686-5523/? D/BrcmNfcJni: nativeNfcTag_doPresenceCheck
2019-01-02 16:29:02.782 1686-5523/? D/BrcmNfcJni: nativeNfcTag_doPresenceCheck: tag already deactivated
2019-01-02 16:29:02.783 1686-5523/? D/NativeNfcTag: Tag lost, restarting polling loop
2019-01-02 16:29:02.783 1686-5523/? D/BrcmNfcJni: nativeNfcTag_doDisconnect: enter
2019-01-02 16:29:02.783 1686-5523/? E/BrcmNfcJni: nativeNfcTag_doDisconnect: tag already deactivated
2019-01-02 16:29:02.783 1686-5523/? D/BrcmNfcJni: nativeNfcTag_doDisconnect: exit
2019-01-02 16:29:02.783 1686-5523/? D/NfcService: applyRouting - enter force = false mScreenState = 8
2019-01-02 16:29:02.783 1686-5523/? D/NfcService: Discovery configuration equal, not updating.
2019-01-02 16:29:02.783 1686-5523/? D/NativeNfcTag: Stopping background presence check
2019-01-02 16:29:02.785 1686-5520/? D/BrcmNfcJni: nativeNfcTag_doPresenceCheck
2019-01-02 16:29:02.785 1686-5520/? D/BrcmNfcJni: nativeNfcTag_doPresenceCheck: tag already deactivated
2019-01-02 16:29:02.785 1686-5520/? D/NativeNfcTag: Tag lost, restarting polling loop
2019-01-02 16:29:02.785 1686-5520/? D/BrcmNfcJni: nativeNfcTag_doDisconnect: enter
2019-01-02 16:29:02.785 1686-5520/? E/BrcmNfcJni: nativeNfcTag_doDisconnect: tag already deactivated
2019-01-02 16:29:02.786 1686-5520/? D/BrcmNfcJni: nativeNfcTag_doDisconnect: exit
2019-01-02 16:29:02.786 1686-5520/? D/NfcService: applyRouting - enter force = false mScreenState = 8
2019-01-02 16:29:02.786 1686-5520/? D/NfcService: Discovery configuration equal, not updating.
2019-01-02 16:29:02.787 1686-5520/? D/NativeNfcTag: Stopping background presence check
2019-01-02 16:29:02.963 5534-5534/? E/mxc4005xc: memsic Open pointer device failed! -1

[anton8900]

Why you don't found successfull reads in read log?

Bytes on card

byte [] bytes = new byte[] {66,55,44,4,44,66,66,66,77,10,11,66,13,10,10,10};

but it returns this

01-22 12:06:24.577 5803-5820/com.example.antonskutov.testnfcapp D/ClassicCardOperations: Read block success 5 [-78, 0, 44, 4, 44, 66, 66, 66, 77, 10, 11, 66, 13, 10, 10, 10]

And no any tag lost exception, it returns this invalid data as many times as i request

Exception will be thrown only in case i stop cycle with debug and then continue

I have tested it now with my Sony Xperia XZ1 on Android 9.0 and it works the same

TestNfcApp [E:\work\projects\TestNfcApp] - ...\app\src\main\java\com\example\antonskutov\testnfcapp\... 

For write tag lost exception works but not correctly too

1) for last operations no data can be written without any tag lost exception

so data not really written but exception is thrown only in next operation

With sony it works better, but sometimes this situation occures too

And please install this app from archive that i have sent and try to test it for youself

[IvanRuiz]

Hi,

Please see internal response below:

I’m sorry. Maybe I was not clear enough the first time.

The issue is on RF side. Actually, we do not receive data from the card.

Meaning that: either the card is broken or the matching between the card and the phone is not good enough.

Did he tried with another card?

Please find below the analyze with the log. Hope, this will clarify.

Again, I don’t have the full log. So, I assume that authentication was successful before this sequence

01-22 12:06:24.595 1412-1646/com.android.nfc D/NxpNciX: len =   6 > 000003103005    this is a command sent to the card to read block 5

01-22 12:06:24.595 1412-1646/com.android.nfc D/NxpTml: PN54X - I2C Write successful.....

01-22 12:06:24.595 1412-1646/com.android.nfc D/NxpTml: PN54X - Posting Fresh Write message.....

01-22 12:06:24.595 1412-1646/com.android.nfc D/NxpTml: PN54X - Tml Writer Thread Running................

01-22 12:06:24.595 1412-1648/com.android.nfc D/NxpHal: write successful status = 0x0

01-22 12:06:24.596 1412-1645/com.android.nfc D/NxpTml: PN54X - I2C Read successful.....

01-22 12:06:24.596 1412-1645/com.android.nfc D/NxpNciR: len =   6 > 600603010001                   This is acknowledge from the PN54x

01-22 12:06:24.596 1412-1645/com.android.nfc D/NxpTml: PN54X - Posting read message.....

01-22 12:06:24.596 1412-1648/com.android.nfc D/NxpHal: read successful status = 0x0

01-22 12:06:24.596 1412-1648/com.android.nfc D/NfcAdaptation: NfcAdaptation::HalDeviceContextDataCallback: len=6

01-22 12:06:24.596 1412-1579/com.android.nfc I/BrcmNfcNfa: NFC received ntf gid:0

01-22 12:06:24.596 1412-1645/com.android.nfc D/NxpTml: PN54X - Read requested.....

01-22 12:06:24.596 1412-1579/com.android.nfc I/BrcmNfcNfa: nci_proc_core_ntf opcode:0x6

01-22 12:06:24.596 1412-1645/com.android.nfc D/NxpTml: PN54X - Invoking I2C Read.....

01-22 12:06:24.596 1412-1579/com.android.nfc I/BrcmNfcNfa: nfc_ncif_send_data :0, num_buff:1 qc:0

01-22 12:06:24.606 1412-1645/com.android.nfc D/NxpTml: PN54X - I2C Read successful.....

01-22 12:06:24.606 1412-1645/com.android.nfc D/NxpNciR: len =   5 > 00000210B2                        This is response from the card. There is no Data here

01-22 12:06:24.606 1412-1645/com.android.nfc D/NxpTml: PN54X - Posting read message.....

01-22 12:06:24.606 1412-1648/com.android.nfc D/NxpHal: read successful status = 0x0

01-22 12:06:24.606 1412-1648/com.android.nfc D/NfcAdaptation: NfcAdaptation::HalDeviceContextDataCallback: len=5

01-22 12:06:24.607 1412-1579/com.android.nfc I/BrcmNfcNfa: NFC received data

01-22 12:06:24.607 1412-1579/com.android.nfc I/BrcmNfcNfa: nfc_ncif_proc_data 0x000002

01-22 12:06:24.607 1412-1579/com.android.nfc I/BrcmNfcNfa: nfc_ncif_proc_data len:2

01-22 12:06:24.607 1412-1645/com.android.nfc D/NxpTml: PN54X - Read requested.....

01-22 12:06:24.607 1412-1645/com.android.nfc D/NxpTml: PN54X - Invoking I2C Read.....

01-22 12:06:24.607 1412-1579/com.android.nfc I/BrcmNfcNfa: nfa_rw_raw_mode_data_cback(): event = 0x6003

01-22 12:06:24.607 1412-1579/com.android.nfc D/BrcmNfcJni: nfaConnectionCallback: event= 9

01-22 12:06:24.607 1412-1579/com.android.nfc D/BrcmNfcJni: nfaConnectionCallback: NFA_DATA_EVT: status = 0x0, len = 2

01-22 12:06:24.607 1412-1579/com.android.nfc D/BrcmNfcJni: nativeNfcTag_doTransceiveStatus: data len=2

01-22 12:06:24.607 1412-1412/com.android.nfc D/BrcmNfcJni: nativeNfcTag_doTransceive: response 2 bytes

01-22 12:06:24.607 1412-1412/com.android.nfc D/BrcmNfcJni: nativeNfcTag_doTransceive: exit

01-22 12:06:24.607 5803-5820/com.example.antonskutov.testnfcapp D/ClassicCardOperations: Read block success 5 [-78, 0, 44, 4, 44, 66, 66, 66, 77, 10, 11, 66, 13, 10, 10, 10]                            This is NOT data from neither our PN54x nor from the card. This must be remaining data in their internal buffer

01-22 12:06:24.607 5803-5820/com.example.antonskutov.testnfcapp D/My Activity: Invalid data returned [-78, 0, 44, 4, 44, 66, 66, 66, 77, 10, 11, 66, 13, 10, 10, 10]

01-22 12:06:24.607 5803-5820/com.example.antonskutov.testnfcapp D/ClassicCardOperations: Read block 5

Regards,

Ivan.

[simon3]

Hi IvanRuiz‌, do you have any potential solutions to this issue?

[anton8900]

I tried with androids running 5.1, 6.0, 7.0 and 9.0 versions. I have hundreds of cards and it work the same for all. I think that is problem with library or protocol. You asked that it is not a data, that is internal buffer, but how i should understand that this 16 bytes is not a data from card in read operation?

And you don't answer why it not always throws exception when it wasn't really written data to card in write operation?

Can you build project and test all for yourself?

[anton8900]

Ivan, yes that is the same project.

Please analyze log files, code and comments in code here nfc tests.zip - Google Drive 

[IvanRuiz]

Hi,

Please help us to clarify the requested information from internal team below.

I guess both log comes from PN548, correct?

The read log does not help that much as there is even not one successful read in it.

Indeed, the write log is showing “Tag Lost Exception”. This is normal behavior when no response is received from the tag.

There is a timeout for each command. If the response is not received within the time range, the tag is considered as lost.

Response not received means: either the tag is not responding or the response is not received/understood by the phone.

It seems your issue is on RF performance side.

Would you please provide more accurate log for confirmation?

The need to have the below sequence

• Starting from the boot
• Run the application for read or write test
• Put the card in front of the phone until the issue occurs

Have you tried with another phone? S9?

By the way, do tyou use plastic card or MIFARE Virtual Card in another form factor?

Thank you.

Best regards,

Ivan.

[anton8900]

1) Card wasn't empty

2) 1K

Code and logs you can found here:

nfc tests.zip - Google Drive 

[IvanRuiz]

Hi,

Could you please confirm if this is the same project as the one in the following thread?

https://community.nxp.com/message/1103907?commentID=1103907&et=watches.email.thread#comment-1103907 

This is the same project for two different threads. Please clarify whether you only need support for this one or both, and send the corresponding projects for each of them.

Thank you.

Regards,

Ivan.

[IvanRuiz]

Hello,

Please provide the full ADB log in text file.

Q1. Are you working with an empty card?

Q2. Is it 1K or 4K?

Regards,

Ivan.