i2c multi-core processor

[anpieber]

I've the following problem with libnfc. I've a little go application which basically does the following

if _, err := device.InitiatorPollTarget(modulations, 0xFF, 1); err != nil { return errors.Wrap(err, "error while polling") }

where the go wrapper does basically nothing fancy wrapping libnfc:

https://github.com/PonteMed/nfc/tree/master/dev/nfc

The reader is connected via i2c.

The funny behavior now is: it basically works perfectly EXCEPT if i do "stress -c 1" - which does basically nothing more than running the cpu0 on 100% (while all other cpus are still idling). I'm on an Apalis T30 board with 4 cores. All other applications are working perfectly fine - except for the libnfc application. It simply does nothing. ASAP the CPU usage goes down it works perfectly again. Google yields nothing about the problem. Before I invest hours and hours and hours removing one component after another: Is this in any way a known problem and does anybody know how to workaround it?

Thank you very much!

[neomilium]

If you're using debug flags on libnfc, do you have some trace ?

[anpieber]

OK, took me some time to get this working as expected... I suspect that there is some behavior in the polling which creates the problem. First of all this is the content of my /etc/nfc/libnfc.conf

allow_autoscan=true
allow_intrusive_scan=false
log_level=3
device.name="pontemed reader"
device.connstring="pn532_i2c:/dev/i2c-0"

I'm using the latest master of libnfc/libfreefare (pulled and compiled today, 2018-11-16).

The device the software is running on is an Apalis T30. The card reader is a pn532 module connected via i2c directly on the board.

If I do a "stress -c 1" in one console I can do a ./nfc-poll which will return:

./nfc-poll uses libnfc 1.7.1
debug   libnfc.general  log_level is set to 3
debug   libnfc.general  allow_autoscan is set to true
debug   libnfc.general  allow_intrusive_scan is set to false
debug   libnfc.general  1 device(s) defined by user
debug   libnfc.general    #0 name: "pontemed reader", connstring: "pn532_i2c:/dev/i2c-0"
debug   libnfc.chip.pn53x       Diagnose
debug   libnfc.chip.pn53x       Timeout value: 500
debug   libnfc.chip.pn53x       SAMConfiguration
debug   libnfc.chip.pn53x       Timeout value: 1000
debug   libnfc.bus.i2c  TX: 00 00 ff 03 fd d4 14 01 17 00 
debug   libnfc.bus.i2c  wrote 10 bytes successfully.
debug   libnfc.chip.pn53x       PN53x ACKed
debug   libnfc.bus.i2c  TX: 00 00 ff 09 f7 d4 00 00 6c 69 62 6e 66 63 be 00 
debug   libnfc.bus.i2c  wrote 16 bytes successfully.
debug   libnfc.chip.pn53x       PN53x ACKed
debug   libnfc.chip.pn53x       GetFirmwareVersion
debug   libnfc.bus.i2c  TX: 00 00 ff 02 fe d4 02 2a 00 
debug   libnfc.bus.i2c  wrote 9 bytes successfully.
debug   libnfc.chip.pn53x       PN53x ACKed
debug   libnfc.chip.pn53x       SetParameters
debug   libnfc.bus.i2c  TX: 00 00 ff 03 fd d4 12 14 06 00 
debug   libnfc.bus.i2c  wrote 10 bytes successfully.
debug   libnfc.chip.pn53x       PN53x ACKed
debug   libnfc.general  "pontemed reader" (pn532_i2c:/dev/i2c-0) has been claimed.
debug   libnfc.chip.pn53x       ReadRegister
debug   libnfc.bus.i2c  TX: 00 00 ff 0c f4 d4 06 63 02 63 03 63 0d 63 38 63 3d b0 00 
debug   libnfc.bus.i2c  wrote 19 bytes successfully.
debug   libnfc.chip.pn53x       PN53x ACKed
debug   libnfc.chip.pn53x       PN53X_REG_CIU_TxMode (Defines the transmission data rate and framing during transmission)
debug   libnfc.chip.pn53x       PN53X_REG_CIU_RxMode (Defines the transmission data rate and framing during receiving)
debug   libnfc.chip.pn53x       WriteRegister
debug   libnfc.bus.i2c  TX: 00 00 ff 08 f8 d4 08 63 02 80 63 03 80 59 00 
debug   libnfc.bus.i2c  wrote 15 bytes successfully.
debug   libnfc.chip.pn53x       PN53x ACKed
debug   libnfc.chip.pn53x       RFConfiguration
debug   libnfc.bus.i2c  TX: 00 00 ff 04 fc d4 32 01 00 f9 00 
debug   libnfc.bus.i2c  wrote 11 bytes successfully.
debug   libnfc.chip.pn53x       PN53x ACKed
debug   libnfc.chip.pn53x       RFConfiguration
debug   libnfc.bus.i2c  TX: 00 00 ff 04 fc d4 32 01 01 f8 00 
debug   libnfc.bus.i2c  wrote 11 bytes successfully.
debug   libnfc.chip.pn53x       PN53x ACKed
debug   libnfc.chip.pn53x       RFConfiguration
debug   libnfc.bus.i2c  TX: 00 00 ff 06 fa d4 32 05 ff ff ff f8 00 
debug   libnfc.bus.i2c  wrote 13 bytes successfully.
debug   libnfc.chip.pn53x       PN53x ACKed
NFC reader: pontemed reader opened
NFC device will poll during 30000 ms (20 pollings of 300 ms for 5 modulations)
debug   libnfc.chip.pn53x       ReadRegister
debug   libnfc.bus.i2c  TX: 00 00 ff 0e f2 d4 06 63 02 63 03 63 05 63 38 63 3c 63 3d 19 00 
debug   libnfc.bus.i2c  wrote 21 bytes successfully.
debug   libnfc.chip.pn53x       PN53x ACKed
debug   libnfc.chip.pn53x       PN53X_REG_CIU_TxAuto (Controls the settings of the antenna driver)
debug   libnfc.chip.pn53x       PN53X_REG_CIU_Control (Contains miscellaneous control bits)
debug   libnfc.chip.pn53x       WriteRegister
debug   libnfc.bus.i2c  TX: 00 00 ff 08 f8 d4 08 63 05 40 63 3c 10 cd 00 
debug   libnfc.bus.i2c  wrote 15 bytes successfully.
debug   libnfc.chip.pn53x       PN53x ACKed
debug   libnfc.chip.pn53x       InAutoPoll
debug   libnfc.chip.pn53x       No timeout
debug   libnfc.bus.i2c  TX: 00 00 ff 0a f6 d4 60 14 02 20 10 03 11 12 04 5c 00 
debug   libnfc.bus.i2c  wrote 17 bytes successfully.
debug   libnfc.chip.pn53x       PN53x ACKed

Now it doesent matter if I put a card on the reader or not - after 30 seconds I get:

No target found.
debug   libnfc.chip.pn53x       InRelease
debug   libnfc.bus.i2c  TX: 00 00 ff 03 fd d4 52 00 da 00 
debug   libnfc.bus.i2c  wrote 10 bytes successfully.
debug   libnfc.chip.pn53x       PN53x ACKed
debug   libnfc.chip.pn53x       RFConfiguration
debug   libnfc.bus.i2c  TX: 00 00 ff 04 fc d4 32 01 00 f9 00 
debug   libnfc.bus.i2c  wrote 11 bytes successfully.
debug   libnfc.chip.pn53x       PN53x ACKed
debug   libnfc.chip.pn53x       PowerDown
debug   libnfc.bus.i2c  TX: 00 00 ff 03 fd d4 16 f0 26 00 
debug   libnfc.bus.i2c  wrote 10 bytes successfully.
debug   libnfc.chip.pn53x       PN53x ACKed

If I don't use stress I almost immediately get

ISO/IEC 14443A (106 kbps) target:
    ATQA (SENS_RES): 03  44  
       UID (NFCID1): 04  75  4b  12  14  4e  80  
      SAK (SEL_RES): 20  
                ATS: 75  77  81  02  80  
Waiting for card removing...
debug       libnfc.chip.pn53x       target_is_present(): Ping -4A
debug   libnfc.chip.pn53x       InCommunicateThru
debug   libnfc.chip.pn53x       Timeout value: 300
debug   libnfc.bus.i2c  TX: 00 00 ff 03 fd d4 42 b2 38 00 
debug   libnfc.bus.i2c  wrote 10 bytes successfully.
debug   libnfc.chip.pn53x       PN53x ACKed
debug   libnfc.chip.pn53x       target_is_present(): Ping -4A
debug   libnfc.chip.pn53x       InCommunicateThru
debug   libnfc.chip.pn53x       Timeout value: 300
debug   libnfc.bus.i2c  TX: 00 00 ff 03 fd d4 42 b2 38 00 
debug   libnfc.bus.i2c  wrote 10 bytes successfully.

htop shows me, using stress, that only one processor out of 4 is occupied (see screenshot)

If I start other applications on the board (e.g. a QT App, or other NFC tools for example) everything works fine. It looks just like the polling/waiting itself has a problem with the loaded CPU. BTW, I get exactly the same behavior if I run stress with -i 1 (-i, --io N spawn N workers spinning on sync()). I've multiple of those devices and this is a behavior spanning over all of them.

I don't have any card reader ready I can connect to my PC validating if this is a general behavior of libnfc or just in this device/hardware/architecture combination. I should receive a different PN532 module I can connect via USB to my PC within the next days.

Any ideas would be very, very welcomed though! It simply does not feel right how the device behaves.

Thank you very much!

[anpieber]

I've added additional debug statements showing that libnfc is hanging in pn53x_transceive in this line if ((res = CHIP_DATA(pnd)->io->receive(pnd, pbtRx, szRx, timeout)) < 0) BUT, receiving itself is not the problem. Directly before running this line the driver communicates even though the cpu is at 100% (using stress -c1) without any troubles in the pn53x_writeback_register call receiving and sending data. This does not make any sense for me :man_shrugging:

[anpieber]

OK - another hint. After registering the hardware interrupt the software is hanging in the call to pn532_i2c_wait_rdyframe of the pn532_i2c_receive method. The problem is that the things returned by pn532_i2c_read does never fullfill the if (rdy & 1) { condition. BUT ONLY if I use stress -c 1 or stress -i 1. Without those it runs without any problem.

I've a basic idea at this level of communication but I'm by far not experienced enough at this level to guess at the reason for this. Any ideas why this happens and how I can work against it would be very welcomed. Am I really the only one plagued by this? Can it be my pn532 chip?