Cascoda driver stops working

[mtusnio]

In some circumstances, especially under high load, the cascoda driver stops working. Running ifconfig lowpan0 down throws:

[ 58.514110] ca8210 spi0.0: ca8210 was busy during attempted write
[ 58.540137] ca8210 spi0.0: spi write retry 1...
[ 58.545942] ca8210 spi0.0: ca8210 was busy during attempted write
[ 58.570183] ca8210 spi0.0: spi write retry 1...

Steps to reproduce:

1. leave iperf3 tests running between 2 boards using 6lowpan.

[nikhil-zinjurde-imgtec]

@mtusnio the above logs do not indicate that the ca8210 driver has stopped working, this is in fact a workaround put in by Cascoda to reload the driver when it stops. Can you please check 6lowpan ping test to confirm whether the driver has actually stopped working?

[mtusnio]

I haven't tried pinging, but in all cases running tcpdump on the interface reports no traffic at all despite clickers sending packets.

[Shpinkso]

@mtusnio is there an automated test case that is likely to be able to check this doesn't reoccur (once it's fixed)

[mtusnio]

Not at the moment, but it might be related to some of the iperf3 issues we've noticed, so it might be worth investigating that.

[mtusnio]

root@myCi40:/# ping6 -I lowpan0 fe80:0000:0000:0000:0204:a30b:0000:e4f4
PING fe80:0000:0000:0000:0204:a3[ 396.301474] ca8210 spi0.0: Link transmission unsuccessful, status = 241
0b:0000:e4f4 (fe[ 396.309368] ca8210 spi0.0: Waiting for transaction overflow to stabilise...
80::204:a30b:0:e4f4): 56 data bytes
[ 398.320172] ca8210 spi0.0: Resetting MAC...
[ 398.325240] ca8210 spi0.0: ca8210 was busy during attempted write
[ 398.350124] ca8210 spi0.0: spi write retry 1...
^C
--- fe80:0000:0000:0000:0204:a30b:0000:e4f4 ping statistics ---
15 packets transmitted, 0 packets received, 100% packet loss
root@myCi40:/# ping6 -I lowpan0 fe80:0000:0000:0000:0204:a30b:0000:e4f4
PING fe80:0000:0000:0000:0204:a30b:0000:e4f4 (fe80::204:a30b:0:e4f4): 56 data bytes
[ 423.677981] ca8210 spi0.0: Link transmission unsuccessful, status = 241
[ 423.685531] ca8210 spi0.0: Waiting for transaction overflow to stabilise...
[ 425.700212] ca8210 spi0.0: Resetting MAC...
[ 425.705190] ca8210 spi0.0: ca8210 was busy during attempted write
[ 425.730103] ca8210 spi0.0: spi write retry 1...
[ 430.671572] ca8210 spi0.0: Link transmission unsuccessful, status = 241
[ 430.679067] ca8210 spi0.0: Waiting for transaction overflow to stabilise...
[ 432.690272] ca8210 spi0.0: Resetting MAC...
[ 432.695295] ca8210 spi0.0: ca8210 was busy during attempted write
[ 432.720100] ca8210 spi0.0: spi write retry 1...

[abhijit-mahajani-imgtec]

Blocked on #295

[nikhil-zinjurde-imgtec]

The failure seems more prominent with Cascoda driver v1.3.0 on simply pinging 2 Ci40 boards with each other. The ping has not survived more than an hour's time.

64 bytes from 2001:1418:100::1: seq=1572 ttl=64 time=24.133 ms
64 bytes from 2001:1418:100::1: seq=1573 ttl=64 time=24.829 ms
64 bytes from 2001:1418:100::1: seq=1574 ttl=64 time=23.616 ms
64 bytes from 2001:1418:100::1: seq=1575 ttl=64 time=23.309 ms
64 bytes from 2001:1418:100::1: seq=1576 ttl=64 time=23.551 ms
[ 2816.955169] ca8210 spi0.0: Link transmission unsuccessful, status = 241
[ 2816.962719] ca8210 spi0.0: Waiting for transaction overflow to stabilise...
[ 2818.976747] ca8210 spi0.0: Resetting MAC...
[ 2818.983119] ca8210 spi0.0: ca8210 was busy during attempted write
[ 2818.990054] ca8210 spi0.0: retried spi write
[ 2818.996747] ca8210 spi0.0: ca8210 was busy during attempted write
[ 2819.003549] ca8210 spi0.0: retried spi write
[ 2819.009662] ca8210 spi0.0: ca8210 was busy during attempted write
[ 2819.016462] ca8210 spi0.0: retried spi write
[ 2819.022551] ca8210 spi0.0: ca8210 was busy during attempted write
[ 2819.029456] ca8210 spi0.0: retried spi write
64 bytes from 2001:1418:100::1: [ 2819.037182] ca8210 spi0.0: ca8210 was busy during attempted write
seq=1578 ttl=64 [ 2819.045374] ca8210 spi0.0: retried spi write
time=1082.084 ms

Test: Ci40 A and B ping simultaneously to each other (Channel: 25, PAN: 0xdcba)
Ci40 A - root@OpenWrt:/# ping6 -I lowpan0 2001:1418:0100::10
Ci40 B - root@OpenWrt:/# ping6 -I lowpan0 2001:1418:0100::1

[nikhil-zinjurde-imgtec]

Just to state clearly, the driver died after getting these logs, had to reboot the board to get 6lowpan working again. Managed to reproduce on 3 rev7 boards.

Build used (includes Cascoda driver v1.3.0): http://jenkins.creatordev.io/job/CreatorDev/job/openwrt/job/ci40/293/artifact/bin/pistachio/

Package: kmod-ca8210
Version: 4.4.14+1.3.0-1
Depends: kernel (= 4.4.14-1-1f9a3bf3251a14e41210cbea7e1f5452), kmod-mac802154, kmod-ieee802154_6lowpan, kmod-nhc_udp, kmod-nhc_fragment, kmod-nhc_dest, kmod-nhc_hop, kmod-nhc_mobility, kmod-nhc_routing, kmod-nhc_ipv6
Status: install user installed
Architecture: pistachio
Installed-Time: 1488820863

[abhijit-mahajani-imgtec]

blocked on Cascoda/ca8210-linux#4

[nikhil-zinjurde-imgtec]

I left a board overnight after a fresh restart, running ping test first thing after 15 hours resulted in failure with these logs

root@OpenWrt:/# ping6 -I lowpan0 2001:1418:0100::10
PING 2001:1418:0100::10 (2001:1418:100::10): 56 [79545.778078] ca8210 spi0.0: Link transmission unsuccessful, status = 241
data bytes
[79545.786896] ca8210 spi0.0: Waiting for transaction overflow to stabilise...
[79547.805063] ca8210 spi0.0: Resetting MAC...
[79547.811038] ca8210 spi0.0: ca8210 was busy during attempted write
[79547.818007] ca8210 spi0.0: retried spi write
[79547.823336] ca8210 spi0.0: Link transmission unsuccessful, status = 241
[79547.830790] ca8210 spi0.0: Waiting for transaction overflow to stabilise...
[79548.805153] ca8210 spi0.0: Synchronous confirm timeout
[79548.810943] ca8210 spi0.0: cascoda_api_downstream failed
[79549.845067] ca8210 spi0.0: Resetting MAC...
[79549.851018] ca8210 spi0.0: ca8210 was busy during attempted write
[79549.857979] ca8210 spi0.0: retried spi write
[79549.863801] ca8210 spi0.0: ca8210 was busy during attempted write
[79549.870671] ca8210 spi0.0: retried spi write
[79549.876517] ca8210 spi0.0: ca8210 was busy during attempted write
[79549.883320] ca8210 spi0.0: retried spi write
[79549.889241] ca8210 spi0.0: ca8210 was busy during attempted write
[79549.896138] ca8210 spi0.0: retried spi write
[79549.903083] ca8210 spi0.0: ca8210 was busy during attempted write
[79549.910017] ca8210 spi0.0: retried spi write
[79549.915898] ca8210 spi0.0: ca8210 was busy during attempted write
[79549.922861] ca8210 spi0.0: retried spi write