Skip to content

Ublox: Ublox Odin W2 WIFI asserts during firmware download #9621

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
JanneKiiskila opened this issue Feb 5, 2019 · 19 comments
Closed

Ublox: Ublox Odin W2 WIFI asserts during firmware download #9621

JanneKiiskila opened this issue Feb 5, 2019 · 19 comments
Labels
devices: ublox type: bug

Comments

@JanneKiiskila
Copy link
Contributor

JanneKiiskila commented Feb 5, 2019 •
edited
Loading

Description

Target board: UBLOX_EVK_ODIN_W2
Connectivity: Wi-Fi
Mbed OS version: any 5.10.0 ... 5.10.4, 5.11.0, 5.12.0-RC1 release

Pelion Device Management - firmware download fails with assertion.

Please follow the Pelion Device Management tutorials for repro steps (manifest, update campaign etc.).

09:09:10.429 | D1 <<< DutThread: [09:09:08][48363][DBG ][SRCE]: arm_uc_http_socket_private.c:1362: >> arm_uc_http_socket_has_received_frag ..
09:09:10.430 | D1 <<< DutThread: [09:09:08][48364][DBG ][SRCE]: arm_uc_http_socket_private.c:1376:   has received full frag? no 1736 of 2560
09:09:10.430 | D1 <<< DutThread: [09:09:08][48365][DBG ][SRCE]: arm_uc_http_socket_private.c:1617: >> arm_uc_http_socket_callback (12)
09:09:10.430 | D1 <<< DutThread: [09:09:08][48366][DBG ][SRCE]: arm_uc_http_socket_private.c:1817: event: frag more
09:09:10.431 | D1 <<< DutThread: [09:09:08][48367][DBG ][SRCE]: arm_uc_http_socket_private.c:904: >> arm_uc_http_socket_receive [expected-event 0] ..
09:09:10.431 | D1 <<< DutThread: [09:09:08][48368][DBG ][SRCE]: arm_uc_http_socket_private.c:918:   space 824
09:09:10.431 | D1 <<< DutThread: [09:09:08][48369][DBG ][SRCE]: arm_uc_http_socket_private.c:945: recv success: 536 bytes received
09:09:10.432 | D1 <<< DutThread: [09:09:08][48370][DBG ][SRCE]: arm_uc_http_socket_private.c:962: open_request_offset 1174752
09:09:10.526 | D1 <<< DutThread: [09:09:08][48371][DBG ][SRCE]: arm_uc_http_socket_private.c:1362: >> arm_uc_http_socket_has_received_frag ..
09:09:10.527 | D1 <<< DutThread: [09:09:08][48372][DBG ][SRCE]: arm_uc_http_socket_private.c:1376:   has received full frag? no 2272 of 2560
09:09:10.527 | D1 <<< DutThread: [09:09:08][48373][DBG ][SRCE]: arm_uc_http_socket_private.c:1617: >> arm_uc_http_socket_callback (12)
09:09:10.528 | D1 <<< DutThread: [09:09:08][48374][DBG ][SRCE]: arm_uc_http_socket_private.c:1817: event: frag more
09:09:10.528 | D1 <<< DutThread: [09:09:08][48375][DBG ][SRCE]: arm_uc_http_socket_private.c:904: >> arm_uc_http_socket_receive [expected-event 0] ..
09:09:10.528 | D1 <<< DutThread: [09:09:08][48376][DBG ][SRCE]: arm_uc_http_socket_private.c:918:   space 288
09:09:10.528 | D1 <<< DutThread: [09:09:08][48377][DBG ][SRCE]: arm_uc_http_socket_private.c:966: recv: pending: 288
09:09:10.528 | D1 <<< DutThread: [09:09:08][48378][DBG ][SRCE]: arm_uc_http_socket_private.c:1825: event: empty fragment receive
09:09:10.529 | D1 <<< DutThread: [09:09:08][48379][DBG ][SRCE]: arm_uc_http_socket_private.c:1617: >> arm_uc_http_socket_callback (12)
09:09:10.529 | D1 <<< DutThread: [09:09:08][48380][DBG ][SRCE]: arm_uc_http_socket_private.c:1817: event: frag more
09:09:10.529 | D1 <<< DutThread: [09:09:08][48381][DBG ][SRCE]: arm_uc_http_socket_private.c:904: >> arm_uc_http_socket_receive [expected-event 0] ..
09:09:10.529 | D1 <<< DutThread: [09:09:08][48382][DBG ][SRCE]: arm_uc_http_socket_private.c:918:   space 288
09:09:10.529 | D1 <<< DutThread: [09:09:08][48383][DBG ][SRCE]: arm_uc_http_socket_private.c:966: recv: pending: 288
09:09:10.530 | D1 <<< DutThread: [09:09:08][48384][DBG ][SRCE]: arm_uc_http_socket_private.c:1825: event: empty fragment receive
09:09:10.530 | D1 <<< DutThread: [09:09:08][48385][DBG ][SRCE]: arm_uc_http_socket_private.c:1829: event: max empty fragment receives
09:09:11.231 | D1 <<< DutThread: mbed assertation failed: FALSE, file: ./mbed-os/targets/TARGET_STM/TARGET_STM32F4/TARGET_STM32F439xI/TARGET_MODULE_UBLOX_ODIN_W���������h���]t
09:09:11.231 | D1 <<< DutThread: �dt
09:09:11.232 | D1 <<< DutThread: �h�������������� ��� ��� �w�������������P

And some more details were dug out by @TeroJaasko 👍

23:18:40.510 | D1 <<< DutThread: File: ./mbed-os/targets/TARGET_STM/TARGET_STM32F4/TARGET_STM32F439xI/TARGET_MODULE_UBLOX_ODIN_W2/sdk/ublox-odin-w2-drivers/OdinWiFiInterface.cpp+1200

...

(gdb) bt
#0  0x080adc6a in update_present_time (ticker=0x812261c <us_data>) at ./mbed-os/hal/mbed_ticker_api.c:132
#1  0x080ae32a in ticker_read_us (ticker=0x812261c <us_data>) at ./mbed-os/hal/mbed_ticker_api.c:421
#2  0x080ae30a in ticker_read (ticker=0x812261c <us_data>) at ./mbed-os/hal/mbed_ticker_api.c:413
#3  0x080b06e6 in wait_us (us=400000) at ./mbed-os/platform/mbed_wait_api_rtos.cpp:50
#4  0x080b068e in wait_ms (ms=400) at ./mbed-os/platform/mbed_wait_api_rtos.cpp:34
#5  0x080aeb56 in mbed_die () at ./mbed-os/platform/mbed_board.c:47
#6  0x080aeac2 in mbed_assert_internal (expr=0x8123864 "FALSE", file=0x8123548 "./mbed-os/targets/TARGET_STM/TARGET_STM32F4/TARGET_STM32F439xI/TARGET_MODULE_UBLOX_ODIN_W2/sdk/ublox-odin-w2-drivers/OdinWiFiInterface.cpp", line=1201) at ./mbed-os/platform/mbed_assert.c:26
#7  0x080b843e in OdinWiFiInterface::handle_wlan_status_connected (this=0x20009d28 <WiFiInterface::get_target_default_instance()::wifi>, wlan_connect=0x20016aa0) at ./mbed-os/targets/TARGET_STM/TARGET_STM32F4/TARGET_STM32F439xI/TARGET_MODULE_UBLOX_ODIN_W2/sdk/ublox-odin-w2-drivers/OdinWiFiInterface.cpp:1201
#8  0x080b7aa2 in OdinWiFiInterface::handle_in_msg (this=0x20009d28 <WiFiInterface::get_target_default_instance()::wifi>) at ./mbed-os/targets/TARGET_STM/TARGET_STM32F4/TARGET_STM32F439xI/TARGET_MODULE_UBLOX_ODIN_W2/sdk/ublox-odin-w2-drivers/OdinWiFiInterface.cpp:777
#9  0x080b6d9c in wlan_callb_s::odin_thread_fcn (wifi=0x20009d28 <WiFiInterface::get_target_default_instance()::wifi>) at ./mbed-os/targets/TARGET_STM/TARGET_STM32F4/TARGET_STM32F439xI/TARGET_MODULE_UBLOX_ODIN_W2/sdk/ublox-odin-w2-drivers/OdinWiFiInterface.cpp:139
#10 0x080b987c in mbed::Callback<void ()>::function_context<void (*)(OdinWiFiInterface*), OdinWiFiInterface>::operator()() const (this=0x2000a000 <WiFiInterface::get_target_default_instance()::wifi+728>) at ./mbed-os/platform/Callback.h:691
#11 0x080b9830 in mbed::Callback<void ()>::function_call<mbed::Callback<void ()>::function_context<void (*)(OdinWiFiInterface*), OdinWiFiInterface> >(void const*) (p=0x2000a000 <WiFiInterface::get_target_default_instance()::wifi+728>) at ./mbed-os/platform/Callback.h:651
#12 0x0805d4c4 in mbed::Callback<void ()>::call() const (this=0x2000a000 <WiFiInterface::get_target_default_instance()::wifi+728>) at ./mbed-os/platform/Callback.h:570
#13 0x0805dcf4 in mbed::Callback<void ()>::operator()() const (this=0x2000a000 <WiFiInterface::get_target_default_instance()::wifi+728>) at ./mbed-os/platform/Callback.h:577
#14 0x080b6c3c in rtos::Thread::_thunk (thread_ptr=0x20009ffc <WiFiInterface::get_target_default_instance()::wifi+724>) at ./mbed-os/rtos/Thread.cpp:431
#15 0x080b5f78 in osThreadGetStackSpace (thread_id=0x0) at ./mbed-os/rtos/TARGET_CORTEX/rtx5/RTX/Source/rtx_thread.c:1729
#16 0x00000000 in ?? ()

Issue request type

[ ] Question
[ ] Enhancement
[x] Bug
@JanneKiiskila
Copy link
Contributor Author

Internal reference: https://jira.arm.com/browse/IOTPART-6682

@ciarmcom
Copy link
Member

ciarmcom commented Feb 5, 2019

Internal Jira reference: https://jira.arm.com/browse/MBOCUSTRIA-837

@SeppoTakalo
Copy link
Contributor

CC: @ARMmbed/team-ublox

@screamerbg
Copy link
Contributor

CC @aqib-ublox

@0xc0170
Copy link
Contributor

0xc0170 commented Mar 14, 2019

I assume this issue is still valid for 5.12rc1/2

@ashok-rao
Copy link
Contributor

Yes. Still valid.

@michalpasztamobica
Copy link
Contributor

We can see this happen a lot in the mbed-os greentea test suite:

[1554866561.85][CONN][RXD] >>> Running case #2: 'NETWORKINTERFACE_STATUS_NONBLOCK'...
[1554866561.95][CONN][INF] found KV pair in stream: {{__testcase_start;NETWORKINTERFACE_STATUS_NONBLOCK}}, queued...
[1554866610.45][CONN][RXD] 
[1554866610.45][CONN][RXD] 
[1554866610.45][CONN][RXD] ++ MbedOS Error Info ++
[1554866610.45][CONN][RXD] Error Status: 0x80FF0144 Code: 324 Module: 255
[1554866610.55][CONN][RXD] Error Message: Assertion failed: FALSE
[1554866610.55][CONN][RXD] Location: 0x8017B15
[1554866610.65][CONN][RXD] File: ./mbed-os/targets/TARGET_STM/TARGET_STM32F4/TARGET_STM32F439xI/TARGET_MODULE_UBLOX_ODIN_W2/sdk/ublox-odin-w2-drivers/OdinWiFiInterface.cpp+1189
[1554866610.75][CONN][RXD] Error Value: 0x0
[1554866610.85][CONN][RXD] Current Thread: application_unnamed_thread  Id: 0x200061EC Entry: 0x800E2D5 StackSize: 0x1000 StackMem: 0x200108B8 SP: 0x20011814 
[1554866610.95][CONN][RXD] For more info, visit: https://mbed.com/s/error?error=0x80FF0144&tgt=MTB_UBLOX_ODIN_W2
[1554866610.95][CONN][RXD] -- MbedOS Error Info --

Could the priority be raised on this issue somehow?
I double checked that the state which isn't handled is S_STA_CONNECTED, so it's the exact same problem.

@cmonr
Copy link
Contributor

cmonr commented Apr 12, 2019

@SenRamakri @bulislaw ?

@aqib-ublox
Copy link
Contributor

@michalpasztamobica which test are u using please mention I have just used https://github.com/ARMmbed/mbed-cloud-client-example and followed instruciton as given in https://www.pelion.com/docs/device-management/current/connecting/mbed-os.html and successfully registered, connect board with pelion and update firmware as well. please see logs
CONNECT-UPDATE-LOGS.txt
build-logs-cloud-client-simple.txt

@michalpasztamobica
Copy link
Contributor

@aqib-ublox , above I quoted logs from NETWORKINTERFACE_STATUS_NONBLOCK test, but it doesn't matter much - across our CI I can see this assert occur in any netsocket-* and network-*.

Anyway - the issue has been quite well defined already. The handle_wlan_status_connected handler asserts when it receives S_STA_CONNECTED. Generate any situation where S_STA_CONNECTED gets into the handler and you will have the issue reproduced, no need to focus on mbed-os tests suites.

@michalpasztamobica
Copy link
Contributor

I double checked the results in CI and I can see the issue last occurred in the run from 13th April and did not occur any more afterwards.
I checked there were no UBLOX-related updates recently, so I think it's just that CI runs tens of tests daily and can trigger the erroneous situation more likely.

@aqib-ublox
Copy link
Contributor

aqib-ublox commented Apr 17, 2019 •
edited
Loading

@michalpasztamobica my point is scenario is we have station connected to AP and still we got handle_wlan_status_connected() again in our scenario ? in our test why this scenario is coming to picture?

@aqib-ublox
Copy link
Contributor

aqib-ublox commented Apr 17, 2019 •
edited
Loading

I just have generated a scenario

  1. I have connected station to AP so this make _state_sta = S_STA_CONNECTED

  2. Down AP and immediately activated it again

    I saw that ODIN_W2 got handle_wlan_status_connected() while _state_sta = S_STA_CONNECTED ok would add handling and generate PR but it's a very aggressive scenario because if AP is not up immediately we would get

cbWLAN_STATUS_CONNECTING

WLAN STATUS CONNECTION FAILURE

which avoid generation of above scenario.
thanks @michalpasztamobica

@michalpasztamobica
Copy link
Contributor

@aqib-ublox , I am glad you managed to get a reproducible scenario.
I think this resembles a situation where a network is on the edge of connectivity and the board sometimes, for a short period, looses the connection and then recovers a moment after.
I think this situation might be quite common in the reality of crowded test racks polluted with a lot of Wi-Fi networks, which is probably why our CI tests were hitting it every now and then.

@JanneKiiskila
Copy link
Contributor Author

Which could also happen if you have a Wi-Fi access point in a place - say with pillars/columns and you have a moving device - it would/could periodically lose the signal and something like this could happen in real life, too. I hope we get a fix for this.

@bulislaw
Copy link
Member

@MarceloSalazar fyi

@aqib-ublox aqib-ublox mentioned this issue Apr 23, 2019
Merged
@aqib-ublox
Copy link
Contributor

#10454 created

@aqib-ublox aqib-ublox mentioned this issue May 28, 2019
Closed
@aqib-ublox
Copy link
Contributor

@JanneKiiskila @michalpasztamobica can it be closed now as fix is merged in #10454

@MarceloSalazar
Copy link

Closing issue as considered resolved

@michalpasztamobica michalpasztamobica mentioned this issue Aug 26, 2019
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
devices: ublox type: bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests