search

Cascoda / ca8210-linux

Linux kernel driver for direct SPI communication with Cascoda's CA-8210 IEEE 802.15.4 transceiver
BSD 3-Clause "New" or "Revised" License
5 stars 5 forks source link

Response to Synchronous request seen twice @ user level #12

Open CiaranWoodward opened 7 years ago

CiaranWoodward commented 7 years ago

Using the debug node to control the driver, two Identical responses were seen to the same request. The dissected exchange.log from kernel exchange and dmesg is shown below.

It can be seen that the TDME-GETSFR Confirm is received twice, which means that the SETSFR command response is lost. It can also be seen that there were a lot of retries and failed IRQs around the time of error.

The driver does not require restarting, and remains functional following the issue.

at: 2017-05-17 13:16:42.571417
Writing data:
TDME-GETSFR Request
SFRPage 0x0 (0)
SFRAddress 0xdb
---
at: 2017-05-17 13:16:42.571482
Received  Sync:
MCPS-DATA Indication
SrcAddrMode 0x2 (16-bit short address)
SrcPANId 0x45  0x45
SrcAddress 0x1  0x0
DstAddrMode 0x2 (16-bit short address)
DstPANId 0x45  0x45
DstAddress 0x3  0x0
Msdulength 0x64
MpduLinkQuality 0xff
DSN 0x33
TimeStamp 0x0  0x0  0x0  0x0
Msdu 0x1  0x2  0x3  0x4  0x5  0x6  0x7  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0  0x0
SecurityLevel 0x0 (None)
---

at: 2017-05-17 13:16:42.601384
Received  Sync:
TDME-GETSFR Confirm
Status 0x0 (SUCCESS)
SFRPage 0x0 (0)
SFRAddress 0xdb
SFRValue 0xe
---

at: 2017-05-17 13:16:42.631382
Writing data:
TDME-SETSFR Request
SFRPage 0x0 (0)
SFRAddress 0xdb
SFRValue 0xa
---

at: 2017-05-17 13:16:42.631443
Received  Sync:
TDME-GETSFR Confirm
Status 0x0 (SUCCESS)
SFRPage 0x0 (0)
SFRAddress 0xdb
SFRValue 0xe
---

at: 2017-05-17 13:16:42.632921
Received Async:
TDME-SETSFR Confirm
Status 0x0 (SUCCESS)
SFRPage 0x0 (0)
SFRAddress 0xdb
---

Dmesg:

66926 May 17 13:16:41 Raspi3B-Rhys kernel: [ 2245.720786] ca8210 spi0.0: retried spi write
66927 May 17 13:16:41 Raspi3B-Rhys kernel: [ 2245.721688] ca8210 spi0.0: ca8210 was busy during attempted write
66928 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.750776] ca8210 spi0.0: retried spi write
66929 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.751677] ca8210 spi0.0: ca8210 was busy during attempted write
66930 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.780786] ca8210 spi0.0: retried spi write
66931 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.781681] ca8210 spi0.0: ca8210 was busy during attempted write
66932 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.810776] ca8210 spi0.0: retried spi write
66933 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.811729] ca8210 spi0.0: ca8210 was busy during attempted write
66934 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.840786] ca8210 spi0.0: retried spi write
66935 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.841681] ca8210 spi0.0: ca8210 was busy during attempted write
66936 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.870775] ca8210 spi0.0: retried spi write
66937 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.871669] ca8210 spi0.0: ca8210 was busy during attempted write
66938 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.900787] ca8210 spi0.0: retried spi write
66939 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.911462] ca8210 spi0.0: ca8210 was busy during attempted write
66940 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.940770] ca8210 spi0.0: retried spi write
66941 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.941638] ca8210 spi0.0: ca8210 was busy during attempted write
66942 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.970768] ca8210 spi0.0: retried spi write
66943 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.980961] ca8210 spi0.0: ca8210 was busy during attempted write
66944 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.980966] ca8210 spi0.0: IRQ servicing NACKd, dropping transfer
66945 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2245.981403] ca8210 spi0.0: ca8210 was busy during attempted write
66946 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.010764] ca8210 spi0.0: retried spi write
66947 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.011635] ca8210 spi0.0: ca8210 was busy during attempted write
66948 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.040789] ca8210 spi0.0: retried spi write
66949 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.041678] ca8210 spi0.0: ca8210 was busy during attempted write
66950 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.070789] ca8210 spi0.0: retried spi write
66951 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.071671] ca8210 spi0.0: ca8210 was busy during attempted write
66952 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.071676] ca8210 spi0.0: IRQ servicing NACKd, dropping transfer
66953 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.072102] ca8210 spi0.0: ca8210 was busy during attempted write
66954 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.100819] ca8210 spi0.0: retried spi write
66955 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.101690] ca8210 spi0.0: ca8210 was busy during attempted write
66956 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.130773] ca8210 spi0.0: retried spi write
66957 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.131656] ca8210 spi0.0: ca8210 was busy during attempted write
66958 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.131662] ca8210 spi0.0: IRQ servicing NACKd, dropping transfer
66959 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.132090] ca8210 spi0.0: ca8210 was busy during attempted write
66960 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.160798] ca8210 spi0.0: retried spi write
66961 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.161671] ca8210 spi0.0: ca8210 was busy during attempted write
66962 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.190785] ca8210 spi0.0: retried spi write
66963 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.191841] ca8210 spi0.0: ca8210 was busy during attempted write
66964 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.191847] ca8210 spi0.0: IRQ servicing NACKd, dropping transfer
66965 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.192278] ca8210 spi0.0: ca8210 was busy during attempted write
66966 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.220768] ca8210 spi0.0: retried spi write
66967 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.221653] ca8210 spi0.0: ca8210 was busy during attempted write
66968 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.250793] ca8210 spi0.0: retried spi write
66969 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.251681] ca8210 spi0.0: ca8210 was busy during attempted write
66970 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.280787] ca8210 spi0.0: retried spi write
66971 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.281659] ca8210 spi0.0: ca8210 was busy during attempted write
66972 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.310817] ca8210 spi0.0: retried spi write
66973 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.312238] ca8210 spi0.0: ca8210 was busy during attempted write
66974 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.312247] ca8210 spi0.0: IRQ servicing NACKd, dropping transfer
66975 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.312939] ca8210 spi0.0: ca8210 was busy during attempted write
66976 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.340818] ca8210 spi0.0: retried spi write
66977 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.342225] ca8210 spi0.0: ca8210 was busy during attempted write
66978 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.370821] ca8210 spi0.0: retried spi write
66979 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.372349] ca8210 spi0.0: ca8210 was busy during attempted write
66980 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.372360] ca8210 spi0.0: IRQ servicing NACKd, dropping transfer
66981 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.373761] ca8210 spi0.0: ca8210 was busy during attempted write
66982 May 17 13:16:42 Raspi3B-Rhys kernel: [ 2246.373770] ca8210 spi0.0: IRQ servicing NACKd, dropping transfer