http request fails if server takes at least 3 seconds to start responding

I'm attempting to HTTP GET from a google cloud function that does a lost of processing so it takes a long time to start responding. On the latest version of my custom board this has started to consistently fail for several hours at a time but then start working for several hours before failing again. I'm able to verify in the server logs that the cloud function thinks it is successfully returning the data. I believe there is a proxy, so maybe it is just successfully returning to the proxy and then the proxy notices a broken tcp connection. I do not have any proxy logs to back this up.

Calling the cloud function from both a different chip and from a browser is always successful. I've created a demo sever where I can control the timeout and it seems that as long as the response time is 2 seconds or below the HTTP GET succeeds.

The failure symptoms on the device is that the first call to zsock_recv() inside of Zephyr's http code never unblocks, even if I let it run overnight. This makes me think that the tcp connection is dropping and the modem does not notice. Zephyr's http timeout is implemented using zsock_shutdown() which I think is not implemented for the nrf9160 (but verification would be appreciated). I'll try using SO_RCVTIMEO to hopefully turn this infinite hang into a cleaner error but I still need to get this http request working.

I'm using a custom board and have verified that this issue exists with both of the following setups:

nrf connect sdk version 2.0.0 and modem firmware version 1.3.1.
nrf connect sdk version 2.3.0 and modem firmware version 1.3.3.

I've attached a minimal example that uses sdk version 2.3.0. The HTTP_DELAY near the top of main.cpp is adjusted to control the delay. In my testing a value of 3 or higher always fails when the board is being sketchy. A value of 0 or 1 always succeeds. 2 works most of the time. I'm keeping the server deployed while this issue is open.

Creating this ticket with attachments is failing. I'll try updating using comments.

Top Replies

Alex Fickle over 2 years ago in reply to Hakon +1 verified

Thanks, I'll get a trace next time it starts to fail. In the meantime I've verified that http timeouts do not work with Zephyr's HTTP library due to lack of support for zsock_shutdown(). This combined…

0 Alex Fickle over 2 years ago

Looks like attaching the prg.conf is what caused creating the post to fail, inserting the as code snippets instead.

prj.conf:

# bootloader
CONFIG_BOOTLOADER_MCUBOOT=y

# C++
CONFIG_CPLUSPLUS=y
CONFIG_STD_CPP17=y
CONFIG_LIB_CPLUSPLUS=y

# libc
CONFIG_NEWLIB_LIBC=y
CONFIG_NEWLIB_LIBC_FLOAT_PRINTF=y
CONFIG_NEWLIB_LIBC_NANO=n

# logging
CONFIG_LOG=y
CONFIG_LOG_MODE_DEFERRED=y
CONFIG_LOG_BUFFER_SIZE=16384
CONFIG_NRF_MODEM_LOG=y
CONFIG_NRF_MODEM_LIB_LOG_LEVEL_DBG=y
CONFIG_LTE_LINK_CONTROL_LOG_LEVEL_DBG=y
CONFIG_PDN_LOG_LEVEL_DBG=y
CONFIG_DATE_TIME_LOG_LEVEL_DBG=y
CONFIG_MODEM_KEY_MGMT_LOG_LEVEL_DBG=y
CONFIG_NET_LOG=y
CONFIG_NET_HTTP_LOG_LEVEL_DBG=y

# trace
CONFIG_NRF_MODEM_LIB_TRACE=y
CONFIG_NRF_MODEM_LIB_TRACE_BACKEND_UART_SYNC=y

# networking
CONFIG_NETWORKING=y
CONFIG_NET_SOCKETS=y
CONFIG_NET_SOCKETS_POSIX_NAMES=y
CONFIG_NET_NATIVE=n
CONFIG_MODEM_KEY_MGMT=y
CONFIG_NRF_MODEM_LIB=y
CONFIG_LTE_LINK_CONTROL=y
CONFIG_LTE_NETWORK_MODE_LTE_M=y
CONFIG_LTE_NETWORK_USE_FALLBACK=n
CONFIG_PDN=y
CONFIG_PDN_DEFAULTS_OVERRIDE=y
CONFIG_PDN_DEFAULT_AUTH_CHAP=y
CONFIG_PDN_DEFAULT_APN="pelion"
CONFIG_PDN_DEFAULT_USERNAME="default"
CONFIG_PDN_DEFAULT_PASSWORD="void"

# network auto connecting
CONFIG_NRF_MODEM_LIB_SYS_INIT=y
# TODO: test if below is needed in latest SDK version, was needed in v2.0.0
CONFIG_PDN_INIT_PRIORITY=89
CONFIG_LTE_AUTO_INIT_AND_CONNECT=n

# date time library
CONFIG_DATE_TIME=y
CONFIG_DATE_TIME_NTP=n
CONFIG_DATE_TIME_MODEM=y
CONFIG_DATE_TIME_AUTO_UPDATE=y

# modem info library
CONFIG_MODEM_INFO=y
CONFIG_MODEM_INFO_ADD_SIM=n
CONFIG_MODEM_INFO_ADD_DEVICE=y
CONFIG_MODEM_INFO_ADD_DATE_TIME=n
CONFIG_MODEM_INFO_ADD_NETWORK=y

# http
CONFIG_HTTP_CLIENT=y

# main thread
CONFIG_MAIN_THREAD_PRIORITY=3
CONFIG_MAIN_STACK_SIZE=4096

# debug options
CONFIG_DEBUG=n
CONFIG_DEBUG_COREDUMP=y
CONFIG_DEBUG_COREDUMP_BACKEND_LOGGING=y
CONFIG_DEBUG_COREDUMP_MEMORY_DUMP_MIN=n

CONFIG_RESET_ON_FATAL_ERROR=n
CONFIG_REBOOT=y

3463.main.cpp

Fullscreen 2476.CMakeLists.txt Download

# SPDX-License-Identifier: Apache-2.0

cmake_minimum_required(VERSION 3.20.0)

find_package(Zephyr REQUIRED HINTS $ENV{ZEPHYR_BASE})
project(hello_world)

target_sources(app PRIVATE src/main.cpp)

0 Alex Fickle over 2 years ago in reply to Alex Fickle

failure-trace.bin

Fullscreen failure-log.txt Download

*** Booting Zephyr OS build v3.2.99-ncs2 ***
I: Starting bootloader
I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Boot source: none
I: Swap type: none
I: Bootloader chainload address offset: 0x10000
[00:00:00.252,838] <inf> nrf_modem: Initializing libmodem 2.3.1-8622ee1c632e
[00:00:00.252,899] <dbg> nrf_modem: Control region at 0x20008000 (0x4e8 bytes)
[00:00:00.252,929] <dbg> nrf_modem: TX region at 0x200084e8 (0x2000 bytes)
[00:00:00.252,960] <dbg> nrf_modem: RX region at 0x2000a568 (0x2000 bytes)
[00:00:00.252,960] <dbg> nrf_modem: Trace region at 0x2000c568 (0x4000 bytes)
[00:00:00.430,480] <dbg> nrf_modem: IPC trace ready
[00:00:00.476,867] <dbg> nrf_modem: Handshake completed
[00:00:00.476,867] <inf> nrf_modem: RPC ready
[00:00:00.477,264] <dbg> nrf_modem: _nrf_modem_lib_init: Modem library has initialized, ret 0
[00:00:00.477,264] <dbg> nrf_modem: _nrf_modem_lib_init: Modem init callback: 0x3688d
[00:00:00.477,294] <dbg> nrf_modem: _nrf_modem_lib_init: Modem init callback: 0x2676d
[00:00:00.477,386] <dbg> nrf_modem: AT+CGDCONT=0,IPV4V6,pelion
[00:00:00.484,069] <dbg> nrf_modem: AT+CGAUTH=0,2,default,void
[00:00:00.484,527] <dbg> nrf_modem: _nrf_modem_lib_init: Modem init callback: 0x364e3
[00:00:00.484,619] <inf> nrf_modem_lib_trace: Trace thread ready
[00:00:00.484,710] <dbg> nrf_modem: AT%XMODEMTRACE=1,2
[00:00:00.485,992] <inf> nrf_modem_lib_trace: Trace level override: 2
*** Booting Zephyr OS build v3.2.99-ncs2 ***
[00:00:00.486,175] <inf> app: main() started
[00:00:01.486,236] <inf> app: CustomBoardInit() started
[00:00:01.496,368] <inf> app: CustomBoardInit() finished
[00:00:01.496,398] <inf> app: NetworkInit() started
[00:00:01.496,459] <dbg> nrf_modem: AT+CMEE?
[00:00:01.505,310] <dbg> nrf_modem: AT+CMEE=1
[00:00:01.505,767] <dbg> nrf_modem: AT%CMNG=2,100,0
[00:00:01.509,521] <dbg> nrf_modem: AT+CMEE=0
[00:00:01.510,040] <dbg> nrf_modem: AT%XSYSTEMMODE?
[00:00:01.510,498] <dbg> lte_lc: init_and_config: System mode (1) and preference (0) are already configured
[00:00:01.510,589] <dbg> nrf_modem: AT+CEREG=5
[00:00:01.510,925] <dbg> nrf_modem: AT+CSCON=1
[00:00:01.511,291] <dbg> nrf_modem: AT+CEREG?
[00:00:01.511,718] <dbg> nrf_modem: AT+CFUN?
[00:00:01.512,145] <dbg> nrf_modem: AT%XSYSTEMMODE=1,0,0,0
[00:00:01.514,221] <dbg> nrf_modem: AT+CEREG=5
[00:00:01.514,556] <dbg> nrf_modem: AT+CSCON=1
[00:00:01.514,923] <dbg> nrf_modem: AT+CFUN=1
[00:00:01.544,769] <dbg> lte_lc: lte_lc_func_mode_set: CFUN monitor callback: 0x3689f
[00:00:01.544,769] <dbg> pdn: on_cfun: Subscribing to +CNEC=16 and +CGEREP=1
[00:00:01.544,830] <dbg> nrf_modem: AT+CNEC=16
[00:00:01.545,257] <dbg> nrf_modem: AT+CGEREP=1
[00:00:05.406,585] <dbg> lte_lc: at_handler_cereg: +CEREG notification: +CEREG: 2,"B481","01D05B0D",7

[00:00:05.406,768] <dbg> lte_lc_helpers: parse_cereg: Network registration status: 2
[00:00:05.406,799] <dbg> lte_lc_helpers: parse_cereg: LTE mode: 7
[00:00:05.406,860] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:05.406,890] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:05.406,951] <dbg> nrf_modem: AT%XTIME=1
[00:00:05.407,348] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:00:05.407,379] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:05.407,379] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:05.407,379] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:00:05.407,409] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:05.407,440] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:05.407,440] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:00:05.497,192] <dbg> lte_lc: at_handler_cscon: +CSCON notification
[00:00:05.497,314] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:05.497,314] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:05.497,344] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:00:08.383,941] <dbg> lte_lc: at_handler_cereg: +CEREG notification: +CEREG: 5,"B481","01D05B0D",7,,,"11100000","11100000"

[00:00:08.384,216] <dbg> lte_lc_helpers: parse_cereg: Network registration status: 5
[00:00:08.384,246] <dbg> lte_lc_helpers: parse_cereg: LTE mode: 7
[00:00:08.384,307] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:08.384,307] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:08.384,338] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:00:08.384,429] <dbg> nrf_modem: AT%XMONITOR
[00:00:08.385,070] <dbg> lte_lc_helpers: parse_psm: TAU: 3240 sec, active time: -1 sec
[00:00:08.385,101] <dbg> lte_lc: lte_lc_psm_get: TAU: 3240 sec, active time: -1 sec
[00:00:08.385,101] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:08.385,131] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:08.385,162] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:00:08.405,792] <dbg> date_time: date_time_core_current_check: Date time never set
[00:00:08.405,822] <dbg> date_time: date_time_at_xtime_handler: Time obtained from cellular network (XTIME notification)
[00:00:08.405,853] <dbg> date_time: date_time_core_schedule_update: New periodic date time update in: 14400 seconds
[00:00:08.405,883] <dbg> date_time: date_time_core_store: System time updated: 2023-03-10 23:05:20
[00:00:08.484,558] <inf> app: current time: 1678489520078
[00:00:14.692,260] <dbg> lte_lc: at_handler_cscon: +CSCON notification
[00:00:14.692,382] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:14.692,413] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:14.692,413] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:00:18.484,649] <inf> app: NetworkInit() finished
[00:00:18.484,771] <dbg> nrf_modem: AT%XCBAND
[00:00:18.493,835] <dbg> nrf_modem: AT%XCBAND=?
[00:00:18.494,323] <dbg> nrf_modem: AT+CGDCONT?
[00:00:18.495,300] <dbg> nrf_modem: AT+CEMODE?
[00:00:18.501,983] <dbg> nrf_modem: AT+COPS?
[00:00:18.502,532] <dbg> nrf_modem: AT+CEREG?
[00:00:18.503,265] <dbg> nrf_modem: AT+CEREG?
[00:00:18.504,028] <dbg> nrf_modem: AT%XSYSTEMMODE?
[00:00:18.504,669] <dbg> nrf_modem: AT%XSYSTEMMODE?
[00:00:18.505,432] <dbg> nrf_modem: AT%XSYSTEMMODE?
[00:00:18.506,164] <dbg> nrf_modem: AT+CGDCONT?
[00:00:18.506,927] <dbg> nrf_modem: AT+CESQ
[00:00:18.513,610] <dbg> nrf_modem: AT+CGMR
[00:00:18.514,068] <dbg> nrf_modem: AT%XVBAT
[00:00:18.514,587] <dbg> nrf_modem: AT+CGSN
[00:00:18.521,240] <inf> app: signal strength (RSRP): -63 dBm
[00:00:18.521,240] <inf> app: battery level: 3285 mV
[00:00:18.521,270] <inf> app: modem firmware: mfw_nrf9160_1.3.3
[00:00:18.521,331] <inf> nrf_modem: Service has port: 443
[00:00:18.521,392] <inf> nrf_modem: getaddrinfo() fam: 0x1, type 0x1, proto 0x6
[00:00:18.639,739] <dbg> lte_lc: at_handler_cscon: +CSCON notification
[00:00:18.639,862] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:18.639,892] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:18.639,892] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:00:18.926,605] <inf> nrf_modem: RPC_IP_GETADDRINFO_RES, result RPC_IP_ERR_OK
[00:00:18.926,696] <dbg> nrf_modem: ai_length 0x4d, ai_family 0x1, ai_addrlen 0x4, ai_namelen 0x31
[00:00:18.926,757] <inf> nrf_modem: Resolved 216.239.36.54
[00:00:18.926,910] <inf> nrf_modem: socket() fam 0x1, type 0x1, proto 0x102
[00:00:18.927,124] <inf> nrf_modem: RPC_IP_OPEN_RES, result RPC_IP_ERR_OK
[00:00:18.927,215] <dbg> nrf_modem: TLS peer verification 2, fd 0x0
[00:00:18.927,246] <dbg> nrf_modem: TLS tags: 1, fd 0x0
[00:00:18.927,276] <inf> nrf_modem: connect() fd 0x0
[00:00:18.927,337] <inf> nrf_modem: sa_family 0x1, destaddr_len 0x4, destport 443
[00:00:19.133,422] <inf> nrf_modem: RPC_IP_CONNECT_RES fd 0x0, result RPC_IP_ERR_OK
[00:00:19.133,483] <dbg> nrf_modem: Waiting for handshake semaphore
[00:00:19.133,514] <inf> nrf_modem: Attaching sock fd 0x0
[00:00:19.133,544] <dbg> nrf_modem: Hostname: none
[00:00:19.133,575] <dbg> nrf_modem: role 0x2, verify 0x2, cache 0x0, tags count 1
[00:00:19.133,605] <dbg> nrf_modem: tag[0]: 100
[00:00:19.142,486] <inf> nrf_modem: RPC_IP_TLS_ATTACH_RES fd 0x0, result RPC_IP_ERR_OK
[00:00:21.017,181] <inf> nrf_modem: RPC_IP_TLS_HANDSHAKE_COMPLETE_NTF fd 0x0, result RPC_IP_ERR_OK
[00:00:21.017,242] <inf> app: SocketTCPConnect() created socket 0
[00:00:21.017,333] <dbg> net_http: http_flush_data: Data to send
                                   47 45 54 20 2f 74 65 73  74 5f 6c 6f 6e 67 5f 68 |GET /tes t_long_h
                                   74 74 70 5f 67 65 74 3f  64 65 6c 61 79 3d 33 26 |ttp_get? delay=3&
                                   73 69 7a 65 3d 31 30 30  20 48 54 54 50 2f 31 2e |size=100  HTTP/1.
                                   31 0d 0a 48 6f 73 74 3a  20 75 73 2d 63 65 6e 74 |1..Host:  us-cent
                                   72 61 6c 31 2d 64 65 76  65 6c 6f 70 6d 65 6e 74 |ral1-dev elopment
                                   2d 32 32 32 36 32 33 2e  63 6c 6f 75 64 66 75 6e |-222623. cloudfun
                                   63 74 69 6f 6e 73 2e 6e  65 74 0d 0a 0d 0a       |ctions.n et....
[00:00:21.017,395] <inf> nrf_modem: send() fd 0x0, len 110, blocking
[00:00:21.018,066] <inf> nrf_modem: RPC_IP_SEND_RES fd 0x0, result RPC_IP_ERR_OK
[00:00:21.018,157] <inf> nrf_modem: send() fd 0x0, 110 bytes sent
[00:00:21.018,157] <dbg> net_http: http_client_req: (0x20015e28): Sent 110 bytes
[00:00:21.018,249] <inf> nrf_modem: recv() fd 0x0, buf 0x2001a8a8, len 256, flags 0 (blocking)
[00:00:24.517,456] <dbg> lte_lc: at_handler_cscon: +CSCON notification
[00:00:24.517,578] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:24.517,578] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:24.517,578] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:01:21.633,819] <err> app: fatal error: watchdog timed out

success-trace.bin

Fullscreen success-log.txt Download

*** Booting Zephyr OS build v3.2.99-ncs2 ***
I: Starting bootloader
I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Boot source: none
I: Swap type: none
I: Bootloader chainload address offset: 0x10000
[00:00:00.252,899] <inf> nrf_modem: Initializing libmodem 2.3.1-8622ee1c632e
[00:00:00.252,960] <dbg> nrf_modem: Control region at 0x20008000 (0x4e8 bytes)
[00:00:00.252,990] <dbg> nrf_modem: TX region at 0x200084e8 (0x2000 bytes)
[00:00:00.253,021] <dbg> nrf_modem: RX region at 0x2000a568 (0x2000 bytes)
[00:00:00.253,021] <dbg> nrf_modem: Trace region at 0x2000c568 (0x4000 bytes)
[00:00:00.430,541] <dbg> nrf_modem: IPC trace ready
[00:00:00.476,898] <dbg> nrf_modem: Handshake completed
[00:00:00.476,928] <inf> nrf_modem: RPC ready
[00:00:00.477,325] <dbg> nrf_modem: _nrf_modem_lib_init: Modem library has initialized, ret 0
[00:00:00.477,325] <dbg> nrf_modem: _nrf_modem_lib_init: Modem init callback: 0x3688d
[00:00:00.477,355] <dbg> nrf_modem: _nrf_modem_lib_init: Modem init callback: 0x2676d
[00:00:00.477,447] <dbg> nrf_modem: AT+CGDCONT=0,IPV4V6,pelion
[00:00:00.484,130] <dbg> nrf_modem: AT+CGAUTH=0,2,default,void
[00:00:00.484,588] <dbg> nrf_modem: _nrf_modem_lib_init: Modem init callback: 0x364e3
[00:00:00.484,680] <inf> nrf_modem_lib_trace: Trace thread ready
[00:00:00.484,771] <dbg> nrf_modem: AT%XMODEMTRACE=1,2
[00:00:00.486,053] <inf> nrf_modem_lib_trace: Trace level override: 2
*** Booting Zephyr OS build v3.2.99-ncs2 ***
[00:00:00.486,236] <inf> app: main() started
[00:00:01.486,297] <inf> app: CustomBoardInit() started
[00:00:01.496,429] <inf> app: CustomBoardInit() finished
[00:00:01.496,459] <inf> app: NetworkInit() started
[00:00:01.496,520] <dbg> nrf_modem: AT+CMEE?
[00:00:01.505,371] <dbg> nrf_modem: AT+CMEE=1
[00:00:01.505,828] <dbg> nrf_modem: AT%CMNG=2,100,0
[00:00:01.509,582] <dbg> nrf_modem: AT+CMEE=0
[00:00:01.510,101] <dbg> nrf_modem: AT%XSYSTEMMODE?
[00:00:01.510,559] <dbg> lte_lc: init_and_config: System mode (1) and preference (0) are already configured
[00:00:01.510,650] <dbg> nrf_modem: AT+CEREG=5
[00:00:01.510,986] <dbg> nrf_modem: AT+CSCON=1
[00:00:01.511,352] <dbg> nrf_modem: AT+CEREG?
[00:00:01.511,779] <dbg> nrf_modem: AT+CFUN?
[00:00:01.512,207] <dbg> nrf_modem: AT%XSYSTEMMODE=1,0,0,0
[00:00:01.514,282] <dbg> nrf_modem: AT+CEREG=5
[00:00:01.514,617] <dbg> nrf_modem: AT+CSCON=1
[00:00:01.514,984] <dbg> nrf_modem: AT+CFUN=1
[00:00:01.544,799] <dbg> lte_lc: lte_lc_func_mode_set: CFUN monitor callback: 0x3689f
[00:00:01.544,830] <dbg> pdn: on_cfun: Subscribing to +CNEC=16 and +CGEREP=1
[00:00:01.544,891] <dbg> nrf_modem: AT+CNEC=16
[00:00:01.545,318] <dbg> nrf_modem: AT+CGEREP=1
[00:00:04.847,747] <dbg> lte_lc: at_handler_cereg: +CEREG notification: +CEREG: 2,"B481","01D05B0D",7

[00:00:04.847,961] <dbg> lte_lc_helpers: parse_cereg: Network registration status: 2
[00:00:04.847,991] <dbg> lte_lc_helpers: parse_cereg: LTE mode: 7
[00:00:04.848,052] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:04.848,052] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:04.848,144] <dbg> nrf_modem: AT%XTIME=1
[00:00:04.848,510] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:00:04.848,541] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:04.848,541] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:04.848,571] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:00:04.848,571] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:04.848,602] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:04.848,602] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:00:04.938,201] <dbg> lte_lc: at_handler_cscon: +CSCON notification
[00:00:04.938,323] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:04.938,323] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:04.938,354] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:00:07.587,036] <dbg> lte_lc: at_handler_cereg: +CEREG notification: +CEREG: 5,"B481","01D05B0D",7,,,"11100000","11100000"

[00:00:07.587,310] <dbg> lte_lc_helpers: parse_cereg: Network registration status: 5
[00:00:07.587,341] <dbg> lte_lc_helpers: parse_cereg: LTE mode: 7
[00:00:07.587,402] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:07.587,432] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:07.587,432] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:00:07.587,524] <dbg> nrf_modem: AT%XMONITOR
[00:00:07.588,195] <dbg> lte_lc_helpers: parse_psm: TAU: 3240 sec, active time: -1 sec
[00:00:07.588,195] <dbg> lte_lc: lte_lc_psm_get: TAU: 3240 sec, active time: -1 sec
[00:00:07.588,226] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:07.588,226] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:07.588,256] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:00:07.616,790] <dbg> date_time: date_time_core_current_check: Date time never set
[00:00:07.616,821] <dbg> date_time: date_time_at_xtime_handler: Time obtained from cellular network (XTIME notification)
[00:00:07.616,851] <dbg> date_time: date_time_core_schedule_update: New periodic date time update in: 14400 seconds
[00:00:07.616,882] <dbg> date_time: date_time_core_store: System time updated: 2023-03-10 23:08:59
[00:00:07.687,652] <inf> app: current time: 1678489739070
[00:00:13.912,170] <dbg> lte_lc: at_handler_cscon: +CSCON notification
[00:00:13.912,322] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:13.912,322] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:13.912,322] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:00:17.687,744] <inf> app: NetworkInit() finished
[00:00:17.687,896] <dbg> nrf_modem: AT%XCBAND
[00:00:17.696,929] <dbg> nrf_modem: AT%XCBAND=?
[00:00:17.697,418] <dbg> nrf_modem: AT+CGDCONT?
[00:00:17.698,425] <dbg> nrf_modem: AT+CEMODE?
[00:00:17.705,108] <dbg> nrf_modem: AT+COPS?
[00:00:17.705,657] <dbg> nrf_modem: AT+CEREG?
[00:00:17.706,390] <dbg> nrf_modem: AT+CEREG?
[00:00:17.707,153] <dbg> nrf_modem: AT%XSYSTEMMODE?
[00:00:17.707,794] <dbg> nrf_modem: AT%XSYSTEMMODE?
[00:00:17.708,557] <dbg> nrf_modem: AT%XSYSTEMMODE?
[00:00:17.709,320] <dbg> nrf_modem: AT+CGDCONT?
[00:00:17.710,113] <dbg> nrf_modem: AT+CESQ
[00:00:17.716,796] <dbg> nrf_modem: AT+CGMR
[00:00:17.717,254] <dbg> nrf_modem: AT%XVBAT
[00:00:17.717,803] <dbg> nrf_modem: AT+CGSN
[00:00:17.718,231] <inf> app: signal strength (RSRP): -66 dBm
[00:00:17.718,261] <inf> app: battery level: 3292 mV
[00:00:17.718,292] <inf> app: modem firmware: mfw_nrf9160_1.3.3
[00:00:17.718,353] <inf> nrf_modem: Service has port: 443
[00:00:17.718,383] <inf> nrf_modem: getaddrinfo() fam: 0x1, type 0x1, proto 0x6
[00:00:17.840,759] <dbg> lte_lc: at_handler_cscon: +CSCON notification
[00:00:17.840,881] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:17.840,911] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:17.840,911] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:00:18.146,514] <inf> nrf_modem: RPC_IP_GETADDRINFO_RES, result RPC_IP_ERR_OK
[00:00:18.146,606] <dbg> nrf_modem: ai_length 0x4d, ai_family 0x1, ai_addrlen 0x4, ai_namelen 0x31
[00:00:18.146,697] <inf> nrf_modem: Resolved 216.239.36.54
[00:00:18.146,850] <inf> nrf_modem: socket() fam 0x1, type 0x1, proto 0x102
[00:00:18.147,277] <inf> nrf_modem: RPC_IP_OPEN_RES, result RPC_IP_ERR_OK
[00:00:18.147,369] <dbg> nrf_modem: TLS peer verification 2, fd 0x0
[00:00:18.147,430] <dbg> nrf_modem: TLS tags: 1, fd 0x0
[00:00:18.147,460] <inf> nrf_modem: connect() fd 0x0
[00:00:18.147,491] <inf> nrf_modem: sa_family 0x1, destaddr_len 0x4, destport 443
[00:00:18.361,450] <inf> nrf_modem: RPC_IP_CONNECT_RES fd 0x0, result RPC_IP_ERR_OK
[00:00:18.361,480] <dbg> nrf_modem: Waiting for handshake semaphore
[00:00:18.361,541] <inf> nrf_modem: Attaching sock fd 0x0
[00:00:18.361,541] <dbg> nrf_modem: Hostname: none
[00:00:18.361,602] <dbg> nrf_modem: role 0x2, verify 0x2, cache 0x0, tags count 1
[00:00:18.361,602] <dbg> nrf_modem: tag[0]: 100
[00:00:18.371,185] <inf> nrf_modem: RPC_IP_TLS_ATTACH_RES fd 0x0, result RPC_IP_ERR_OK
[00:00:20.389,404] <inf> nrf_modem: RPC_IP_TLS_HANDSHAKE_COMPLETE_NTF fd 0x0, result RPC_IP_ERR_OK
[00:00:20.389,495] <inf> app: SocketTCPConnect() created socket 0
[00:00:20.389,587] <dbg> net_http: http_flush_data: Data to send
                                   47 45 54 20 2f 74 65 73  74 5f 6c 6f 6e 67 5f 68 |GET /tes t_long_h
                                   74 74 70 5f 67 65 74 3f  64 65 6c 61 79 3d 32 26 |ttp_get? delay=2&
                                   73 69 7a 65 3d 31 30 30  20 48 54 54 50 2f 31 2e |size=100  HTTP/1.
                                   31 0d 0a 48 6f 73 74 3a  20 75 73 2d 63 65 6e 74 |1..Host:  us-cent
                                   72 61 6c 31 2d 64 65 76  65 6c 6f 70 6d 65 6e 74 |ral1-dev elopment
                                   2d 32 32 32 36 32 33 2e  63 6c 6f 75 64 66 75 6e |-222623. cloudfun
                                   63 74 69 6f 6e 73 2e 6e  65 74 0d 0a 0d 0a       |ctions.n et....
[00:00:20.389,617] <inf> nrf_modem: send() fd 0x0, len 110, blocking
[00:00:20.390,258] <inf> nrf_modem: RPC_IP_SEND_RES fd 0x0, result RPC_IP_ERR_OK
[00:00:20.390,350] <inf> nrf_modem: send() fd 0x0, 110 bytes sent
[00:00:20.390,380] <dbg> net_http: http_client_req: (0x20015e28): Sent 110 bytes
[00:00:20.390,441] <inf> nrf_modem: recv() fd 0x0, buf 0x2001a8a8, len 256, flags 0 (blocking)
[00:00:22.689,331] <inf> nrf_modem: RPC_IP_RECVFROM_NTF, fd 0x0 (513 bytes)
[00:00:22.689,392] <dbg> nrf_modem: No sender address
[00:00:22.689,422] <dbg> nrf_modem: Incoming pkt, data 0x2000a718, len 513
[00:00:22.689,514] <dbg> net_http: on_message_begin: (0x20015e28): -- HTTP GET response (headers) --
[00:00:22.689,575] <dbg> net_http: on_status: (0x20015e28): HTTP response status 200 OK
[00:00:22.689,758] <dbg> net_http: print_header_field: (0x20015e28): [12] Content-Type
[00:00:22.689,941] <dbg> net_http: print_header_field: (0x20015e28): [24] text/html; charset=utf-8
[00:00:22.690,093] <dbg> net_http: print_header_field: (0x20015e28): [21] Function-Execution-Id
[00:00:22.690,246] <dbg> net_http: print_header_field: (0x20015e28): [12] cxkra63w4sfl
[00:00:22.690,399] <dbg> net_http: print_header_field: (0x20015e28): [21] X-Cloud-Trace-Context
[00:00:22.690,551] <dbg> net_http: print_header_field: (0x20015e28): [36] e5d68e597d45fadef0feefd31aedb491;o=1
[00:00:22.690,673] <dbg> net_http: print_header_field: (0x20015e28): [4] Date
[00:00:22.690,795] <dbg> net_http: print_header_field: (0x20015e28): [29] Fri, 10 Mar 2023 23:09:14 GMT
[00:00:22.690,887] <dbg> net_http: print_header_field: (0x20015e28): [6] Server
[00:00:22.690,979] <dbg> net_http: print_header_field: (0x20015e28): [15] Google Frontend
[00:00:22.691,101] <dbg> net_http: print_header_field: (0x20015e28): [14] Content-Length
[00:00:22.691,162] <dbg> net_http: print_header_field: (0x20015e28): [3] 100
[00:00:22.691,253] <dbg> net_http: print_header_field: (0x20015e28): [7] Alt-Svc
[00:00:22.691,314] <dbg> net_http: print_header_field: (0x20015e28): [9] h3=":443"
[00:00:22.691,345] <dbg> net_http: http_wait_data: (0x20015e28): Calling callback for partitioned 256 len data
[00:00:22.691,345] <inf> app: HttpResponseCallback() called
[00:00:22.691,375] <inf> app: got http status code update: 200
[00:00:22.691,436] <inf> nrf_modem: recv() fd 0x0, buf 0x2001a8a8, len 256, flags 0 (blocking)
[00:00:22.691,650] <dbg> net_http: print_header_field: (0x20015e28): [127] ; ma=2592000,h3-29=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":4
[00:00:22.691,680] <dbg> net_http: on_headers_complete: (0x20015e28): Headers complete
[00:00:22.691,680] <dbg> net_http: on_body: (0x20015e28): Processed 99 length 99
[00:00:22.691,711] <dbg> net_http: http_wait_data: (0x20015e28): Calling callback for partitioned 256 len data
[00:00:22.691,711] <inf> app: HttpResponseCallback() called
[00:00:22.691,741] <inf> app: got a body fragment of length 99
[00:00:22.691,772] <inf> nrf_modem: recv() fd 0x0, buf 0x2001a8a8, len 256, flags 0 (blocking)
[00:00:22.691,833] <dbg> nrf_modem: Freeing pkt 0x200168ec, pkt.data 0x2000a718
[00:00:22.691,864] <dbg> net_http: on_body: (0x20015e28): Processed 100 length 1
[00:00:22.691,894] <dbg> net_http: on_message_complete: (0x20015e28): -- HTTP GET response (complete) --
[00:00:22.691,925] <dbg> net_http: http_wait_data: (0x20015e28): Calling callback for 1 len data
[00:00:22.691,925] <inf> app: HttpResponseCallback() called
[00:00:22.691,955] <inf> app: got a body fragment of length 1
[00:00:22.691,955] <dbg> net_http: http_client_req: (0x20015e28): Received 513 bytes
[00:00:22.691,986] <inf> nrf_modem: close() fd 0x0
[00:00:22.693,634] <inf> nrf_modem: RPC_IP_CLOSE_RES fd 0x0, result RPC_IP_ERR_OK
[00:00:22.693,695] <inf> app: HttpGet() was successful!!!
[00:00:23.942,474] <dbg> lte_lc: at_handler_cscon: +CSCON notification
[00:00:23.942,596] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:23.942,626] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:23.942,626] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done
[00:00:24.016,815] <dbg> lte_lc: at_handler_cscon: +CSCON notification
[00:00:24.016,937] <dbg> lte_lc_helpers: event_handler_list_dispatch: Dispatching events:
[00:00:24.016,937] <dbg> lte_lc_helpers: event_handler_list_dispatch:  - handler=0x00026AF9
[00:00:24.016,937] <dbg> lte_lc_helpers: event_handler_list_dispatch: Done

0 JONATHAN LL over 2 years ago

Hi,

Will look in to this and get back to you.

Note: If you put all the files in a compressed folder like zip file then it will be accepted.

Regards,
Jonathan
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel
0 Alex Fickle over 2 years ago in reply to Alex Fickle

Minor update, there was a bug in the output of the cell signal strength in the above logs. The real signal strength was -77 dBm for the failure case and -74 dBm for the success case. Should not change much as these are both excellent values.
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel
0 Hakon over 2 years ago

Hello,

I'm taking over for Jonathan. I will try to reproduce this.
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel