Si446x Driver failure, invalid sync event in rx_on state #61
Description
Test is running continuous network send/receive operations. Only Basestation (dvt1) and one prototype (TIB4) are running. FSM fails when it tries EV_INVALID_SYNC(4) event while in ST_RX_ON(6) state.
Here's the exception:
Breakpoint 1, PanicP__Panic__panic (pcode=0x1c, where=0x51, arg0=arg0@entry=0x4, arg1=arg1@entry=0x6, arg2=arg2@entry=0x0, arg3=arg3@entry=0x0) at /home/vagrant/data/tag_integration/mm/tos/system/panic/PanicP.nc:755
755 nop(); /* BRK */
=> 0x000001f0 <PanicP__Panic__panic+0>: 00 bf nop
(gdb)
*** Panic: 28(d), w: 81(d), a: 0004 0006 0000 0000
Here's the backtrace:
bt
#0 PanicP__Panic__panic (pcode=0x1c, where=0x51, arg0=arg0@entry=0x4, arg1=arg1@entry=0x6, arg2=arg2@entry=0x0, arg3=arg3@entry=0x0) at /home/vagrant/data/tag_integration/mm/tos/system/panic/PanicP.nc:755
#1 0x000026f0 in Si446xDriverLayerP__Panic__panic (pcode=pcode@entry=0x1c, where=where@entry=0x51, arg0=arg0@entry=0x4, arg1=arg1@entry=0x6, arg2=arg2@entry=0x0, arg3=arg3@entry=0x0) at /home/vagrant/data/tag_integration/prod/tos/interfaces/Panic.nc:101
#2 0x000028e2 in Si446xDriverLayerP__fsm_select_transition (ev=ev@entry=Si446xDriverLayerP__E_INVALID_SYNC, st=<optimized out>) at /home/vagrant/data/tag_integration/mm/tos/chips/si446x/Si446xDriverLayerP.nc:273
#3 0x0000ece0 in Si446xDriverLayerP__fsm_change_state (ev=Si446xDriverLayerP__E_INVALID_SYNC) at /home/vagrant/data/tag_integration/mm/tos/chips/si446x/Si446xDriverLayerP.nc:397
#4 0x0000eece in Si446xDriverLayerP__process_interrupt () at /home/vagrant/data/tag_integration/mm/tos/chips/si446x/Si446xDriverLayerP.nc:1458
#5 0x0000eefa in Si446xDriverLayerP__Tasklet__run () at /home/vagrant/data/tag_integration/mm/tos/chips/si446x/Si446xDriverLayerP.nc:1494
#6 0x0000ef32 in TaskletC__0__Tasklet__run () at /home/vagrant/data/tag_integration/prod/tos/lib/rfxlink/util/Tasklet.nc:48
#7 0x0000ef42 in TaskletC__0__doit () at /home/vagrant/data/tag_integration/prod/tos/lib/rfxlink/util/TaskletC.nc:82
#8 0x0000ef9a in TaskletC__0__Tasklet__schedule () at /home/vagrant/data/tag_integration/prod/tos/lib/rfxlink/util/TaskletC.nc:129
#9 0x0000f0ca in Si446xDriverLayerP__Tasklet__schedule () at /home/vagrant/data/tag_integration/prod/tos/lib/rfxlink/util/Tasklet.nc:59
#10 0x0000f2a4 in Si446xDriverLayerP__fsm_int_queue (ev=ev@entry=Si446xDriverLayerP__E_CONFIG_DONE) at /home/vagrant/data/tag_integration/mm/tos/chips/si446x/Si446xDriverLayerP.nc:304
#11 0x0000f2ba in Si446xDriverLayerP__Si446xCmd__interrupt () at /home/vagrant/data/tag_integration/mm/tos/chips/si446x/Si446xDriverLayerP.nc:1302
#12 0x0000f2c6 in Si446xCmdP__Si446xCmd__interrupt () at /home/vagrant/data/tag_integration/mm/tos/chips/si446x/Si446xCmd.nc:164
#13 0x0000f2f4 in Si446xCmdP__HW__si446x_interrupt () at /home/vagrant/data/tag_integration/mm/tos/chips/si446x/Si446xCmdP.nc:923
#14 0x0000f2fe in Si446xPinsP__HW__si446x_interrupt () at /home/vagrant/data/tag_integration/mm/tos/chips/si446x/Si446xInterface.nc:164
#15 0x0000f306 in Si446xPinsP__RadioNIRQ__fired () at /home/vagrant/data/tag_integration/mm/tos/platforms/mm6a/hardware/si446x/Si446xPinsP.nc:63
#16 0x0000f312 in HplMsp432PortIntP__Int__fired (arg_0x7ff1617cc770=<optimized out>) at /home/vagrant/data/tag_integration/prod/tos/chips/msp432/msp432p401/pins/HplMsp432PortInt.nc:68
#17 0x0000f346 in HplMsp432PortIntP__port_handler (port_id=port_id@entry=0x60, n=<optimized out>) at /home/vagrant/data/tag_integration/prod/tos/chips/msp432/msp432p401/pins/HplMsp432PortIntP.nc:92
#18 0x0001223a in PORT6_Handler () at /home/vagrant/data/tag_integration/prod/tos/chips/msp432/msp432p401/pins/HplMsp432PortIntP.nc:190
#19 <signal handler called>
0xfffffff9: Cannot access memory at address 0xfffffff8
#20 __nesc_disable_interrupt () at /home/vagrant/data/tag_integration/prod/tos/chips/cortex/cortexm_nesc.h:127
#21 McuSleepC__McuSleep__sleep () at /home/vagrant/data/tag_integration/prod/tos/chips/msp432/McuSleepC.nc:53
#22 0x0000b28a in SchedulerBasicP__McuSleep__sleep () at /home/vagrant/data/tag_integration/prod/tos/interfaces/McuSleep.nc:79
#23 0x000120c4 in SchedulerBasicP__Scheduler__taskLoop () at /home/vagrant/data/tag_integration/prod/tos/system/SchedulerBasicP.nc:160
#24 0x00012102 in RealMainP__Scheduler__taskLoop () at ```
/home/vagrant/data/tag_integration/prod/tos/interfaces/Scheduler.nc:72
#25 0x0001214c in main () at /home/vagrant/data/tag_integration/prod/tos/system/RealMainP.nc:107
Here are the last 100 entries in the state machine trace buffer:
(gdb) radiofsm -100
55 54 120
t 55: time:0x9a3fbf11(0x0 ) E_INVALID_SYNC S_RX_ON A_BREAK S_SDN
t 56: time:0x9a066328(0x86e ) E_TRANSMIT S_RX_ON A_TX_START S_TX_ACTIVE
t 57: time:0x9a066e74(0x14 ) E_TX_THRESH S_TX_ACTIVE A_TX_FILL_FF S_TX_ACTIVE
t 58: time:0x9a06fdd4(0x5d0 ) E_PACKET_SENT S_TX_ACTIVE A_TX_CMP S_RX_ON
t 59: time:0x9a08754b(0x74 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 60: time:0x9a088d30(0x11 ) E_SYNC_DETECT S_RX_ACTIVE A_NOP S_RX_ACTIVE
t 61: time:0x9a08de34(0x438 ) E_RX_THRESH S_RX_ACTIVE A_RX_FETCH_FF S_RX_ACTIVE
t 62: time:0x9a08f53a(0x961 ) E_PACKET_RX S_RX_ACTIVE A_RX_CMP S_RX_ON
t 63: time:0x9a09c782(0x766 ) E_TRANSMIT S_RX_ON A_TX_START S_TX_ACTIVE
t 64: time:0x9a0a0247(0x14 ) E_TX_THRESH S_TX_ACTIVE A_TX_FILL_FF S_TX_ACTIVE
t 65: time:0x9a0a64ec(0x5d0 ) E_PACKET_SENT S_TX_ACTIVE A_TX_CMP S_RX_ON
t 66: time:0x9a0bea97(0x74 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 67: time:0x9a0c02e4(0x11 ) E_SYNC_DETECT S_RX_ACTIVE A_NOP S_RX_ACTIVE
t 68: time:0x9a0c53e8(0x438 ) E_RX_THRESH S_RX_ACTIVE A_RX_FETCH_FF S_RX_ACTIVE
t 69: time:0x9a0c7b20(0x9c5 ) E_PACKET_RX S_RX_ACTIVE A_RX_CMP S_RX_ON
t 70: time:0x9a0d4f6a(0x86f ) E_TRANSMIT S_RX_ON A_TX_START S_TX_ACTIVE
t 71: time:0x9a0d5ab6(0x14 ) E_TX_THRESH S_TX_ACTIVE A_TX_FILL_FF S_TX_ACTIVE
t 72: time:0x9a0dea16(0x5d0 ) E_PACKET_SENT S_TX_ACTIVE A_TX_CMP S_RX_ON
t 73: time:0x9a0f56b9(0x73 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 74: time:0x9a0f6f03(0x11 ) E_SYNC_DETECT S_RX_ACTIVE A_NOP S_RX_ACTIVE
t 75: time:0x9a0fc007(0x438 ) E_RX_THRESH S_RX_ACTIVE A_RX_FETCH_FF S_RX_ACTIVE
t 76: time:0x9a0fd70c(0x961 ) E_PACKET_RX S_RX_ACTIVE A_RX_CMP S_RX_ON
t 77: time:0x9a10abe6(0x766 ) E_TRANSMIT S_RX_ON A_TX_START S_TX_ACTIVE
t 78: time:0x9a10e6ab(0x14 ) E_TX_THRESH S_TX_ACTIVE A_TX_FILL_FF S_TX_ACTIVE
t 79: time:0x9a114950(0x5d0 ) E_PACKET_SENT S_TX_ACTIVE A_TX_CMP S_RX_ON
t 80: time:0x9a12abd9(0x74 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 81: time:0x9a12c3bc(0x11 ) E_SYNC_DETECT S_RX_ACTIVE A_NOP S_RX_ACTIVE
t 82: time:0x9a1314c0(0x437 ) E_RX_THRESH S_RX_ACTIVE A_RX_FETCH_FF S_RX_ACTIVE
t 83: time:0x9a133bf7(0x9c5 ) E_PACKET_RX S_RX_ACTIVE A_RX_CMP S_RX_ON
t 84: time:0x9a14105b(0xa1e ) E_TRANSMIT S_RX_ON A_TX_START S_TX_ACTIVE
t 85: time:0x9a141dd3(0x14 ) E_TX_THRESH S_TX_ACTIVE A_TX_FILL_FF S_TX_ACTIVE
t 86: time:0x9a14ac2d(0x5d0 ) E_PACKET_SENT S_TX_ACTIVE A_TX_CMP S_RX_ON
t 87: time:0x9a1620e3(0x73 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 88: time:0x9a16392f(0x12 ) E_SYNC_DETECT S_RX_ACTIVE A_NOP S_RX_ACTIVE
t 89: time:0x9a168a33(0x438 ) E_RX_THRESH S_RX_ACTIVE A_RX_FETCH_FF S_RX_ACTIVE
t 90: time:0x9a16a138(0x960 ) E_PACKET_RX S_RX_ACTIVE A_RX_CMP S_RX_ON
t 91: time:0x9a1774a7(0x767 ) E_TRANSMIT S_RX_ON A_TX_START S_TX_ACTIVE
t 92: time:0x9a17af6d(0x14 ) E_TX_THRESH S_TX_ACTIVE A_TX_FILL_FF S_TX_ACTIVE
t 93: time:0x9a181211(0x5d0 ) E_PACKET_SENT S_TX_ACTIVE A_TX_CMP S_RX_ON
t 94: time:0x9a1998d2(0x73 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 95: time:0x9a19b11c(0x11 ) E_SYNC_DETECT S_RX_ACTIVE A_NOP S_RX_ACTIVE
t 96: time:0x9a1a0220(0x437 ) E_RX_THRESH S_RX_ACTIVE A_RX_FETCH_FF S_RX_ACTIVE
t 97: time:0x9a1a2958(0x9c4 ) E_PACKET_RX S_RX_ACTIVE A_RX_CMP S_RX_ON
t 98: time:0x9a1afc8d(0x86f ) E_TRANSMIT S_RX_ON A_TX_START S_TX_ACTIVE
t 99: time:0x9a1b07d9(0x14 ) E_TX_THRESH S_TX_ACTIVE A_TX_FILL_FF S_TX_ACTIVE
t 100: time:0x9a1b9738(0x5d0 ) E_PACKET_SENT S_TX_ACTIVE A_TX_CMP S_RX_ON
t 101: time:0x9a1d0259(0x74 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 102: time:0x9a1d1aa1(0x12 ) E_SYNC_DETECT S_RX_ACTIVE A_NOP S_RX_ACTIVE
t 103: time:0x9a1d6ba7(0x438 ) E_RX_THRESH S_RX_ACTIVE A_RX_FETCH_FF S_RX_ACTIVE
t 104: time:0x9a1d82ac(0x961 ) E_PACKET_RX S_RX_ACTIVE A_RX_CMP S_RX_ON
t 105: time:0x9a1e5513(0x766 ) E_TRANSMIT S_RX_ON A_TX_START S_TX_ACTIVE
t 106: time:0x9a1e8fd8(0x14 ) E_TX_THRESH S_TX_ACTIVE A_TX_FILL_FF S_TX_ACTIVE
t 107: time:0x9a1ef27d(0x5d0 ) E_PACKET_SENT S_TX_ACTIVE A_TX_CMP S_RX_ON
t 108: time:0x9a2076b7(0x74 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 109: time:0x9a208f04(0x12 ) E_SYNC_DETECT S_RX_ACTIVE A_NOP S_RX_ACTIVE
t 110: time:0x9a20e007(0x438 ) E_RX_THRESH S_RX_ACTIVE A_RX_FETCH_FF S_RX_ACTIVE
t 111: time:0x9a21073f(0x9c5 ) E_PACKET_RX S_RX_ACTIVE A_RX_CMP S_RX_ON
t 112: time:0x9a21dcf6(0x86f ) E_TRANSMIT S_RX_ON A_TX_START S_TX_ACTIVE
t 113: time:0x9a21e843(0x14 ) E_TX_THRESH S_TX_ACTIVE A_TX_FILL_FF S_TX_ACTIVE
t 114: time:0x9a2277a2(0x5d0 ) E_PACKET_SENT S_TX_ACTIVE A_TX_CMP S_RX_ON
t 115: time:0x9a2436a0(0x73 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 116: time:0x9a244e87(0x11 ) E_SYNC_DETECT S_RX_ACTIVE A_NOP S_RX_ACTIVE
t 117: time:0x9a249f88(0x438 ) E_RX_THRESH S_RX_ACTIVE A_RX_FETCH_FF S_RX_ACTIVE
t 118: time:0x9a24b690(0x960 ) E_PACKET_RX S_RX_ACTIVE A_RX_CMP S_RX_ON
t 119: time:0x9a258864(0x766 ) E_TRANSMIT S_RX_ON A_TX_START S_TX_ACTIVE
t 0: time:0x9a25c329(0x14 ) E_TX_THRESH S_TX_ACTIVE A_TX_FILL_FF S_TX_ACTIVE
t 1: time:0x9a2625ce(0x5cf ) E_PACKET_SENT S_TX_ACTIVE A_TX_CMP S_RX_ON
t 2: time:0x9a27ad8d(0x73 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 3: time:0x9a27c5da(0x11 ) E_SYNC_DETECT S_RX_ACTIVE A_NOP S_RX_ACTIVE
t 4: time:0x9a2816df(0x438 ) E_RX_THRESH S_RX_ACTIVE A_RX_FETCH_FF S_RX_ACTIVE
t 5: time:0x9a283e17(0x9c5 ) E_PACKET_RX S_RX_ACTIVE A_RX_CMP S_RX_ON
t 6: time:0x9a29104a(0x86f ) E_TRANSMIT S_RX_ON A_TX_START S_TX_ACTIVE
t 7: time:0x9a291b96(0x14 ) E_TX_THRESH S_TX_ACTIVE A_TX_FILL_FF S_TX_ACTIVE
t 8: time:0x9a29aaf5(0x5d0 ) E_PACKET_SENT S_TX_ACTIVE A_TX_CMP S_RX_ON
t 9: time:0x9a2b23e2(0x73 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 10: time:0x9a2b38f2(0x11 ) E_SYNC_DETECT S_RX_ACTIVE A_NOP S_RX_ACTIVE
t 11: time:0x9a2b89f5(0x438 ) E_RX_THRESH S_RX_ACTIVE A_RX_FETCH_FF S_RX_ACTIVE
t 12: time:0x9a2ba0fb(0x960 ) E_PACKET_RX S_RX_ACTIVE A_RX_CMP S_RX_ON
t 13: time:0x9a2c74a9(0x766 ) E_TRANSMIT S_RX_ON A_TX_START S_TX_ACTIVE
t 14: time:0x9a2caf6e(0x14 ) E_TX_THRESH S_TX_ACTIVE A_TX_FILL_FF S_TX_ACTIVE
t 15: time:0x9a2d1213(0x5d0 ) E_PACKET_SENT S_TX_ACTIVE A_TX_CMP S_RX_ON
t 16: time:0x9a2e908a(0x73 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 17: time:0x9a2ea8d4(0x11 ) E_SYNC_DETECT S_RX_ACTIVE A_NOP S_RX_ACTIVE
t 18: time:0x9a2ef9da(0x437 ) E_RX_THRESH S_RX_ACTIVE A_RX_FETCH_FF S_RX_ACTIVE
t 19: time:0x9a2f2111(0x9c5 ) E_PACKET_RX S_RX_ACTIVE A_RX_CMP S_RX_ON
t 20: time:0x9a2ff4a8(0x86f ) E_TRANSMIT S_RX_ON A_TX_START S_TX_ACTIVE
t 21: time:0x9a2ffff4(0x14 ) E_TX_THRESH S_TX_ACTIVE A_TX_FILL_FF S_TX_ACTIVE
t 22: time:0x9a308f53(0x5d0 ) E_PACKET_SENT S_TX_ACTIVE A_TX_CMP S_RX_ON
t 23: time:0x9a31fad8(0x73 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 24: time:0x9a321324(0x12 ) E_SYNC_DETECT S_RX_ACTIVE A_NOP S_RX_ACTIVE
t 25: time:0x9a326426(0x438 ) E_RX_THRESH S_RX_ACTIVE A_RX_FETCH_FF S_RX_ACTIVE
t 26: time:0x9a327b2d(0x961 ) E_PACKET_RX S_RX_ACTIVE A_RX_CMP S_RX_ON
t 27: time:0x9a334d2f(0x7f6 ) E_TRANSMIT S_RX_ON A_TX_START S_TX_ACTIVE
t 28: time:0x9a338829(0x14 ) E_TX_THRESH S_TX_ACTIVE A_TX_FILL_FF S_TX_ACTIVE
t 29: time:0x9a33eace(0x5cf ) E_PACKET_SENT S_TX_ACTIVE A_TX_CMP S_RX_ON
t 30: time:0x9a35711b(0x73 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 31: time:0x9a358965(0x11 ) E_SYNC_DETECT S_RX_ACTIVE A_NOP S_RX_ACTIVE
t 32: time:0x9a35da6a(0x438 ) E_RX_THRESH S_RX_ACTIVE A_RX_FETCH_FF S_RX_ACTIVE
t 33: time:0x9a3601a2(0x9c5 ) E_PACKET_RX S_RX_ACTIVE A_RX_CMP S_RX_ON
t 34: time:0x9a36d513(0x86e ) E_TRANSMIT S_RX_ON A_TX_START S_TX_ACTIVE
t 35: time:0x9a36e05f(0x14 ) E_TX_THRESH S_TX_ACTIVE A_TX_FILL_FF S_TX_ACTIVE
t 36: time:0x9a376fbf(0x5d0 ) E_PACKET_SENT S_TX_ACTIVE A_TX_CMP S_RX_ON
t 37: time:0x9a38d797(0x73 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 38: time:0x9a38efe4(0x11 ) E_SYNC_DETECT S_RX_ACTIVE A_NOP S_RX_ACTIVE
t 39: time:0x9a3940e9(0x438 ) E_RX_THRESH S_RX_ACTIVE A_RX_FETCH_FF S_RX_ACTIVE
t 40: time:0x9a3957ef(0x960 ) E_PACKET_RX S_RX_ACTIVE A_RX_CMP S_RX_ON
t 41: time:0x9a3a29a9(0x766 ) E_TRANSMIT S_RX_ON A_TX_START S_TX_ACTIVE
t 42: time:0x9a3a646e(0x14 ) E_TX_THRESH S_TX_ACTIVE A_TX_FILL_FF S_TX_ACTIVE
t 43: time:0x9a3ac713(0x5d0 ) E_PACKET_SENT S_TX_ACTIVE A_TX_CMP S_RX_ON
t 44: time:0x9a3c4c86(0x73 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 45: time:0x9a3c64d0(0x11 ) E_SYNC_DETECT S_RX_ACTIVE A_NOP S_RX_ACTIVE
t 46: time:0x9a3cb5d4(0x438 ) E_RX_THRESH S_RX_ACTIVE A_RX_FETCH_FF S_RX_ACTIVE
t 47: time:0x9a3cdd0c(0x9c4 ) E_PACKET_RX S_RX_ACTIVE A_RX_CMP S_RX_ON
t 48: time:0x9a3db191(0x86f ) E_TRANSMIT S_RX_ON A_TX_START S_TX_ACTIVE
t 49: time:0x9a3dbcde(0x14 ) E_TX_THRESH S_TX_ACTIVE A_TX_FILL_FF S_TX_ACTIVE
t 50: time:0x9a3e4c3d(0x5d0 ) E_PACKET_SENT S_TX_ACTIVE A_TX_CMP S_RX_ON
t 51: time:0x9a3fa25f(0x73 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 52: time:0x9a3fac21(0x64d ) E_INVALID_SYNC S_RX_ACTIVE A_CLEAR_SYNC S_RX_ON
t 53: time:0x9a3fb54a(0x73 ) E_PREAMBLE_DETECT S_RX_ON A_RX_START S_RX_ACTIVE
t 54: time:0x9a3fb661(0x5d4 ) E_INVALID_SYNC S_RX_ACTIVE A_CLEAR_SYNC S_RX_ON
Here are the Si446x driver statistics counters:
(gdb) p Si446xDriverLayerP__global_ioc
$4 = {pRxMsg = 0x20002908 <Si446xDriverLayerP__rxMsgBuffer>, pTxMsg = 0x0, rc_readys = 0xb99b, tx_packets = 0xb99a, tx_reports = 0xb99a, rx_packets = 0xb9b4, rx_reports = 0xb99a, tx_timeouts = 0x0, tx_underruns = 0x0, rx_bad_crcs = 0x1, rx_timeouts = 0x1, rx_inv_syncs = 0x19, rx_errors = 0x0, rx_overruns = 0x0, rx_active_overruns = 0x0, rx_crc_overruns = 0x0, rx_crc_packet_rx = 0x0, nops = 0xb99b, unshuts = 0x1, channel = 0x0, tx_power = 0x0, tx_ff_index = 0x20, rx_ff_index = 0x0, rc_signal = 0x0, tx_signal = 0x0, tx_error = SUCCESS}