From: Guennadi L. <gl...@ds...> - 2007-02-23 16:04:38
|
Hello all I am testing fast IrDA communication with a PXA270 CPU using IrNET + ppp stack with a verified reliable partner. PXA270 is running under 2.6.18-rc2 kernel. Normally I can establish a connection exchange data. In most cases I can also break the visible connection, see how the stack switches down to 9600 baud (the PXA270 is doing discovery), then I open the connection again, they negotiate to 4mbps again, re-establish ppp, and everything works again. However, sometimes this doesn't happen. I.e., they see each other at 9600 baud, I can see their records appear in /proc/net/irda/discovery, but they never switch to 4mbps. Another possible scenario is that they do switch to 4mbps, but the connection cannot be esrablished, i.e., no pings or any other IP packets can be exchanged. Interesting also, if I "kill -HUP" the pppd on ANY of the 2 sides, it switches to 4mbps and either re-establishes the connections or hangs at 4mbps further... Here is irdadump output on PXA270 side: 1) normal 9600 discovery: 15:11:41.049381 xid:cmd 1e91de63 > ffffffff S=6 s=2 (14) 15:11:41.169422 xid:cmd 1e91de63 > ffffffff S=6 s=3 (14) 15:11:41.250715 xid:rsp 1e91de63 < 39705d32 S=6 s=3 testhost hint=4400 [ Computer LAN Access ] (25) 15:11:41.289461 xid:cmd 1e91de63 > ffffffff S=6 s=4 (14) 15:11:41.409389 xid:cmd 1e91de63 > ffffffff S=6 s=5 (14) 15:11:41.490720 xid:rsp 1e91de63 < 39705d32 S=6 s=5 testhost hint=4400 [ Computer LAN Access ] (25) 15:11:41.529394 xid:cmd 1e91de63 > ffffffff S=6 s=* pxa270 hint=4400 [ Computer LAN Access ] (24) that's all what happens when they hang. 2) good case when they re-establish the connection: 15:11:43.839447 xid:cmd 1e91de63 > ffffffff S=6 s=0 (14) 15:11:43.959380 xid:cmd 1e91de63 > ffffffff S=6 s=1 (14) 15:11:44.079441 xid:cmd 1e91de63 > ffffffff S=6 s=2 (14) 15:11:44.199381 xid:cmd 1e91de63 > ffffffff S=6 s=3 (14) 15:11:44.280725 xid:rsp 1e91de63 < 39705d32 S=6 s=3 testhost hint=4400 [ Computer LAN Access ] (25) 15:11:44.319454 xid:cmd 1e91de63 > ffffffff S=6 s=4 (14) 15:11:44.439449 xid:cmd 1e91de63 > ffffffff S=6 s=5 (14) 15:11:44.520809 xid:rsp 1e91de63 < 39705d32 S=6 s=5 testhost hint=4400 [ Computer LAN Access ] (25) 15:11:44.559390 xid:cmd 1e91de63 > ffffffff S=6 s=* pxa270 hint=4400 [ Computer LAN Access ] (24) 15:11:44.753903 snrm:cmd ca=fe pf=1 1e91de63 < 39705d32 new-ca=a8 (33) 15:11:44.754050 ua:rsp ca=a8 pf=1 1e91de63 > 39705d32 (32) 15:11:44.819610 rr:cmd < ca=a8 pf=1 nr=0 (2) 15:11:44.819709 rr:rsp > ca=a8 pf=1 nr=0 (2) 15:11:44.822145 i:cmd < ca=a8 pf=1 nr=0 ns=0 LM slsap=2a dlsap=00 CONN_CMD (6) 15:11:44.822305 i:rsp > ca=a8 pf=1 nr=1 ns=0 LM slsap=00 dlsap=2a CONN_RSP (6) 15:11:44.824754 i:cmd < ca=a8 pf=1 nr=1 ns=1 LM slsap=2a dlsap=00 GET_VALUE_BY_CLASS: "IrNetv1" "IrDA:TinyTP:LsapSel" (33) 15:11:44.824867 i:rsp > ca=a8 pf=1 nr=2 ns=1 LM slsap=00 dlsap=2a GET_VALUE_BY_CLASS: Success Integer: 10 (15) 15:11:44.827461 i:cmd < ca=a8 pf=0 nr=2 ns=2 LM slsap=2a dlsap=00 DISC (6) 15:11:44.827831 i:cmd < ca=a8 pf=1 nr=2 ns=3 LM slsap=2c dlsap=10 CONN_CMD TTP credits=0(12) 15:11:44.827978 i:rsp > ca=a8 pf=1 nr=4 ns=2 LM slsap=10 dlsap=2c CONN_RSP TTP credits=0(12) 15:11:44.830523 i:cmd < ca=a8 pf=1 nr=3 ns=4 LM slsap=2c dlsap=10 TTP credits=0 (25) 15:11:44.830619 rr:rsp > ca=a8 pf=1 nr=5 (2) 15:11:44.832990 rr:cmd < ca=a8 pf=1 nr=3 (2) 3) killing pppd on the "testhost" side: 15:12:53.049399 xid:cmd 1e91de63 > ffffffff S=6 s=0 (14) 15:12:53.169443 xid:cmd 1e91de63 > ffffffff S=6 s=1 (14) 15:12:53.289383 xid:cmd 1e91de63 > ffffffff S=6 s=2 (14) 15:12:53.409437 xid:cmd 1e91de63 > ffffffff S=6 s=3 (14) 15:12:53.529441 xid:cmd 1e91de63 > ffffffff S=6 s=4 (14) 15:12:53.610855 xid:rsp 1e91de63 < 39705d32 S=6 s=4 testhost hint=4400 [ Computer LAN Access ] (25) 15:12:53.649450 xid:cmd 1e91de63 > ffffffff S=6 s=5 (14) 15:12:53.730788 xid:rsp 1e91de63 < 39705d32 S=6 s=5 testhost hint=4400 [ Computer LAN Access ] (25) 15:12:53.769386 xid:cmd 1e91de63 > ffffffff S=6 s=* pxa270 hint=4400 [ Computer LAN Access ] (24) (kill -HUP `pidof pppd`) 15:12:55.990454 xid:cmd ffffffff < 39705d32 S=6 s=0 (14) 15:12:56.073363 xid:cmd ffffffff < 39705d32 S=6 s=1 (14) 15:12:56.163314 xid:cmd ffffffff < 39705d32 S=6 s=2 (14) 15:12:56.163412 xid:rsp 1e91de63 > 39705d32 S=6 s=2 testhost hint=4400 [ Computer LAN Access ] (24) 15:12:56.253270 xid:cmd ffffffff < 39705d32 S=6 s=3 (14) 15:12:56.343319 xid:cmd ffffffff < 39705d32 S=6 s=4 (14) 15:12:56.433313 xid:cmd ffffffff < 39705d32 S=6 s=5 (14) 15:12:56.554506 xid:cmd ffffffff < 39705d32 S=6 s=* testhost hint=4400 [ Computer LAN Access ] (25) 15:12:56.585843 snrm:cmd ca=fe pf=1 1e91de63 < 39705d32 new-ca=a8 (33) 15:12:56.585988 ua:rsp ca=a8 pf=1 1e91de63 > 39705d32 (32) 15:13:00.162530 snrm:cmd ca=fe pf=1 1e91de63 < 39705d32 new-ca=a8 (33) 15:13:00.162681 ua:rsp ca=a8 pf=1 1e91de63 > 39705d32 (32) 15:13:00.228203 rr:cmd < ca=a8 pf=1 nr=0 (2) 15:13:00.228303 rr:rsp > ca=a8 pf=1 nr=0 (2) 15:13:00.230692 i:cmd < ca=a8 pf=1 nr=0 ns=0 LM slsap=39 dlsap=00 CONN_CMD (6) 15:13:00.230859 i:rsp > ca=a8 pf=1 nr=1 ns=0 LM slsap=00 dlsap=39 CONN_RSP (6) 15:13:00.233216 i:cmd < ca=a8 pf=1 nr=1 ns=1 LM slsap=39 dlsap=00 GET_VALUE_BY_CLASS: "IrNetv1" "IrDA:TinyTP:LsapSel" (33) 15:13:00.233360 i:rsp > ca=a8 pf=1 nr=2 ns=1 LM slsap=00 dlsap=39 GET_VALUE_BY_CLASS: Success Integer: 10 (15) 15:13:00.235850 i:cmd < ca=a8 pf=0 nr=2 ns=2 LM slsap=39 dlsap=00 DISC (6) 15:13:00.236221 i:cmd < ca=a8 pf=1 nr=2 ns=3 LM slsap=3b dlsap=10 CONN_CMD TTP credits=0(12) 15:13:00.236395 i:rsp > ca=a8 pf=1 nr=4 ns=2 LM slsap=10 dlsap=3b CONN_RSP TTP credits=0(12) 15:13:00.238885 i:cmd < ca=a8 pf=0 nr=3 ns=4 LM slsap=3b dlsap=10 TTP credits=0 (25) 15:13:00.239283 i:cmd < ca=a8 pf=1 nr=3 ns=5 LM slsap=3b dlsap=10 TTP credits=0 (25) 15:13:00.239443 rr:rsp > ca=a8 pf=1 nr=6 (2) 15:13:00.241686 rr:cmd < ca=a8 pf=1 nr=3 (2) 4) killing pppd on the pxa270 side: (kill -HUP `pidof pppd`) 15:22:45.091392 xid:cmd 1e91de63 > ffffffff S=6 s=3 (14) 15:22:45.211404 xid:cmd 1e91de63 > ffffffff S=6 s=4 (14) 15:22:45.292828 xid:rsp 1e91de63 < 39705d32 S=6 s=4 testhost hint=4400 [ Computer LAN Access ] (25) 15:22:45.331514 xid:cmd 1e91de63 > ffffffff S=6 s=5 (14) 15:22:45.412893 xid:rsp 1e91de63 < 39705d32 S=6 s=5 testhost hint=4400 [ Computer LAN Access ] (25) 15:22:45.451519 xid:cmd 1e91de63 > ffffffff S=6 s=* pxa270 hint=4400 [ Computer LAN Access ] (24) 15:22:45.975735 snrm:cmd ca=fe pf=1 1e91de63 > 39705d32 new-ca=a8 (33) 15:22:46.084195 ua:rsp ca=a8 pf=1 1e91de63 < 39705d32 (32) 15:22:46.096866 rr:cmd > ca=a8 pf=1 nr=0 (2) 15:22:46.098165 rr:rsp < ca=a8 pf=1 nr=0 (2) 15:22:46.098266 i:cmd > ca=a8 pf=1 nr=0 ns=0 LM slsap=14 dlsap=00 CONN_CMD (6) 15:22:46.100781 i:rsp < ca=a8 pf=1 nr=1 ns=0 LM slsap=00 dlsap=14 CONN_RSP (6) 15:22:46.100909 i:cmd > ca=a8 pf=1 nr=1 ns=1 LM slsap=14 dlsap=00 GET_VALUE_BY_CLASS: "IrNetv1" "IrDA:TinyTP:LsapSel" (33) 15:22:46.103456 i:rsp < ca=a8 pf=1 nr=2 ns=1 LM slsap=00 dlsap=14 GET_VALUE_BY_CLASS: Success Integer: 10 (15) 15:22:46.103662 i:cmd > ca=a8 pf=0 nr=2 ns=2 LM slsap=14 dlsap=00 DISC (6) 15:22:46.104883 i:cmd > ca=a8 pf=1 nr=2 ns=3 LM slsap=16 dlsap=10 CONN_CMD TTP credits=0(12) 15:22:46.106456 i:rsp < ca=a8 pf=1 nr=4 ns=2 LM slsap=10 dlsap=16 CONN_RSP TTP credits=0(12) 15:22:46.106636 i:cmd > ca=a8 pf=1 nr=3 ns=4 LM slsap=16 dlsap=10 TTP credits=0 (25) 15:22:46.109019 rr:rsp < ca=a8 pf=1 nr=5 (2) 15:22:46.109112 rr:cmd > ca=a8 pf=1 nr=3 (2) 15:22:46.111557 i:rsp < ca=a8 pf=1 nr=5 ns=3 LM slsap=10 dlsap=16 TTP credits=1 (13) 15:22:46.111630 rr:cmd > ca=a8 pf=1 nr=4 (2) So, looks like in problem cases nobody just cares to send the "snrm" command like 15:22:45.975735 snrm:cmd ca=fe pf=1 1e91de63 > 39705d32 new-ca=a8 (33) which, probably, is a parameter update command, right? And killing pppd makes the respective host send such a command, which, however, is also not quite successful. What can be the problem? Last kernel known to work was 2.4.21:-) Thanks Guennadi --------------------------------- Guennadi Liakhovetski, Ph.D. DSA Daten- und Systemtechnik GmbH Pascalstr. 28 D-52076 Aachen Germany |