Hello,
I am currently developing a new bt-le-program and besides my own log-messages, I wanted to enable also the log-output that is happing in the files from the Nordic SDK. Due to some previous experiments with different examples, I figured that especially for error-tracing I am not garantueed to see my own log-messages on the UART.
Sorry for this huge text, but I wanted to provide as much information as possible and also keep everything in one topic!
So first of all I implemented a wrapper-function for APP_ERROR_CHECK(), that also generates a normal printf()-message:
void check_error_code(const char* function_name, uint32_t err_code, int8_t err_position)
{
APP_ERROR_CHECK(err_code);
#ifdef DEBUG_APP_ERROR_CODE
if(err_code != NRF_SUCCESS) {
printf("%s: '%s()' - Error #%ld [%d]\r\n", print_timestamp(), function_name, err_code, err_position);
}// if(err_code != NRF_SUCCESS)
#endif /* DEBUG_APP_ERROR_CODE */
}
At that point I found out, that in case something is going wrong in the APP_ERROR_CHECK()-chain (-> APP_ERROR_HANDLER() -> app_error_handler_bare() -> app_error_fault_handler()) then I am missing the printf()-message and the UART just dies without any further responses from the program.
Here is an example for this problem:
void tag_service_char_update(uint16_t handle_num, int32_t *value)
{
...
if(m_tag_service.conn_handle != BLE_CONN_HANDLE_INVALID)
{
...
err_code = sd_ble_gatts_hvx(m_tag_service.conn_handle, &hvx_params);
check_error_code(__func__, err_code, 1);
}// if(m_tag_service.conn_handle != BLE_CONN_HANDLE_INVALID)
}
Basically I just wanted an error-check for sd_ble_gatts_hvx() - which isnt so bad in general, but not if your trying to run a check on error 0x3401 which gets caused by not having registered for notifications yet by setting the corresponding CCCD (see here).
This is the output with APP_ERROR_CHECK():
0.000013 : UART Start!
0.254431 : BLE Stack Initialized
...
0.258291 : Advertising Initialized
7.085754 : BLE_GAP_EVT_CONNECTED
7.085895 : TSS: old_state: 00 / new_state: 10
7
Right after the function TSS the function SUT gets called that initiates a tag_service_char_update() and where everything ends...
In comparison the output without APP_ERROR_CHECK():
0.000013 : UART Start!
0.254335 : BLE Stack Initialized
...
0.258162 : Advertising Initialized
7.289678 : BLE_GAP_EVT_CONNECTED
7.289818 : TSS: old_state: 00 / new_state: 10
...
7.341076 : ---------- GATT-Connection established ----------
7.341263 : TSS: old_state: 10 / new_state: 11
7.341446 : SUT: tag_state: 10
7.341600 : 'tag_service_char_update()' - Error #13313 [1]
...
7.392454 : SUT: tag_state: 11
7.392608 : 'tag_service_char_update()' - Error #13313 [1]
7.780288 : BLE_GAP_EVT_CONN_PARAM_UPDATE
8.446338 : BLE_GAP_EVT_CONN_PARAM_UPDATE
12.420753 : BLE_GAP_EVT_CONN_PARAM_UPDATE
...
After that I decided to try my luck with adding some backtracing-functionality with registering a signal-handler to exclude any SEG-FAULTs or similar errors, but that obviously didnt brought that much more insight. Only tried the unwind-api so far, which is coming with the gnu-arm-tools - didnt linked libunwind as of yet.
Then I decided its time to go through the entire Nordic SDK to see how appropriate error-handling is done there. While doing some research I found a good "tutorial", that is explaining in detail how to set up the NRF_LOG()-api for your program. A few more topics like this or this also address difficulties that might occur when getting NRF_LOG() to work.
Now to my questions:
a) Is there a possible interference of doing both uart_init(); and NRF_LOG_INIT(NULL); simultaneously?
b) What is the correct setting for the macros UART_DEFAULT_CONFIG_HWFC, NRF_LOG_DEFERRED and NRF_LOG_BACKEND_SERIAL_UART_FLOW_CONTROL? If I understand their description correctly they are about controlling an internal character-buffering that is done for the UART, so they should either be all 0 or 1 (which requires FLUSH)?
c) Under which circumstances is the assert_nrf_callback() invoked? Does it automatically get registered by the softdevice-manager due to an "extern"-prefix or do I have to do it manually? (Cant seem to find any call-hierarchy for that function so I cant say which files actually use it!)
d) Is the 180s-timeout of the advertising also causing some kind of error? Because for this problem I am also seeing just a "sudden death" of the UART...
0.000013 : UART Start!
0.254432 : BLE Stack Initialized
...
0.258296 : Advertising Initialized
182
Is it caused due to only having a ble_adv_fast_timeout which causes the execution of m_error_handler(ret) in on_timeout() of ble_advertising.c?
e) How can I get a log-message even before calling uart_init(); or NRF_LOG_INIT(NULL);? (including an unidentifyable character)
▒SDH:INFO:sd_ble_enable: RAM START at 0x20002128
0.000013 : UART Start!
0.258799 : BLE Stack Initialized
...
0.313270 : Advertising Initialized
...
f) When I add an NRF_LOG_INFO("\r\nERROR\r\n"); in my check_error_code()-function (with disabled APP_ERROR_CHECK()) then I am seeing the following:
▒SDH:INFO:sd_ble_enable: RAM START at 0x20002128
0.000013 : UART Start!
0.258931 : BLE Stack Initialized
...
0.313402 : Advertising Initialized
28.956534 : BLE_GAP_EVT_CONNECTED
28.959667 : TSS: old_state: 00 / new_state: 10
...
29.028157 : ---------- GATT-Connection established ----------
29.033743 : TSS: old_state: 10 / new_state: 11
29.0SAT:INFO:
Error
38039 : SUT: tag_state: 10
29.042854 : 'tag_service_char_update()' - Error #13313 [1]
29.093409 : SUT: old_state: 10 / new_state: 11
29.097701 : ---------- IDLE ----------
29.1SAT:INFO:
Error
01271 : SUT: tag_state: 11
29.106082 : 'tag_service_char_update()' - Error #13313 [1]
29.432641 : BLE_GAP_EVT_CONN_PARAM_UPDATE
30.106564 : BLE_GAP_EVT_CONN_PARAM_UPDATE
...
Is that behaviour of breaking my printf()-messages normal? My guess would be that the NRF_LOG()-API operates with a higher event-priority then the UART-api...
I would very much like to bring more transparency into my system to precisely see whats been happening there and to have everything synced with my timestamps!
Any1 got an idea?
Thanks in advance!
