nfcpy

latency with npp-test-server & Android's ndef push

Asked by hanzo hattori

Hi there,
Thanks for all your great works with nfcpy library.

little similar to this question tho :
https://answers.launchpad.net/nfcpy/+question/168566

I can get NDEF text messages with npp-test-server.py, but getting troubled with a severe latency like 5000ms at the worst case (it ranges from 1000ms with good luck). I am pushing NDEF with enableForegroundNdefPush() method. The NDEF data type is NDEF Well-known NFC Type RTD-Text format. The Android device is Samsung Galaxy SII LTE and Im using SONY rc-s370 as a reader connected to windows xp.

the running options are like :
------------------------------------------------
npp-test-server.py -f debug.log --device usb:054C:02E1 -d nfc.llcp.llc -d
nfc.npp.server --mode initiator -l -1
------------------------------------------------

and servers give me the log like (so long, sorry..):
------------------------------------------------
2012-02-10 15:33:18,023 INFO [root] enable debug output for module 'nfc.llcp.llc'
2012-02-10 15:33:18,023 INFO [root] enable debug output for module 'nfc.npp.server'
2012-02-10 15:33:18,023 INFO [nfc.clf] searching for reader with path 'usb:054C:02E1'
2012-02-10 15:33:18,023 INFO [dev] searching for a usb bus reader
2012-02-10 15:33:18,039 DEBUG [dev] path match for 'usb:vendor:[product]'
2012-02-10 15:33:18,039 DEBUG [dev] import nfc.dev.rcs956_usb
2012-02-10 15:33:18,053 INFO [nfc.dev.pn53x] chipset is a PN533 version 1.48
2012-02-10 15:33:20,851 INFO [nfc.dev.pn53x] activated a p2p target in 424 kbps active mode
2012-02-10 15:33:20,851 DEBUG [nfc.llcp.llc] llc cfg {'recv-lto': 1500, 'send-miu': 128, 'send-agf': True, 'send-lto': 1500, 'send-lsc': 3, 'recv-miu': 1024, 'recv-wks': 3, 'send-wks': 1, 'rcvd-ver': (1, 0)}
2012-02-10 15:33:20,851 INFO [nfc.llcp.llc] LLCP Link established, I'm the DEP Initiator
Local LLCP Settings
  LLCP Version: 1.1
  Link Timeout: 1500 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
2012-02-10 15:33:20,867 DEBUG [nfc.llcp.llc] SEND 0 -> 0 SYMM
2012-02-10 15:33:20,867 INFO [nfc.npp.server] npp server bound to port 16
2012-02-10 15:33:20,867 DEBUG [nfc.llcp.llc] in exchange => IOError [Errno 10] rf field not activated in time by active mode peer
2012-02-10 15:33:20,867 INFO [nfc.llcp.llc] shutdown on link disruption
2012-02-10 15:33:20,867 DEBUG [nfc.llcp.llc] closing service access point 16
2012-02-10 15:33:20,867 DEBUG [nfc.llcp.llc] shutdown socket DLC 16 <-> None LISTEN RW(R)=None V(S)=0 V(SA)=0 RW(L)=2 V(R)=0 V(RA)=0
2012-02-10 15:33:20,867 ERROR [nfc.npp.server] nfc.llcp.Error: [EPIPE] Broken pipe
2012-02-10 15:33:20,867 DEBUG [nfc.llcp.llc] closing service access point 1
2012-02-10 15:33:20,867 DEBUG [nfc.llcp.llc] closing service access point 0
2012-02-10 15:33:20,867 DEBUG [nfc.llcp.llc] llc run thread terminated
2012-02-10 15:33:21,881 DEBUG [nfc.llcp.llc] shutdown requested
2012-02-10 15:33:21,881 INFO [root] I was the Initiator
2012-02-10 15:33:23,819 INFO [nfc.dev.pn53x] activated a p2p target in 424 kbps active mode
2012-02-10 15:33:23,819 DEBUG [nfc.llcp.llc] llc cfg {'recv-lto': 1500, 'send-miu': 128, 'send-agf': True, 'send-lto': 1500, 'send-lsc': 3, 'recv-miu': 1024, 'recv-wks': 3, 'send-wks': 1, 'rcvd-ver': (1, 0)}
2012-02-10 15:33:23,819 INFO [nfc.llcp.llc] LLCP Link established, I'm the DEP Initiator
Local LLCP Settings
  LLCP Version: 1.1
  Link Timeout: 1500 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
2012-02-10 15:33:23,835 DEBUG [nfc.llcp.llc] SEND 0 -> 0 SYMM
2012-02-10 15:33:23,835 INFO [nfc.npp.server] npp server bound to port 16
2012-02-10 15:33:23,851 DEBUG [nfc.llcp.llc] in exchange => IOError [Errno 10] rf field not activated in time by active mode peer
2012-02-10 15:33:23,851 INFO [nfc.llcp.llc] shutdown on link disruption
2012-02-10 15:33:23,851 DEBUG [nfc.llcp.llc] closing service access point 16
2012-02-10 15:33:23,851 DEBUG [nfc.llcp.llc] shutdown socket DLC 16 <-> None LISTEN RW(R)=None V(S)=0 V(SA)=0 RW(L)=2 V(R)=0 V(RA)=0
2012-02-10 15:33:23,851 ERROR [nfc.npp.server] nfc.llcp.Error: [EPIPE] Broken pipe
2012-02-10 15:33:23,851 DEBUG [nfc.llcp.llc] closing service access point 1
2012-02-10 15:33:23,851 DEBUG [nfc.llcp.llc] closing service access point 0
2012-02-10 15:33:23,851 DEBUG [nfc.llcp.llc] llc run thread terminated
2012-02-10 15:33:24,867 DEBUG [nfc.llcp.llc] shutdown requested
2012-02-10 15:33:24,867 INFO [root] I was the Initiator
2012-02-10 15:33:27,601 INFO [nfc.dev.pn53x] activated a p2p target in 424 kbps active mode
2012-02-10 15:33:27,601 DEBUG [nfc.llcp.llc] llc cfg {'recv-lto': 1500, 'send-miu': 128, 'send-agf': True, 'send-lto': 1500, 'send-lsc': 3, 'recv-miu': 1024, 'recv-wks': 3, 'send-wks': 1, 'rcvd-ver': (1, 0)}
2012-02-10 15:33:27,601 INFO [nfc.llcp.llc] LLCP Link established, I'm the DEP Initiator
Local LLCP Settings
  LLCP Version: 1.1
  Link Timeout: 1500 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
2012-02-10 15:33:27,617 DEBUG [nfc.llcp.llc] SEND 0 -> 0 SYMM
2012-02-10 15:33:27,617 INFO [nfc.npp.server] npp server bound to port 16
2012-02-10 15:33:27,617 DEBUG [nfc.llcp.llc] in exchange => IOError [Errno 10] rf field not activated in time by active mode peer
2012-02-10 15:33:27,617 INFO [nfc.llcp.llc] shutdown on link disruption
2012-02-10 15:33:27,617 DEBUG [nfc.llcp.llc] closing service access point 16
2012-02-10 15:33:27,617 DEBUG [nfc.llcp.llc] shutdown socket DLC 16 <-> None LISTEN RW(R)=None V(S)=0 V(SA)=0 RW(L)=2 V(R)=0 V(RA)=0
2012-02-10 15:33:27,617 ERROR [nfc.npp.server] nfc.llcp.Error: [EPIPE] Broken pipe
2012-02-10 15:33:27,617 DEBUG [nfc.llcp.llc] closing service access point 1
2012-02-10 15:33:27,617 DEBUG [nfc.llcp.llc] closing service access point 0
2012-02-10 15:33:27,617 DEBUG [nfc.llcp.llc] llc run thread terminated
2012-02-10 15:33:28,631 DEBUG [nfc.llcp.llc] shutdown requested
2012-02-10 15:33:28,631 INFO [root] I was the Initiator
2012-02-10 15:33:28,773 INFO [nfc.dev.pn53x] activated a p2p target in 424 kbps active mode
2012-02-10 15:33:28,773 DEBUG [nfc.llcp.llc] llc cfg {'recv-lto': 1500, 'send-miu': 128, 'send-agf': True, 'send-lto': 1500, 'send-lsc': 3, 'recv-miu': 1024, 'recv-wks': 3, 'send-wks': 1, 'rcvd-ver': (1, 0)}
2012-02-10 15:33:28,773 INFO [nfc.llcp.llc] LLCP Link established, I'm the DEP Initiator
Local LLCP Settings
  LLCP Version: 1.1
  Link Timeout: 1500 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
2012-02-10 15:33:28,788 DEBUG [nfc.llcp.llc] SEND 0 -> 0 SYMM
2012-02-10 15:33:28,788 INFO [nfc.npp.server] npp server bound to port 16
2012-02-10 15:33:28,788 DEBUG [nfc.llcp.llc] in exchange => IOError [Errno 10] rf field not activated in time by active mode peer
2012-02-10 15:33:28,788 INFO [nfc.llcp.llc] shutdown on link disruption
2012-02-10 15:33:28,788 DEBUG [nfc.llcp.llc] closing service access point 16
2012-02-10 15:33:28,788 DEBUG [nfc.llcp.llc] shutdown socket DLC 16 <-> None LISTEN RW(R)=None V(S)=0 V(SA)=0 RW(L)=2 V(R)=0 V(RA)=0
2012-02-10 15:33:28,788 ERROR [nfc.npp.server] nfc.llcp.Error: [EPIPE] Broken pipe
2012-02-10 15:33:28,788 DEBUG [nfc.llcp.llc] closing service access point 1
2012-02-10 15:33:28,788 DEBUG [nfc.llcp.llc] closing service access point 0
2012-02-10 15:33:28,788 DEBUG [nfc.llcp.llc] llc run thread terminated
2012-02-10 15:33:29,788 DEBUG [nfc.llcp.llc] shutdown requested
2012-02-10 15:33:29,788 INFO [root] I was the Initiator
2012-02-10 15:33:29,928 INFO [nfc.dev.pn53x] activated a p2p target in 424 kbps active mode
2012-02-10 15:33:29,928 DEBUG [nfc.llcp.llc] llc cfg {'recv-lto': 1500, 'send-miu': 128, 'send-agf': True, 'send-lto': 1500, 'send-lsc': 3, 'recv-miu': 1024, 'recv-wks': 3, 'send-wks': 1, 'rcvd-ver': (1, 0)}
2012-02-10 15:33:29,928 INFO [nfc.llcp.llc] LLCP Link established, I'm the DEP Initiator
Local LLCP Settings
  LLCP Version: 1.1
  Link Timeout: 1500 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
2012-02-10 15:33:29,944 DEBUG [nfc.llcp.llc] SEND 0 -> 0 SYMM
2012-02-10 15:33:29,944 INFO [nfc.npp.server] npp server bound to port 16
2012-02-10 15:33:29,944 DEBUG [nfc.llcp.llc] in exchange => IOError [Errno 10] rf field not activated in time by active mode peer
2012-02-10 15:33:29,944 INFO [nfc.llcp.llc] shutdown on link disruption
2012-02-10 15:33:29,944 DEBUG [nfc.llcp.llc] closing service access point 16
2012-02-10 15:33:29,944 DEBUG [nfc.llcp.llc] shutdown socket DLC 16 <-> None LISTEN RW(R)=None V(S)=0 V(SA)=0 RW(L)=2 V(R)=0 V(RA)=0
2012-02-10 15:33:29,944 ERROR [nfc.npp.server] nfc.llcp.Error: [EPIPE] Broken pipe
2012-02-10 15:33:29,944 DEBUG [nfc.llcp.llc] closing service access point 1
2012-02-10 15:33:29,944 DEBUG [nfc.llcp.llc] closing service access point 0
2012-02-10 15:33:29,944 DEBUG [nfc.llcp.llc] llc run thread terminated
2012-02-10 15:33:30,944 DEBUG [nfc.llcp.llc] shutdown requested
2012-02-10 15:33:30,944 INFO [root] I was the Initiator
2012-02-10 15:33:31,085 INFO [nfc.dev.pn53x] activated a p2p target in 424 kbps active mode
2012-02-10 15:33:31,085 DEBUG [nfc.llcp.llc] llc cfg {'recv-lto': 1500, 'send-miu': 128, 'send-agf': True, 'send-lto': 1500, 'send-lsc': 3, 'recv-miu': 1024, 'recv-wks': 3, 'send-wks': 1, 'rcvd-ver': (1, 0)}
2012-02-10 15:33:31,085 INFO [nfc.llcp.llc] LLCP Link established, I'm the DEP Initiator
Local LLCP Settings
  LLCP Version: 1.1
  Link Timeout: 1500 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
2012-02-10 15:33:31,085 DEBUG [nfc.llcp.llc] SEND 0 -> 0 SYMM
2012-02-10 15:33:31,101 INFO [nfc.npp.server] npp server bound to port 16
2012-02-10 15:33:31,101 DEBUG [nfc.llcp.llc] in exchange => IOError [Errno 10] rf field not activated in time by active mode peer
2012-02-10 15:33:31,101 INFO [nfc.llcp.llc] shutdown on link disruption
2012-02-10 15:33:31,101 DEBUG [nfc.llcp.llc] closing service access point 16
2012-02-10 15:33:31,101 DEBUG [nfc.llcp.llc] shutdown socket DLC 16 <-> None LISTEN RW(R)=None V(S)=0 V(SA)=0 RW(L)=2 V(R)=0 V(RA)=0
2012-02-10 15:33:31,101 ERROR [nfc.npp.server] nfc.llcp.Error: [EPIPE] Broken pipe
2012-02-10 15:33:31,101 DEBUG [nfc.llcp.llc] closing service access point 1
2012-02-10 15:33:31,101 DEBUG [nfc.llcp.llc] closing service access point 0
2012-02-10 15:33:31,101 DEBUG [nfc.llcp.llc] llc run thread terminated
2012-02-10 15:33:32,117 DEBUG [nfc.llcp.llc] shutdown requested
2012-02-10 15:33:32,117 INFO [root] I was the Initiator
2012-02-10 15:33:32,256 INFO [nfc.dev.pn53x] activated a p2p target in 424 kbps active mode
2012-02-10 15:33:32,256 DEBUG [nfc.llcp.llc] llc cfg {'recv-lto': 1500, 'send-miu': 128, 'send-agf': True, 'send-lto': 1500, 'send-lsc': 3, 'recv-miu': 1024, 'recv-wks': 3, 'send-wks': 1, 'rcvd-ver': (1, 0)}
2012-02-10 15:33:32,256 INFO [nfc.llcp.llc] LLCP Link established, I'm the DEP Initiator
Local LLCP Settings
  LLCP Version: 1.1
  Link Timeout: 1500 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
2012-02-10 15:33:32,256 DEBUG [nfc.llcp.llc] SEND 0 -> 0 SYMM
2012-02-10 15:33:32,273 INFO [nfc.npp.server] npp server bound to port 16
2012-02-10 15:33:32,381 DEBUG [nfc.llcp.llc] RECV 33 -> 1 CONN MIU=128 RW=1 SN=com.android.npp
2012-02-10 15:33:32,381 INFO [nfc.llcp.tco] accepting CONNECT from SAP 33
2012-02-10 15:33:32,381 DEBUG [nfc.llcp.llc] new data link connection (16 <=== 33)
2012-02-10 15:33:32,381 DEBUG [nfc.npp.server] client connected, serving in main thread
2012-02-10 15:33:32,381 INFO [nfc.npp.server] serving npp client on remote sap 33
2012-02-10 15:33:32,381 DEBUG [nfc.llcp.llc] SEND 0 -> 0 SYMM
2012-02-10 15:33:33,163 DEBUG [nfc.llcp.llc] RECV 0 -> 0 SYMM
2012-02-10 15:33:33,163 DEBUG [nfc.llcp.llc] SEND 16 -> 33 CC MIU=128 RW=2
2012-02-10 15:33:33,210 DEBUG [nfc.llcp.llc] RECV 33 -> 16 I N(S)=0 N(R)=0 LEN=40 SDU=0100000001010000001ed1011a5402656e3030303030303031303030303034343030303030303031
2012-02-10 15:33:33,210 DEBUG [nfc.llcp.llc] SEND 16 -> 33 RR N(R)=1
2012-02-10 15:33:33,226 DEBUG [nfc.llcp.llc] RECV 33 -> 16 DISC
2012-02-10 15:33:33,226 DEBUG [nfc.npp.server] got 40 octets data
2012-02-10 15:33:33,242 DEBUG [nfc.llcp.llc] SEND 16 -> 33 DM REASON=0
2012-02-10 15:33:33,242 DEBUG [nfc.npp.server] version 1, 1 entries
2012-02-10 15:33:33,242 DEBUG [nfc.npp.server] processing NDEF message #1
2012-02-10 15:33:33,242 DEBUG [nfc.npp.server] action code 1, ndef length 30 octet
2012-02-10 15:33:33,242 DEBUG [nfc.npp.server] have complete ndef message, 30 octets
2012-02-10 15:33:33,242 INFO [root] ndef push server got message
2012-02-10 15:33:33,242 INFO [root] 0000: d1 01 1a 54 02 65 6e 30 30 30 30 30 30 30 31 30 ...T.en000000010
  0010: 30 30 30 30 34 34 30 30 30 30 30 30 30 31 00004400000001
2012-02-10 15:33:33,242 INFO [root] NDEF records:
2012-02-10 15:33:33,242 INFO [root] [0] type = urn:nfc:wkt:T
2012-02-10 15:33:33,242 INFO [root] [0] name =
2012-02-10 15:33:33,242 INFO [root] [0] data = .en00000001000004400000001
2012-02-10 15:33:33,273 DEBUG [nfc.llcp.llc] shutdown requested
2012-02-10 15:33:34,006 DEBUG [nfc.llcp.llc] RECV 0 -> 0 SYMM
2012-02-10 15:33:34,006 INFO [nfc.llcp.llc] shutdown on local request
2012-02-10 15:33:34,006 DEBUG [nfc.llcp.llc] SEND 0 -> 0 DISC
2012-02-10 15:33:34,038 ERROR [nfc.dev.pn53x_usb] libusb0-dll:err [_usb_reap_async] timeout error

2012-02-10 15:33:34,038 DEBUG [nfc.llcp.llc] closing service access point 16
2012-02-10 15:33:34,038 DEBUG [nfc.llcp.llc] shutdown socket DLC 16 <-> None LISTEN RW(R)=None V(S)=0 V(SA)=0 RW(L)=2 V(R)=0 V(RA)=0
2012-02-10 15:33:34,038 ERROR [nfc.npp.server] nfc.llcp.Error: [EPIPE] Broken pipe
2012-02-10 15:33:34,038 DEBUG [nfc.llcp.llc] closing service access point 1
2012-02-10 15:33:34,038 DEBUG [nfc.llcp.llc] closing service access point 0
2012-02-10 15:33:34,038 DEBUG [nfc.llcp.llc] llc run thread terminated
2012-02-10 15:33:34,038 INFO [root] I was the Initiator
2012-02-10 15:33:38,648 INFO [root] aborted by user
------------------------------------------------

The log can be read as LLCP link has "IOError [Errno 10] rf field not activated in time by active mode peer", but I don't understand how to avoid it.

I have changed the "Link Timeout" of LLCP server to 1500 ms to become same as remote timeout parameter, but it didn't improve very much.

Every advice will be appreciated.
thanks,
/h

Question information

Language:
English Edit question
Status:
Solved
For:
nfcpy Edit question
Assignee:
No assignee Edit question
Solved by:
hanzo hattori
Solved:
Last query:
Last reply:
Revision history for this message
Stephen Tiedemann (stephen-tiedemann) said : 		#1

I can't see that behaviour with neither the Google Nexus nor Galaxy Nexus. Link timeout is unlikely to be the cause. You could check if active mode or 424 kbps cause the problem. Look for the line "for mode, speed in (("active", "424"), ("passive", "424")):" in nfc/dev/pn53x.py and replace ("active", "424") with ("passive", "212"). Maybe that gives further clue.

Revision history for this message
hanzo hattori (hnzhtr) said : 		#2

hi Stephen,
thanks for your swift reply!

i made commented-out ("active", "424") and instead used set of ("passive", "212") , and now it works like a charm.

tho ("active", "212") set was also allowably quick against my expectation, i don't need to push-back any data from the reader this time, ("passive", "212") mode should be suitable.

anyway thanks again for this great library and your support,
gonna dig deeper into nfcpy.
/h