High latency as NPP client between Arygon ADRB and Samsung Nexus S

Hi,

I have slightly adapted nfcpy so that it can work with a desktop reader from
Arygon (ADRB model). I am mainly interested into pushing an NDEF message from
the reader to a Samsung Nexus S. My development environment is Windows, using
python 2.6.6 and pyserial 2.5. I am using the virtual COM port from the
manufacturer of the USB to UART MCU used by the ADRB (Silabs). The
modifications mostly consisted of using pyserial for serial communication with
the reader, as well as prepending the 0x32 byte to each command for selection
of the TAMA low level language by the firmware of the reader. I also replaced
the ACK message when aborting a command, as is done in libnfc.

I am using the npp-test-client configured as a target, with Android quirks mode
enabled. The timeout for listen is set to a high value for testing purposes.
The first two commands sent are used to set the baud rate between the host and
the MCU and between the MCU and the pn53x (it is using the Arygon HL ASCII
language). I have put a log of a successful push from the ADRB to the SNS.
Overall, I can reproduce this success quite consistently with a few failures
most probably due to timing issues.

My concern is the high value of the time needed to complete a few of the
wait_command(), around 800ms. When removing the overhead of nfcpy, it still
need at least 500ms before a character is available for reading on the serial
port, which has a direct impact on the user experience (the push feels
"laggy"). I did the same run under Linux where it gives me the same result.

I would like to know if someone can reproduce such numbers? Is it normal
behaviour? I feel like this value is quite high, and wonder whether it is
coming from the Android NFC stack or from my side (namely software/NFC related
or specific to the ADRB)?

Thanks,

Jérôme

--------------------------------------------------------------------------------------------------------------------

2011-08-19 17:34:36,806 INFO [root] enable debug output for module 'nfc.dev.pn53x'
2011-08-19 17:34:36,806 INFO [root] enable debug output for module 'nfc.llcp.llc'
2011-08-19 17:34:36,806 INFO [root] enable debug output for module 'nfc.llcp.tco'
2011-08-19 17:34:36,806 INFO [root] enable debug output for module 'nfc.llcp.pdu'
2011-08-19 17:34:36,806 INFO [root] enable debug output for module 'nfc.clf'
2011-08-19 17:34:36,806 INFO [root] enable debug output for module 'nfc.dep'
2011-08-19 17:34:36,806 INFO [root] enable debug output for module 'nfc.tt2'
2011-08-19 17:34:36,806 INFO [root] enable debug output for module 'nfc.tt3'
2011-08-19 17:34:36,806 INFO [root] enable debug output for module 'nfc.npp.client'
2011-08-19 17:34:36,854 INFO [nfc.dev.pn53x] searching for a usb tty reader
2011-08-19 17:34:36,901 DEBUG [nfc.dev.pn53x] >>> 3061683036
2011-08-19 17:34:36,931 DEBUG [nfc.dev.pn53x] tty timeout set to None sec
2011-08-19 17:34:36,931 DEBUG [nfc.dev.pn53x] <<< [FF000000

]
2011-08-19 17:34:36,931 DEBUG [nfc.dev.pn53x] >>> 3061743036
2011-08-19 17:34:36,963 DEBUG [nfc.dev.pn53x] tty timeout set to None sec
2011-08-19 17:34:37,102 DEBUG [nfc.dev.pn53x] <<< [FF000000

]
2011-08-19 17:34:37,102 DEBUG [nfc.dev.pn53x] GetFirmwareVersion
2011-08-19 17:34:37,118 DEBUG [nfc.dev.pn53x] >>> 320000ff02fed4022a00
2011-08-19 17:34:37,134 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:37,134 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:37,165 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:37,165 DEBUG [nfc.dev.pn53x] <<< 0000ff06fad50332010607e800
2011-08-19 17:34:37,165 INFO [nfc.dev.pn53x] chipset is a PN532 version 1.6
2011-08-19 17:34:37,165 DEBUG [nfc.dev.pn53x] ATR_RES timeout: 102.4 ms
2011-08-19 17:34:37,165 DEBUG [nfc.dev.pn53x] non-DEP timeout: 204.8 ms
2011-08-19 17:34:37,180 DEBUG [nfc.dev.pn53x] RFConfiguration
2011-08-19 17:34:37,180 DEBUG [nfc.dev.pn53x] >>> 320000ff06fad432020b0b0cd600
2011-08-19 17:34:37,197 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:37,197 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:37,227 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:37,227 DEBUG [nfc.dev.pn53x] <<< 0000ff02fed533f800
2011-08-19 17:34:37,227 DEBUG [nfc.dev.pn53x] RFConfiguration
2011-08-19 17:34:37,227 DEBUG [nfc.dev.pn53x] >>> 320000ff06fad43205020100f200
2011-08-19 17:34:37,259 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:37,259 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:37,290 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:37,290 DEBUG [nfc.dev.pn53x] <<< 0000ff02fed533f800
2011-08-19 17:34:37,290 DEBUG [nfc.clf] using driver <nfc.dev.pn53x.device object at 0x01A23330>
2011-08-19 17:34:37,290 DEBUG [nfc.dev.pn53x] listen: gb=46666d0101110202038003020003040164070103 timeout=100000 ms RWT=4.94903126844
2011-08-19 17:34:37,290 DEBUG [nfc.dev.pn53x] TgInitAsTarget
2011-08-19 17:34:37,290 DEBUG [nfc.dev.pn53x] >>> 320000ff3bc5d48c0201010000004001fe0fbbbaa6c9890000000000000000ffff01fe0fbbbaa6c98900001446666d0101110202038003020003040164070103002500
2011-08-19 17:34:37,322 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:37,322 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:37,352 DEBUG [nfc.dev.pn53x] tty timeout set to 100.0 sec
2011-08-19 17:34:37,664 DEBUG [nfc.dev.pn53x] <<< 0000ff21dfd58d261ed40001fe0fbbbaa6c98900000000003246666d010110030200010401960d00
2011-08-19 17:34:37,664 INFO [nfc.dev.pn53x] activated as dep target in 424 kbps passive mode
2011-08-19 17:34:37,664 DEBUG [nfc.clf] got dep master, general bytes 46666d01011003020001040196
2011-08-19 17:34:37,680 DEBUG [nfc.llcp.llc] llc cfg {'recv-lto': 1500, 'send-miu': 128, 'send-agf': False, 'send-lto': 1000, 'send-lsc': 3, 'recv-miu': 1024, 'recv-wks': 3, 'send-wks': 1, 'rcvd-ver': (1, 0)}
2011-08-19 17:34:37,680 INFO [nfc.llcp.llc] LLCP Link established, I'm the the DEP Target
Local LLCP Settings
  LLCP Version: 1.1
  Link Timeout: 1000 ms
  Max Inf Unit: 1024 octet
  Service List: 0000000000000011
Remote LLCP Settings
  LLCP Version: 1.0
  Link Timeout: 1500 ms
  Max Inf Unit: 128 octet
  Service List: 0000000000000001
2011-08-19 17:34:37,680 DEBUG [nfc.dev.pn53x] TgGetData
2011-08-19 17:34:37,680 DEBUG [nfc.npp.client] 73 bytes to send
2011-08-19 17:34:37,680 DEBUG [nfc.dev.pn53x] >>> 320000ff02fed486a600
2011-08-19 17:34:37,711 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:37,711 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:37,743 DEBUG [nfc.dev.pn53x] tty timeout set to 1.55 sec
2011-08-19 17:34:38,476 DEBUG [nfc.dev.pn53x] <<< 0000ff05fbd587000000a400
2011-08-19 17:34:38,476 DEBUG [nfc.dep] wait_command() completed in 796 ms
2011-08-19 17:34:38,476 DEBUG [nfc.dep] dep recv 2 byte
  0000: 00 00 ..
2011-08-19 17:34:38,476 DEBUG [nfc.llcp.llc] RECV 0 -> 0 SYMM
2011-08-19 17:34:38,476 DEBUG [nfc.llcp.tco] DLC (32,None) CONNECT dequeue CONNECT PDU
2011-08-19 17:34:38,476 DEBUG [nfc.llcp.llc] SEND 32 -> 1 CONN MIU=128 RW=1 SN=com.android.npp
2011-08-19 17:34:38,476 DEBUG [nfc.dep] dep send 19 byte
  0000: 05 20 06 0f 63 6f 6d 2e 61 6e 64 72 6f 69 64 2e . ..com.android.
  0010: 6e 70 70 npp
2011-08-19 17:34:38,492 DEBUG [nfc.dev.pn53x] TgSetData
2011-08-19 17:34:38,492 DEBUG [nfc.dev.pn53x] >>> 320000ff15ebd48e0520060f636f6d2e616e64726f69642e6e70709a00
2011-08-19 17:34:38,507 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:38,507 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:38,539 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:38,539 DEBUG [nfc.dev.pn53x] <<< 0000ff03fdd58f009c00
2011-08-19 17:34:38,539 DEBUG [nfc.dep] send_response() completed in 46 ms
2011-08-19 17:34:38,539 DEBUG [nfc.dev.pn53x] TgGetData
2011-08-19 17:34:38,539 DEBUG [nfc.dev.pn53x] >>> 320000ff02fed486a600
2011-08-19 17:34:38,569 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:38,569 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:38,601 DEBUG [nfc.dev.pn53x] tty timeout set to 1.55 sec
2011-08-19 17:34:38,601 DEBUG [nfc.dev.pn53x] <<< 0000ff09f7d587008190020200781700
2011-08-19 17:34:38,601 DEBUG [nfc.dep] wait_command() completed in 62 ms
2011-08-19 17:34:38,601 DEBUG [nfc.dep] dep recv 6 byte
  0000: 81 90 02 02 00 78 .....x
2011-08-19 17:34:38,601 DEBUG [nfc.llcp.llc] RECV 16 -> 32 CC MIU=248 RW=1
2011-08-19 17:34:38,601 DEBUG [nfc.llcp.tco] DLC (32,None) CONNECT enqueue CC PDU
2011-08-19 17:34:38,601 DEBUG [nfc.llcp.llc] SEND 0 -> 0 SYMM
2011-08-19 17:34:38,601 DEBUG [nfc.llcp.llc] connected (32 ===> 16)
2011-08-19 17:34:38,601 DEBUG [nfc.dep] dep send 2 byte
  0000: 00 00 ..
2011-08-19 17:34:38,617 DEBUG [nfc.npp.client] connection established with sap 16
2011-08-19 17:34:38,617 DEBUG [nfc.dev.pn53x] TgSetData
2011-08-19 17:34:38,617 DEBUG [nfc.llcp.tco] DLC (32,16) ESTABLISHED send() DLC 32 <-> 16 ESTABLISHED RW(R)=1 V(S)=0 V(SA)=0 RW(L)=1 V(R)=0 V(RA)=0
2011-08-19 17:34:38,617 DEBUG [nfc.dev.pn53x] >>> 320000ff04fcd48e00009e00
2011-08-19 17:34:38,648 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:38,648 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:38,664 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:38,664 DEBUG [nfc.dev.pn53x] <<< 0000ff03fdd58f009c00
2011-08-19 17:34:38,664 DEBUG [nfc.dep] send_response() completed in 46 ms
2011-08-19 17:34:38,680 DEBUG [nfc.dev.pn53x] TgGetData
2011-08-19 17:34:38,680 DEBUG [nfc.dev.pn53x] >>> 320000ff02fed486a600
2011-08-19 17:34:38,694 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:38,694 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:38,726 DEBUG [nfc.dev.pn53x] tty timeout set to 1.55 sec
2011-08-19 17:34:39,413 DEBUG [nfc.dev.pn53x] <<< 0000ff05fbd587000000a400
2011-08-19 17:34:39,413 DEBUG [nfc.dep] wait_command() completed in 733 ms
2011-08-19 17:34:39,413 DEBUG [nfc.dep] dep recv 2 byte
  0000: 00 00 ..
2011-08-19 17:34:39,413 DEBUG [nfc.llcp.llc] RECV 0 -> 0 SYMM
2011-08-19 17:34:39,413 DEBUG [nfc.llcp.tco] DLC (32,16) ESTABLISHED dequeue I PDU
2011-08-19 17:34:39,413 DEBUG [nfc.llcp.llc] SEND 32 -> 16 I N(S)=0 N(R)=0 LEN=73 SDU=0100000001010000003f91010e5402656e48656c6c6f20576f726c6411010d5402646548616c6c6f2057656c7451011854026672426f6e6a6f757220746f7574206c65206d6f6e6465
2011-08-19 17:34:39,413 DEBUG [nfc.npp.client] Message sent
2011-08-19 17:34:39,428 DEBUG [nfc.dep] dep send 76 byte
  0000: 43 20 00 01 00 00 00 01 01 00 00 00 3f 91 01 0e C ..........?...
  0010: 54 02 65 6e 48 65 6c 6c 6f 20 57 6f 72 6c 64 11 T.enHello World.
  0020: 01 0d 54 02 64 65 48 61 6c 6c 6f 20 57 65 6c 74 ..T.deHallo Welt
  0030: 51 01 18 54 02 66 72 42 6f 6e 6a 6f 75 72 20 74 Q..T.frBonjour t
  0040: 6f 75 74 20 6c 65 20 6d 6f 6e 64 65 out le monde
2011-08-19 17:34:39,428 DEBUG [nfc.llcp.tco] DLC (32,16) ESTABLISHED close()
2011-08-19 17:34:39,428 DEBUG [nfc.dev.pn53x] TgSetData
2011-08-19 17:34:39,428 DEBUG [nfc.dev.pn53x] >>> 320000ff4eb2d48e4320000100000001010000003f91010e5402656e48656c6c6f20576f726c6411010d5402646548616c6c6f2057656c7451011854026672426f6e6a6f757220746f7574206c65206d6f6e6465a300
2011-08-19 17:34:39,460 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:39,460 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:39,476 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:39,490 DEBUG [nfc.dev.pn53x] <<< 0000ff03fdd58f009c00
2011-08-19 17:34:39,490 DEBUG [nfc.dep] send_response() completed in 62 ms
2011-08-19 17:34:39,490 DEBUG [nfc.dev.pn53x] TgGetData
2011-08-19 17:34:39,490 DEBUG [nfc.dev.pn53x] >>> 320000ff02fed486a600
2011-08-19 17:34:39,506 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:39,522 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:39,538 DEBUG [nfc.dev.pn53x] tty timeout set to 1.55 sec
2011-08-19 17:34:39,538 DEBUG [nfc.dev.pn53x] <<< 0000ff06fad58700835001d000
2011-08-19 17:34:39,538 DEBUG [nfc.dep] wait_command() completed in 47 ms
2011-08-19 17:34:39,538 DEBUG [nfc.dep] dep recv 3 byte
  0000: 83 50 01 .P.
2011-08-19 17:34:39,538 DEBUG [nfc.llcp.llc] RECV 16 -> 32 RR N(R)=1
2011-08-19 17:34:39,538 DEBUG [nfc.llcp.tco] DLC (32,16) DISCONNECT enqueue RR PDU
2011-08-19 17:34:39,553 DEBUG [nfc.llcp.tco] DLC (32,16) DISCONNECT dequeue DISC PDU
2011-08-19 17:34:39,553 DEBUG [nfc.llcp.llc] SEND 32 -> 16 DISC
2011-08-19 17:34:39,553 DEBUG [nfc.dep] dep send 2 byte
  0000: 41 60 A`
2011-08-19 17:34:39,569 DEBUG [nfc.dev.pn53x] TgSetData
2011-08-19 17:34:39,569 DEBUG [nfc.dev.pn53x] >>> 320000ff04fcd48e4160fd00
2011-08-19 17:34:39,599 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:39,599 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:39,615 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:39,615 DEBUG [nfc.dev.pn53x] <<< 0000ff03fdd58f009c00
2011-08-19 17:34:39,615 DEBUG [nfc.dep] send_response() completed in 46 ms
2011-08-19 17:34:39,615 DEBUG [nfc.dev.pn53x] TgGetData
2011-08-19 17:34:39,631 DEBUG [nfc.dev.pn53x] >>> 320000ff02fed486a600
2011-08-19 17:34:39,647 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:39,647 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:39,677 DEBUG [nfc.dev.pn53x] tty timeout set to 1.55 sec
2011-08-19 17:34:39,677 DEBUG [nfc.dev.pn53x] <<< 0000ff06fad5870081d0005300
2011-08-19 17:34:39,677 DEBUG [nfc.dep] wait_command() completed in 62 ms
2011-08-19 17:34:39,677 DEBUG [nfc.dep] dep recv 3 byte
  0000: 81 d0 00 ...
2011-08-19 17:34:39,677 DEBUG [nfc.llcp.llc] RECV 16 -> 32 DM REASON=0
2011-08-19 17:34:39,694 DEBUG [nfc.llcp.tco] DLC (32,16) DISCONNECT enqueue DM PDU
2011-08-19 17:34:39,694 DEBUG [nfc.llcp.llc] SEND 0 -> 0 SYMM
2011-08-19 17:34:39,694 DEBUG [nfc.llcp.llc] shutdown requested
2011-08-19 17:34:39,694 DEBUG [nfc.dep] dep send 2 byte
  0000: 00 00 ..
2011-08-19 17:34:39,694 DEBUG [nfc.dev.pn53x] TgSetData
2011-08-19 17:34:39,694 DEBUG [nfc.dev.pn53x] >>> 320000ff04fcd48e00009e00
2011-08-19 17:34:39,724 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:39,724 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:39,740 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:39,740 DEBUG [nfc.dev.pn53x] <<< 0000ff03fdd58f009c00
2011-08-19 17:34:39,740 DEBUG [nfc.dep] send_response() completed in 46 ms
2011-08-19 17:34:39,756 DEBUG [nfc.dev.pn53x] TgGetData
2011-08-19 17:34:39,756 DEBUG [nfc.dev.pn53x] >>> 320000ff02fed486a600
2011-08-19 17:34:39,788 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:39,788 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:39,802 DEBUG [nfc.dev.pn53x] tty timeout set to 1.55 sec
2011-08-19 17:34:40,473 DEBUG [nfc.dev.pn53x] <<< 0000ff05fbd587000000a400
2011-08-19 17:34:40,473 DEBUG [nfc.dep] wait_command() completed in 717 ms
2011-08-19 17:34:40,473 DEBUG [nfc.dep] dep recv 2 byte
  0000: 00 00 ..
2011-08-19 17:34:40,473 DEBUG [nfc.llcp.llc] RECV 0 -> 0 SYMM
2011-08-19 17:34:40,473 DEBUG [nfc.llcp.llc] SEND 0 -> 0 DISC
2011-08-19 17:34:40,473 DEBUG [nfc.dep] dep send 2 byte
  0000: 01 40 .@
2011-08-19 17:34:40,490 DEBUG [nfc.dev.pn53x] TgSetData
2011-08-19 17:34:40,490 DEBUG [nfc.dev.pn53x] >>> 320000ff04fcd48e01405d00
2011-08-19 17:34:40,506 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:40,506 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:40,536 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:40,536 DEBUG [nfc.dev.pn53x] <<< 0000ff03fdd58f009c00
2011-08-19 17:34:40,536 DEBUG [nfc.dep] send_response() completed in 46 ms
2011-08-19 17:34:40,552 DEBUG [nfc.dev.pn53x] TgGetData
2011-08-19 17:34:40,552 DEBUG [nfc.dev.pn53x] >>> 320000ff02fed486a600
2011-08-19 17:34:40,568 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:40,568 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:40,598 DEBUG [nfc.dev.pn53x] tty timeout set to 1.55 sec
2011-08-19 17:34:40,598 DEBUG [nfc.dev.pn53x] <<< 0000ff03fdd587297b00
2011-08-19 17:34:40,598 DEBUG [nfc.llcp.llc] wait_command: IOError [Errno 41] released by initiator while operating as target
2011-08-19 17:34:40,598 INFO [nfc.llcp.llc] shutdown on link disruption
2011-08-19 17:34:40,598 DEBUG [nfc.llcp.llc] closing service access point 1
2011-08-19 17:34:40,598 DEBUG [nfc.llcp.llc] closing service access point 0
2011-08-19 17:34:40,598 DEBUG [nfc.llcp.llc] llc run thread terminated
2011-08-19 17:34:40,615 INFO [root] I was the Target
2011-08-19 17:34:40,615 DEBUG [nfc.dev.pn53x] RFConfiguration
2011-08-19 17:34:40,615 DEBUG [nfc.dev.pn53x] >>> 320000ff04fcd4320100f900
2011-08-19 17:34:40,645 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:40,645 DEBUG [nfc.dev.pn53x] <<< 0000ff00ff00
2011-08-19 17:34:40,661 DEBUG [nfc.dev.pn53x] tty timeout set to 0.1 sec
2011-08-19 17:34:40,661 DEBUG [nfc.dev.pn53x] <<< 0000ff02fed533f800
2011-08-19 17:34:40,661 DEBUG [nfc.dev.pn53x] closing COM2