the question of twr_node_nranges_tdma reboot

[yanxuex]

Hi
When I run twr_node_nranges_tdma APP for a long time, I find that it restarts every time when the utime upto 0xFFFFFFFF.

log:
{"utime": 4288931898,"wcs": [275343380480,275343380480,275343380480],"skew": 0}
{"utime": 4290007361,"wcs": [344062857216,344062857216,344062857216],"skew": 0}
{"utime": 4291082816,"wcs": [412782333952,412782333952,412782333952],"skew": 0}
{"utime": 4292158260,"wcs": [481501810688,481501810688,481501810688],"skew": 0}
{"utime": 4293233731,"wcs": [550221287424,550221287424,550221287424],"skew": 0}
{"utime": 4294309201,"wcs": [618940764160,618940764160,618940764160],"skew": 0}
{"utime": 414252,"wcs": [687660240896,687660240896,687660240896],"skew": 0}
{"utime": 1489700,"wcs": [756379717632,756379717632,756379717632],"skew": 0}
{"utime": 2565154,"wcs": [825099194368,825099194368,825099194368],"skew": 0}
{"utime": 3640608,"wcs": [893818671104,893818671104,893818671104],"skew": 0}
{"utime": 4716062,"wcs": [962538147840,962538147840,962538147840],"skew": 0}
{"utime": 5791516,"wcs": [1031257624576,1031257624576,1031257624576],"skew": 0}
{"utime": 6866982,"wcs": [465473536,465473536,465473536],"skew": 0}
{"utime": 7942418,"wcs": [69184950272,69184950272,69184950272],"skew": 0}
{"utime": 9017872,"wcs": [137904427008,137904427008,137904427008],"skew": 0}
{"utime": 10093325,"wcs": [206623903744,206623903744,206623903744],"skew": 0}
{"utime": 11168780,"wcs": [275343380480,275343380480,275343380480],"skew": 0}
551327 Assert @ 0xc429 - repos/apache-mynewt-core/kernel/os/src/os_sanity.c:180
551327 Unhandled interrupt (2), exception sp 0x200013b0
551327 r0:0x00000000 r1:0x00000000 r2:0x80000000 r3:0xe000ed00
551327 r4:0x00016ccc r5:0x0000c429 r6:0x000000b4 r7:0x00000000
551327 r8:0xffffffff r9:0x0008699e r10:0x00000000 r11:0x00000000
551327 r12:0x00000000 lr:0x0000b973 pc:0x0000b982 psr:0x61000000
551327 ICSR:0x00421802 HFSR:0x00000000 CFSR:0x00000000
551327 BFAR:0xe000ed38 MMFAR:0xe000ed34
{"utime": 252031,"msg": "dw1000_pkg_init"}
{"utime": 260014,"msg": "ccp_pkg_init"}
{"utime": 260950,"msg": "tdma_pkg_init"}
{"utime": 261623,"msg": "rng_pkg_init"}
{"utime": 261965,"msg": "nrng_pkg_init"}
{"utime": 262310,"msg": "ss_nrng_pkg_init"}
{"utime": 262655,"exec": "apps/twr_node_nranges_tdma/src/main.c"}
{"utime": 262655,"msg": "device_id = 0xDECA0130"}
{"utime": 262655,"msg": "PANID = 0xDECA"}
{"utime": 262655,"msg": "DeviceID = 0x1010"}
{"utime": 262655,"msg": "partID = 0xC41040AF"}
{"utime": 262655,"msg": "lotID = 0x13A6102"}
{"utime": 262655,"msg": "xtal_trim = 0x17"}
{"utime": 262655,"msg": "frame_duration = 195 usec"}
{"utime": 262655,"msg": "SHR_duration = 139 usec"}
{"utime": 262655,"msg": "holdoff = 821 usec"}
{"utime": 2420672,"wcs": [137920926720,137920926720,137920926720],"skew": 0}
{"utime": 3496932,"wcs": [206640403456,206640403456,206640403456],"skew": 0}
{"utime": 4572426,"wcs": [275359880192,275359880192,275359880192],"skew": 0}
{"utime": 5647870,"wcs": [344079356928,344079356928,344079356928],"skew": 0}
{"utime": 6723333,"wcs": [412798833664,412798833664,412798833664],"skew": 0}
{"utime": 7798788,"wcs": [481518310400,481518310400,481518310400],"skew": 0}
{"utime": 8874239,"wcs": [550237787136,550237787136,550237787136],"skew": 0}

[pkettle]

Hi Yan,
I suspect this is related to hal_timer_start_at() call in ccp_master_timer_cv_cb(). The resulting timer delay is negative and exceeds 10s, the timeout set in the os_sanity, see syscfg.yml TDMA_SANITY_INTERVAL. I will propose a fix for the next release.

Thanks for catching this. Regards Paul.

[yanxuex]

Hi pkettle
thank for your timely answer。

I opened the log of tx_complete_cb()and tdma_superframe_event_cb() in the tdma.c file, and change TDMA_SANITY_INTERVAL: 20 in syscfg.yml，the log when the problem occurs is as follows。
I think hal_timer_start_at() works well，tdma_task() works not well . Because when dw1000_ccp_send() finish tdma:tx_complete_cb() has sent tdma->event_cb.c_ev, but tdma_superframe_event_cb() not receive this event. sanity_feeding_cb not runing, so reboot after 20s.

I don't know why?

[2019/3/8 16:54:31] {"utime": 4291079282,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:31] {"utime": 4291079710,"msg": "tdma_superframe_event_cb"}
[2019/3/8 16:54:31] {"utime": 4291084105,"wcs": [412782451200,412782451200,412782451200],"skew": 0}
[2019/3/8 16:54:32] {"utime": 4292154737,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:32] {"utime": 4292155166,"msg": "tdma_superframe_event_cb"}
[2019/3/8 16:54:32] {"utime": 4292159568,"wcs": [481501927936,481501927936,481501927936],"skew": 0}
[2019/3/8 16:54:34] {"utime": 4293230191,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:34] {"utime": 4293230611,"msg": "tdma_superframe_event_cb"}
[2019/3/8 16:54:34] {"utime": 4293235030,"wcs": [550221404672,550221404672,550221404672],"skew": 0}
[2019/3/8 16:54:35] {"utime": 4294305646,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:35] {"utime": 4294306065,"msg": "tdma_superframe_event_cb"}
[2019/3/8 16:54:35] {"utime": 4294310489,"wcs": [618940881408,618940881408,618940881408],"skew": 0}
[2019/3/8 16:54:36] {"utime": 413804,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:36] {"utime": 415071,"wcs": [687660358144,687660358144,687660358144],"skew": 0}
[2019/3/8 16:54:37] {"utime": 1489259,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:37] {"utime": 1490533,"wcs": [756379834880,756379834880,756379834880],"skew": 0}
[2019/3/8 16:54:38] {"utime": 2564713,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:38] {"utime": 2565987,"wcs": [825099311616,825099311616,825099311616],"skew": 0}
[2019/3/8 16:54:39] {"utime": 3640167,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:39] {"utime": 3641451,"wcs": [893818788352,893818788352,893818788352],"skew": 0}
[2019/3/8 16:54:40] {"utime": 4715621,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:40] {"utime": 4716896,"wcs": [962538265088,962538265088,962538265088],"skew": 0}
[2019/3/8 16:54:41] {"utime": 5791076,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:41] {"utime": 5792350,"wcs": [1031257741824,1031257741824,1031257741824],"skew": 0}
[2019/3/8 16:54:42] {"utime": 6866530,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:42] {"utime": 6867825,"wcs": [465590784,465590784,465590784],"skew": 0}
[2019/3/8 16:54:43] {"utime": 7941984,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:43] {"utime": 7943251,"wcs": [69185067520,69185067520,69185067520],"skew": 0}
[2019/3/8 16:54:44] {"utime": 9017438,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:44] {"utime": 9018705,"wcs": [137904544256,137904544256,137904544256],"skew": 0}
[2019/3/8 16:54:45] {"utime": 10092892,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:45] {"utime": 10094183,"wcs": [206624020992,206624020992,206624020992],"skew": 0}
[2019/3/8 16:54:46] {"utime": 11168346,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:46] {"utime": 11169628,"wcs": [275343497728,275343497728,275343497728],"skew": 0}
[2019/3/8 16:54:48] {"utime": 12243800,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:48] {"utime": 12245081,"wcs": [344062974464,344062974464,344062974464],"skew": 0}
[2019/3/8 16:54:49] {"utime": 13319254,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:49] {"utime": 13320545,"wcs": [412782451200,412782451200,412782451200],"skew": 0}
[2019/3/8 16:54:50] {"utime": 14394709,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:50] {"utime": 14395990,"wcs": [481501927936,481501927936,481501927936],"skew": 0}
[2019/3/8 16:54:51] {"utime": 15470163,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:51] {"utime": 15471451,"wcs": [550221404672,550221404672,550221404672],"skew": 0}
[2019/3/8 16:54:52] {"utime": 16545617,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:52] {"utime": 16546915,"wcs": [618940881408,618940881408,618940881408],"skew": 0}
[2019/3/8 16:54:53] {"utime": 17621071,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:53] {"utime": 17622359,"wcs": [687660358144,687660358144,687660358144],"skew": 0}
[2019/3/8 16:54:54] {"utime": 18696525,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:54] {"utime": 18697813,"wcs": [756379834880,756379834880,756379834880],"skew": 0}
[2019/3/8 16:54:55] {"utime": 19771979,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:55] {"utime": 19773277,"wcs": [825099311616,825099311616,825099311616],"skew": 0}
[2019/3/8 16:54:56] {"utime": 20847433,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:56] {"utime": 20848721,"wcs": [893818788352,893818788352,893818788352],"skew": 0}
[2019/3/8 16:54:57] {"utime": 21922887,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:57] {"utime": 21924175,"wcs": [962538265088,962538265088,962538265088],"skew": 0}
[2019/3/8 16:54:58] {"utime": 22998340,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:58] {"utime": 22999638,"wcs": [1031257741824,1031257741824,1031257741824],"skew": 0}
[2019/3/8 16:54:59] {"utime": 24073794,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:54:59] {"utime": 24075094,"wcs": [465590784,465590784,465590784],"skew": 0}
[2019/3/8 16:55:00] {"utime": 25149248,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:55:00] {"utime": 25150530,"wcs": [69185067520,69185067520,69185067520],"skew": 0}
[2019/3/8 16:55:01] {"utime": 26224702,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:55:01] {"utime": 26225993,"wcs": [137904544256,137904544256,137904544256],"skew": 0}
[2019/3/8 16:55:02] 553248 Assert @ 0xc429 - repos/apache-mynewt-core/kernel/os/src/os_sanity.c:180
[2019/3/8 16:55:02] 553248 Unhandled interrupt (2), exception sp 0x200013b0
[2019/3/8 16:55:02] 553248 r0:0x00000000 r1:0x00000000 r2:0x80000000 r3:0xe000ed00
[2019/3/8 16:55:02] 553248 r4:0x00016cec r5:0x0000c429 r6:0x000000b4 r7:0x00000000
[2019/3/8 16:55:02] 553248 r8:0xffffffff r9:0x0008711f r10:0x00000000 r11:0x00000000
[2019/3/8 16:55:02] 553248 r12:0x00000000 lr:0x0000b973 pc:0x0000b982 psr:0x61000000
[2019/3/8 16:55:02] 553248 ICSR:0x00421802 HFSR:0x00000000 CFSR:0x00000000
[2019/3/8 16:55:02] 553248 BFAR:0xe000ed38 MMFAR:0xe000ed34
[2019/3/8 16:55:03] {"utime": 252029,"msg": "dw1000_pkg_init"}
[2019/3/8 16:55:03] {"utime": 260013,"msg": "ccp_pkg_init"}
[2019/3/8 16:55:03] {"utime": 260949,"msg": "tdma_pkg_init"}
[2019/3/8 16:55:03] {"utime": 261623,"msg": "rng_pkg_init"}
[2019/3/8 16:55:03] {"utime": 261964,"msg": "nrng_pkg_init"}
[2019/3/8 16:55:03] {"utime": 262309,"msg": "ss_nrng_pkg_init"}
[2019/3/8 16:55:03] {"utime": 262654,"exec": "apps/twr_node_nranges_tdma/src/main.c"}
[2019/3/8 16:55:03] {"utime": 262654,"msg": "device_id = 0xDECA0130"}
[2019/3/8 16:55:03] {"utime": 262654,"msg": "PANID = 0xDECA"}
[2019/3/8 16:55:03] {"utime": 262654,"msg": "DeviceID = 0x1010"}
[2019/3/8 16:55:03] {"utime": 262654,"msg": "partID = 0xC41040AF"}
[2019/3/8 16:55:03] {"utime": 262654,"msg": "lotID = 0x13A6102"}
[2019/3/8 16:55:03] {"utime": 262654,"msg": "xtal_trim = 0x17"}
[2019/3/8 16:55:03] {"utime": 262654,"msg": "frame_duration = 195 usec"}
[2019/3/8 16:55:03] {"utime": 262654,"msg": "SHR_duration = 139 usec"}
[2019/3/8 16:55:03] {"utime": 262654,"msg": "holdoff = 821 usec"}
[2019/3/8 16:55:04] {"utime": 1342080,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:55:04] {"utime": 1342458,"msg": "tdma_superframe_event_cb"}
[2019/3/8 16:55:05] {"utime": 2417535,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:55:05] {"utime": 2417914,"msg": "tdma_superframe_event_cb"}
[2019/3/8 16:55:05] {"utime": 2421433,"wcs": [137921014784,137921014784,137921014784],"skew": 0}
[2019/3/8 16:55:06] {"utime": 3492989,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:55:06] {"utime": 3493368,"msg": "tdma_superframe_event_cb"}
[2019/3/8 16:55:06] {"utime": 3497693,"wcs": [206640491520,206640491520,206640491520],"skew": 0}
[2019/3/8 16:55:07] {"utime": 4568443,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:55:07] {"utime": 4568822,"msg": "tdma_superframe_event_cb"}
[2019/3/8 16:55:07] {"utime": 4573187,"wcs": [275359968256,275359968256,275359968256],"skew": 0}
[2019/3/8 16:55:08] {"utime": 5643897,"msg": "tdma:tx_complete_cb"}
[2019/3/8 16:55:08] {"utime": 5644276,"msg": "tdma_superframe_event_cb"}
[2019/3/8 16:55:08] {"utime": 5648631,"wcs": [344079444992,344079444992,344079444992],"skew": 0}

[pkettle]

Hi Yanxuex,

It appears that the ccp->sem is blocking. Can you set the TDMA_SANITY_INTERVAL=0 and allow os_timer rollover to occur. On the console type dw1000 dump. This will allow us see what is happening on the DW1000. Can you send the dump?

Regards Paul.

[yanxuex]

Hi Paul
the shell not works well with the default syscfg.yml of twr_node_nranges_tdma app .
can you give me the syscfg.yml file which the shell works well.

thanks.

[ncasaril]

Just a note that I'm able to reproduce the issue using Timer 0 at 16MHz after a couple of hours. I don't think the dw1000 dump with be very informative at this stage. Thanks though @yanxuex.