secure http issue, works first time, data corruption after first time...

[Anthony Ambuehl]

I"m using SLM from NCS 1.6.1.  

I'm testing HTTPCREQ with HTTPC port 443 and security tag = 1.   After I reset SLM, my send is successful and passes server validation checks.  If I repeat the procedure sending the exact same data, the server is detecting a validation failure indicating something in the data has changed.  The only way to get a successful server validation is by reseting SLM.  I suspect there is some state that is not complete reset by XHTTPCCON=0 in the TLS implementation.   When I test the same with non-secure HTTP (port 80) to postman-echo my payloads are identical.  

Is there any equivalent to postman-echo with an https variant? 

Any idea why it breaks after the first successful attempt?

[Charlie]

Hi Anthony,

Could you provide your current modem firmware version and a modem trace when the failure happens?

Best regards,

Charlie

[Anthony Ambuehl]

Hello Charlie,

I updated modem firmware to 1.3.0 just last week while I was update NCS SDK to 1.6.1.

I tried to capture the modem trace but the generated bin files don't appear to have much of interest.  I'll attach one for reference.   I did confirm with breakpoints that the calls to nrf_modem_os_trace_put were occurring.   My DK has the VDD_IO switched to 3V, perhaps that causes some problems?

trace-2021-09-21T18-56-24.844Z.bin

Fullscreen 2021-09-21T18_19_00.340Z-log.txt Download

2021-09-21T18:19:01.369Z INFO Application data folder: C:\Users\antho\AppData\Roaming\nrfconnect\pc-nrfconnect-tracecollector
2021-09-21T18:19:01.506Z DEBUG App pc-nrfconnect-tracecollector v1.0.8 official
2021-09-21T18:19:01.506Z DEBUG App path: C:\Users\antho\.nrfconnect-apps\node_modules\pc-nrfconnect-tracecollector
2021-09-21T18:19:01.506Z DEBUG nRFConnect 3.7.1, required by the app is (^3.0.0)
2021-09-21T18:19:01.506Z DEBUG nRFConnect path: C:\Users\antho\AppData\Local\Programs\nrfconnect\resources\app.asar
2021-09-21T18:19:01.506Z DEBUG HomeDir: C:\Users\antho
2021-09-21T18:19:01.506Z DEBUG TmpDir: C:\Users\antho\AppData\Local\Temp
2021-09-21T18:19:01.522Z VERBOSE Could not fetch serial number for serial port at COM3
2021-09-21T18:19:18.242Z INFO Device opened
2021-09-21T18:19:35.013Z INFO Tracefile created: C:\Users\antho\AppData\Roaming\nrfconnect\pc-nrfconnect-tracecollector\trace-2021-09-21T18-19-35.007Z.bin
2021-09-21T18:22:32.757Z INFO Device opened
2021-09-21T18:22:34.375Z INFO Tracefile closed
2021-09-21T18:22:51.512Z INFO Device closed
2021-09-21T18:23:44.277Z INFO Device opened
2021-09-21T18:23:49.004Z INFO Tracefile created: C:\Users\antho\AppData\Roaming\nrfconnect\pc-nrfconnect-tracecollector\trace-2021-09-21T18-23-49.002Z.bin
2021-09-21T18:24:50.973Z INFO Tracefile closed
2021-09-21T18:25:02.054Z INFO Generating system report...
2021-09-21T18:25:08.780Z INFO System report: C:\Users\antho\AppData\Roaming\nrfconnect\pc-nrfconnect-tracecollector\nrfconnect-system-report-2021-09-21T18-25-02.054Z.txt
2021-09-21T18:42:28.840Z INFO Device closed
2021-09-21T18:42:28.842Z INFO Device opened
2021-09-21T18:42:30.375Z INFO Tracefile created: C:\Users\antho\AppData\Roaming\nrfconnect\pc-nrfconnect-tracecollector\trace-2021-09-21T18-42-30.374Z.bin
2021-09-21T18:45:51.259Z INFO Tracefile closed
2021-09-21T18:56:07.878Z INFO Device closed
2021-09-21T18:56:07.881Z INFO Device opened
2021-09-21T18:56:24.845Z INFO Tracefile created: C:\Users\antho\AppData\Roaming\nrfconnect\pc-nrfconnect-tracecollector\trace-2021-09-21T18-56-24.844Z.bin
2021-09-21T18:59:45.684Z INFO Tracefile closed

Fullscreen nrfconnect-system-report-2021-09-21T18-25-02.054Z.txt Download

# nRFConnect System Report - 2021-09-21T18-25-02.054Z

- System:     LENOVO 20HHCTO1WW
- BIOS:       LENOVO LENOVO - 1550
- CPU:        1 x Intel® Xeon® E3-1535M v6 3.1 GHz 8 cores (4 physical)
- Memory:     12.1 GB free of 31.8 GB total
- Filesystem: C: (NTFS) 237.1 GB 88.8% used

- OS:         Microsoft Windows 10 Pro for Workstations (10.0.19043) win32 ia32

- Versions
    - kernel: 10.0.19043
    - git: 2.31.1.windows.1
    - node: 12.13.0
    - python: 2.7.17
    - python3: 3.9.7

- Connected devices:
    - COM5: 000960049301 PCA10090
    - COM4: 000683148200 PCA10056

[Charlie]

Hi Anthony,

After some investigation, I can confirm that modem trace does not work on this application since most of the commands work with the modem firmware directly.

In order to get more debug info, I suggest you try our latest nRF Connect SDK 1.7.0 which is available on nRF Connect for Desktop->Toolchain Manager now, you need to add the following setting to get more info:

CONFIG_LOG_MODE_IMMEDIATE=y
CONFIG_NET_LOG=y
CONFIG_NET_HTTP_LOG_LEVEL_DBG=y
CONFIG_SLM_LOG_LEVEL_DBG=y

Then more debug information will appear on the J-Link RTT Viewer terminal.

Best regards,

Charlie 

[Anthony Ambuehl]

I setup to test with 1.7.0 today.  I am getting interesting logs via J-Link RTT-Viewer.

Fullscreen ncs_sdk_170.log Download

# SEGGER J-Link RTT Viewer V6.94b Terminal Log File
# Compiled: 18:05:14 on Jan 26 2021
# Logging started @ 24 Sep 2021 10:54:25
00> *** Booting Zephyr OS build v2.6.99-ncs1  ***
00> 
00> [00:00:00.201,873] <dbg> at_cmd.at_cmd_driver_init: Common AT socket created
00> [00:00:00.202,301] <dbg> at_cmd.at_cmd_driver_init: Common AT socket processing thread created
00> [00:00:00.202,758] <dbg> at_cmd.at_cmd_set_notification_handler: Setting notification handler to 0x33d01
00> [00:00:00.203,277] <inf> slm: Serial LTE Modem
00> [00:00:00.212,463] <err> settings: set-value failure. key: slm/fota_type error(-2)
00> [00:00:00.223,358] <dbg> at_cmd.socket_thread_fn: AT socket thread started
00> [00:00:00.223,754] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:00.224,212] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:00.238,769] <dbg> at_cmd.at_write: Sending command AT+CGSN
00> [00:00:00.245,452] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CGSN
00> [00:00:00.246,002] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 22 bytes, 352656106104584
00> OK
00> 
00> [00:00:00.246,490] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:00.252,197] <inf> slm_at_host: at_host init done
00> [00:00:00.252,624] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:00.253,021] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:10.012,939] <dbg> at_cmd.at_write: Sending command AT
00> [00:01:10.019,683] <dbg> at_cmd.at_cmd_write: Awaiting response for AT
00> [00:01:10.020,141] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:10.020,599] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:10.021,148] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:10.021,575] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:10.032,592] <dbg> at_cmd.at_write: Sending command AT+CGMR
00> [00:01:10.039,276] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CGMR
00> [00:01:10.039,825] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 24 bytes, mfw_nrf9160_1.3.0
00> OK
00> 
00> [00:01:10.040,313] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:10.040,832] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:10.041,351] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:10.046,997] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
00> [00:01:10.053,710] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
00> [00:01:10.054,260] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:10.054,687] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:10.055,206] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:10.055,633] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:10.058,410] <dbg> at_cmd.at_write: Sending command AT+CEREG?
00> [00:01:10.060,455] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG?
00> [00:01:10.061,004] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 18 bytes, +CEREG: 5,4
00> OK
00> 
00> [00:01:10.061,492] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:10.061,981] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:10.062,500] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:10.067,657] <dbg> at_cmd.at_write: Sending command AT+CPSMS?
00> [00:01:10.074,340] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS?
00> [00:01:10.074,890] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 40 bytes, +CPSMS: 1,,,"10101010","00000101"
00> OK
00> 
00> [00:01:10.075,408] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:10.075,897] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:10.076,416] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:10.083,465] <dbg> at_cmd.at_write: Sending command AT+CFUN?
00> [00:01:10.090,179] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN?
00> [00:01:10.090,728] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, +CFUN: 0
00> OK
00> 
00> [00:01:10.091,186] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:10.091,705] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:10.092,224] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:22.097,473] <dbg> at_cmd.at_write: Sending command AT+CFUN=4
00> [00:01:22.104,156] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=4
00> [00:01:22.104,705] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:22.105,133] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:22.105,651] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:22.106,079] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:31.479,736] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
00> [00:01:31.486,450] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
00> 
00> [00:01:31.486,999] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:31.487,426] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:31.488,006] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:31.488,433] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:31.492,187] <dbg> at_cmd.at_write: Sending command AT+CEREG?
00> [00:01:31.493,194] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG?
00> [00:01:31.493,743] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 18 bytes, +CEREG: 5,4
00> OK
00> 
00> [00:01:31.494,201] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:31.494,720] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:31.495,208] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:31.503,387] <dbg> at_cmd.at_write: Sending command AT+CPSMS?
00> [00:01:31.510,070] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS?
00> [00:01:31.510,620] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 40 bytes, +CPSMS: 1,,,"10101010","00000101"
00> OK
00> 
00> [00:01:31.511,169] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:31.511,688] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:31.512,207] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:31.519,226] <dbg> at_cmd.at_write: Sending command AT+CFUN?
00> [00:01:31.525,939] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN?
00> [00:01:31.526,489] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, +CFUN: 4
00> OK
00> 
00> [00:01:31.526,947] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:31.527,435] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:31.527,923] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:31.532,836] <dbg> at_cmd.at_write: Sending command AT+CFUN=21
00> [00:01:31.539,550] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=21
00> [00:01:31.569,366] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:31.569,793] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:31.570,312] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:31.570,739] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:33.070,770] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 32 bytes, +CEREG: 2,"8D07","0A459C0F",7
00> 
00> [00:01:33.071,594] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:33.072,052] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:34.123,657] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 56 bytes, +CEREG: 1,"8D07","0A459C0F",7,,,"00001000","11100000"
00> 
00> [00:01:34.124,572] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:34.125,000] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:35.878,875] <dbg> net_http.Data to send
00>                                   50 4f 53 54 20 2f 64 65  76 69 63 65 2f 61 70 69 |POST /de vice/api
00>                                   2f 76 30 2f 73 74 61 74  69 6f 6e 2f 70 6f 77 65 |/v0/stat ion/powe
00>                                   72 6f 6e 74 65 73 74 20  48 54 54 50 2f 31 2e 31 |rontest  HTTP/1.1
00>                                   0d 0a 48 6f 73 74 3a 20  61 70 69 2e 63 6c 6f 75 |..Host:  api.clou
00>                                   64 2e 63 61 6c 61 68 65  61 6c 74 68 2e 63 6f 6d |d.calahe alth.com
00>                                   0d 0a                                            |..               
00> [00:01:35.885,742] <dbg> net_http.Data to send
00>                                   0d 0a                                            |..               
00> [00:01:35.887,084] <inf> slm_at_host: Enter datamode
00> [00:01:35.890,899] <inf> slm_at_host: Raw send 1
00> [00:01:35.891,815] <inf> slm_httpc: datamode send: 0
00> [00:01:35.917,083] <inf> slm_at_host: Raw send 255
00> [00:01:35.918,426] <inf> slm_httpc: datamode send: 0
00> [00:01:35.943,389] <inf> slm_at_host: Raw send 256
00> [00:01:35.944,763] <inf> slm_httpc: datamode send: 0
00> [00:01:35.957,519] <inf> slm_at_host: Raw send 135
00> [00:01:35.958,984] <inf> slm_httpc: datamode send: 0
00> [00:01:38.935,455] <inf> slm_at_host: Raw send 2
00> [00:01:38.935,791] <wrn> slm_httpc: send unexpected payload
00> [00:01:38.943,023] <inf> slm_httpc: datamode send: 0
00> [00:01:38.943,969] <dbg> net_http.http_client_req: (0x200151a8): Sent 782 bytes
00> [00:01:39.262,390] <dbg> net_http.on_message_begin: (0x200151a8): -- HTTP POST response (headers) --
00> [00:01:39.262,939] <dbg> net_http.on_status: (0x200151a8): HTTP response status 400 BAD REQUEST
00> [00:01:39.264,007] <dbg> net_http.print_header_field: (0x200151a8): [4] Date
00> [00:01:39.265,045] <dbg> net_http.print_header_field: (0x200151a8): [29] Fri, 24 Sep 2021 17:55:12 GMT
00> [00:01:39.266,113] <dbg> net_http.print_header_field: (0x200151a8): [12] Content-Type
00> [00:01:39.267,150] <dbg> net_http.print_header_field: (0x200151a8): [16] application/json
00> [00:01:39.268,218] <dbg> net_http.print_header_field: (0x200151a8): [14] Content-Length
00> [00:01:39.269,226] <dbg> net_http.print_header_field: (0x200151a8): [2] 39
00> [00:01:39.270,233] <dbg> net_http.print_header_field: (0x200151a8): [10] Connection
00> [00:01:39.271,240] <dbg> net_http.print_header_field: (0x200151a8): [10] keep-alive
00> [00:01:39.272,216] <dbg> net_http.print_header_field: (0x200151a8): [10] Set-Cookie
00> [00:01:39.273,254] <dbg> net_http.print_header_field: (0x200151a8): [127] AWSALB=rQ6+rJXzRjyeQwUcoCGBjmzvx8G6bini+SOSBHMNIwYJDTvW2+uPTI8Z8plgZBmxjiEv/x8/QseXK118DiXrCjr1h5f4DaTrI1q+sSEx8c+OXg7WiTu11MB+
00> [00:01:39.274,444] <dbg> net_http.print_header_field: (0x200151a8): [10] Set-Cookie
00> [00:01:39.275,360] <dbg> net_http.print_header_field: (0x200151a8): [127] AWSALBCORS=rQ6+rJXzRjyeQwUcoCGBjmzvx8G6bini+SOSBHMNIwYJDTvW2+uPTI8Z8plgZBmxjiEv/x8/QseXK118DiXrCjr1h5f4DaTrI1q+sSEx8c+OXg7WiTu1
00> [00:01:39.276,458] <dbg> net_http.print_header_field: (0x200151a8): [6] Server
00> [00:01:39.277,221] <dbg> net_http.print_header_field: (0x200151a8): [12] nginx/1.17.6
00> [00:01:39.277,984] <dbg> net_http.print_header_field: (0x200151a8): [13] Cache-Control
00> [00:01:39.278,717] <dbg> net_http.print_header_field: (0x200151a8): [8] no-store
00> [00:01:39.279,479] <dbg> net_http.print_header_field: (0x200151a8): [15] X-Frame-Options
00> [00:01:39.280,242] <dbg> net_http.print_header_field: (0x200151a8): [10] SAMEORIGIN
00> [00:01:39.281,005] <dbg> net_http.print_header_field: (0x200151a8): [16] X-XSS-Protection
00> [00:01:39.281,707] <dbg> net_http.print_header_field: (0x200151a8): [13] 1; mode=block
00> [00:01:39.287,628] <dbg> net_http.print_header_field: (0x200151a8): [22] X-Content-Type-Options
00> [00:01:39.288,360] <dbg> net_http.print_header_field: (0x200151a8): [7] nosniff
00> [00:01:39.289,062] <dbg> net_http.print_header_field: (0x200151a8): [23] Content-Security-Policy
00> [00:01:39.289,733] <dbg> net_http.print_header_field: (0x200151a8): [18] default-src 'self'
00> [00:01:39.290,466] <dbg> net_http.print_header_field: (0x200151a8): [25] X-Content-Security-Policy
00> [00:01:39.291,168] <dbg> net_http.print_header_field: (0x200151a8): [18] default-src 'self'
00> [00:01:39.291,839] <dbg> net_http.print_header_field: (0x200151a8): [25] Strict-Transport-Security
00> [00:01:39.292,541] <dbg> net_http.print_header_field: (0x200151a8): [35] max-age=31556926; includeSubDomains
00> [00:01:39.293,212] <dbg> net_http.print_header_field: (0x200151a8): [15] Referrer-Policy
00> [00:01:39.293,823] <dbg> net_http.print_header_field: (0x200151a8): [31] strict-origin-when-cross-origin
00> [00:01:39.294,494] <dbg> net_http.print_header_field: (0x200151a8): [27] Access-Control-Allow-Origin
00> [00:01:39.295,104] <dbg> net_http.print_header_field: (0x200151a8): [1] *
00> [00:01:39.300,750] <dbg> net_http.on_headers_complete: (0x200151a8): Headers complete
00> [00:01:39.301,269] <dbg> net_http.on_body: (0x200151a8): Processed 39 length 39
00> [00:01:39.301,757] <dbg> net_http.on_body: (0x200151a8): Calling callback for partitioned 971 len data
00> [00:01:39.387,603] <dbg> net_http.on_message_complete: (0x200151a8): -- HTTP POST response (complete) --
00> [00:01:39.391,021] <dbg> net_http.http_client_req: (0x200151a8): Received 971 bytes
00> [00:01:39.398,162] <inf> slm_at_host: Raw send 16
00> [00:01:39.398,498] <wrn> slm_httpc: send unexpected payload
00> [00:01:39.398,834] <inf> slm_httpc: datamode send: 0
00> [00:01:39.401,641] <inf> slm_at_host: Exit datamode
00> [00:01:39.401,977] <inf> slm_httpc: HTTP thread terminated
00> [00:01:52.408,172] <dbg> at_cmd.at_write: Sending command AT
00> [00:01:52.414,916] <dbg> at_cmd.at_cmd_write: Awaiting response for AT
00> [00:01:52.415,374] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:52.415,832] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:52.416,381] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:52.416,839] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:52.428,894] <dbg> at_cmd.at_write: Sending command AT+CGMR
00> [00:01:52.435,577] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CGMR
00> [00:01:52.436,126] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 24 bytes, mfw_nrf9160_1.3.0
00> OK
00> 
00> [00:01:52.436,614] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:52.437,103] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:52.437,591] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:52.443,267] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
00> [00:01:52.449,981] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
00> [00:01:52.450,531] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:52.450,988] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:52.451,538] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:52.451,965] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:52.454,711] <dbg> at_cmd.at_write: Sending command AT+CEREG?
00> [00:01:52.456,726] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG?
00> [00:01:52.457,275] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 62 bytes, +CEREG: 5,1,"8D07","0A459C0F",7,,,"00001000","11100000"
00> OK
00> 
00> [00:01:52.457,855] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:52.458,374] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:52.458,862] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:52.467,864] <dbg> at_cmd.at_write: Sending command AT+CPSMS?
00> [00:01:52.474,548] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS?
00> [00:01:52.475,097] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 40 bytes, +CPSMS: 1,,,"10101010","00000101"
00> OK
00> 
00> [00:01:52.475,646] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:52.476,165] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:52.476,684] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:52.483,734] <dbg> at_cmd.at_write: Sending command AT+CFUN?
00> [00:01:52.490,447] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN?
00> [00:01:52.490,997] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, +CFUN: 1
00> OK
00> 
00> [00:01:52.491,455] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:52.491,943] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:52.492,431] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:02:04.497,711] <dbg> at_cmd.at_write: Sending command AT+CFUN=4
00> [00:02:04.504,394] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=4
00> [00:02:05.205,902] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 12 bytes, +CEREG: 0
00> 
00> [00:02:05.206,634] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:02:05.207,061] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:02:06.584,747] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:02:06.585,174] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:02:06.585,693] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:02:06.586,120] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:02:42.192,199] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
00> [00:02:42.198,913] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
00> [00:02:42.199,462] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:02:42.199,890] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:02:42.200,439] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:02:42.200,866] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:02:42.204,620] <dbg> at_cmd.at_write: Sending command AT+CEREG?
00> [00:02:42.205,657] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG?
00> [00:02:42.206,207] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 18 bytes, +CEREG: 5,0
00> OK
00> 
00> [00:02:42.206,665] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:02:42.207,183] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:02:42.207,672] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:02:42.212,829] <dbg> at_cmd.at_write: Sending command AT+CPSMS?
00> [00:02:42.219,512] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS?
00> [00:02:42.220,062] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 40 bytes, +CPSMS: 1,,,"10101010","00000101"
00> OK
00> 
00> [00:02:42.220,581] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:02:42.221,099] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:02:42.221,618] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:02:42.228,637] <dbg> at_cmd.at_write: Sending command AT+CFUN?
00> [00:02:42.235,351] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN?
00> [00:02:42.235,900] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, +CFUN: 4
00> OK
00> 
00> [00:02:42.236,358] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:02:42.236,846] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:02:42.237,335] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:02:42.242,248] <dbg> at_cmd.at_write: Sending command AT+CFUN=21
00> [00:02:42.248,962] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=21
00> [00:02:42.278,717] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:02:42.279,144] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:02:42.279,693] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:02:42.280,120] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:02:43.596,191] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 32 bytes, +CEREG: 2,"8D07","0A459C0F",7
00> 
00> [00:02:43.596,984] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:02:43.597,412] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:02:44.214,111] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 56 bytes, +CEREG: 1,"8D07","0A459C0F",7,,,"00001000","11100000"
00> 
00> [00:02:44.215,026] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:02:44.215,484] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:02:46.237,945] <dbg> net_http.Data to send
00>                                   50 4f 53 54 20 2f 64 65  76 69 63 65 2f 61 70 69 |POST /de vice/api
00>                                   2f 76 30 2f 73 74 61 74  69 6f 6e 2f 70 6f 77 65 |/v0/stat ion/powe
00>                                   72 6f 6e 74 65 73 74 20  48 54 54 50 2f 31 2e 31 |rontest  HTTP/1.1
00>                                   0d 0a 48 6f 73 74 3a 20  61 70 69 2e 63 6c 6f 75 |..Host:  api.clou
00>                                   64 2e 63 61 6c 61 68 65  61 6c 74 68 2e 63 6f 6d |d.calahe alth.com
00>                                   0d 0a                                            |..               
00> [00:02:46.245,025] <dbg> net_http.Data to send
00>                                   0d 0a                                            |..               
00> [00:02:46.246,551] <inf> slm_at_host: Enter datamode
00> [00:02:46.248,504] <dbg> net_http.http_client_req: (0x200151a8): Sent 134 bytes
00> [00:02:46.249,969] <inf> slm_at_host: Raw send 1
00> [00:02:46.250,885] <inf> slm_httpc: datamode send: 0
00> [00:02:46.275,573] <inf> slm_at_host: Raw send 255
00> [00:02:46.276,702] <inf> slm_httpc: datamode send: 0
00> [00:02:46.277,648] <inf> slm_at_host: Raw send 1
00> [00:02:46.278,869] <inf> slm_httpc: datamode send: 0
00> [00:02:56.249,359] <dbg> net_http.http_wait_data: Connection error (116)
00> [00:02:56.249,816] <dbg> net_http.http_client_req: (0x200151a8): Wait data failure (-116)
00> *** Booting Zephyr OS build v2.6.99-ncs1  ***
00> 
00> [00:00:00.201,843] <dbg> at_cmd.at_cmd_driver_init: Common AT socket created
00> [00:00:00.202,270] <dbg> at_cmd.at_cmd_driver_init: Common AT socket processing thread created
00> [00:00:00.202,728] <dbg> at_cmd.at_cmd_set_notification_handler: Setting notification handler to 0x33d01
00> [00:00:00.203,247] <inf> slm: Serial LTE Modem
00> [00:00:00.212,463] <err> settings: set-value failure. key: slm/fota_type error(-2)
00> [00:00:00.223,327] <dbg> at_cmd.socket_thread_fn: AT socket thread started
00> [00:00:00.223,754] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:00.224,182] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:00.238,769] <dbg> at_cmd.at_write: Sending command AT+CGSN
00> [00:00:00.245,422] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CGSN
00> [00:00:00.245,941] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 22 bytes, 352656106104584
00> OK
00> 
00> [00:00:00.246,459] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:00.252,166] <inf> slm_at_host: at_host init done
00> [00:00:00.252,593] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:00.252,990] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:34.737,945] <dbg> at_cmd.at_write: Sending command AT
00> [00:00:34.744,689] <dbg> at_cmd.at_cmd_write: Awaiting response for AT
00> [00:00:34.745,147] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:00:34.745,605] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:34.746,154] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:34.746,582] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:34.754,577] <dbg> at_cmd.at_write: Sending command AT+CGMR
00> [00:00:34.761,260] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CGMR
00> [00:00:34.761,810] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 24 bytes, mfw_nrf9160_1.3.0
00> OK
00> 
00> [00:00:34.762,298] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:34.762,817] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:34.763,336] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:34.768,981] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
00> [00:00:34.775,695] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
00> [00:00:34.776,245] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:00:34.776,672] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:34.777,221] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:34.777,618] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:34.783,416] <dbg> at_cmd.at_write: Sending command AT+CEREG?
00> [00:00:34.790,100] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG?
00> [00:00:34.790,649] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 18 bytes, +CEREG: 5,4
00> OK
00> 
00> [00:00:34.791,137] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:34.791,625] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:34.792,144] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:34.797,302] <dbg> at_cmd.at_write: Sending command AT+CPSMS?
00> [00:00:34.803,985] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS?
00> [00:00:34.804,534] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 40 bytes, +CPSMS: 1,,,"10101010","00000101"
00> OK
00> 
00> [00:00:34.805,053] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:34.805,541] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:34.806,060] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:34.813,110] <dbg> at_cmd.at_write: Sending command AT+CFUN?
00> [00:00:34.819,824] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN?
00> [00:00:34.820,373] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, +CFUN: 0
00> OK
00> 
00> [00:00:34.820,831] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:34.821,350] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:34.821,868] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:46.827,117] <dbg> at_cmd.at_write: Sending command AT+CFUN=4
00> [00:00:46.833,801] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=4
00> [00:00:46.834,350] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:00:46.834,777] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:46.835,327] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:46.835,723] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:54.155,944] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
00> [00:00:54.162,658] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
00> [00:00:54.163,208] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:00:54.163,635] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:54.164,215] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:54.164,642] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:54.168,395] <dbg> at_cmd.at_write: Sending command AT+CEREG?
00> [00:00:54.169,403] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG?
00> [00:00:54.169,952] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 18 bytes, +CEREG: 5,4
00> OK
00> 
00> [00:00:54.170,410] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:54.170,928] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:54.171,417] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:54.176,574] <dbg> at_cmd.at_write: Sending command AT+CPSMS?
00> [00:00:54.183,258] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS?
00> [00:00:54.183,807] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 40 bytes, +CPSMS: 1,,,"10101010","00000101"
00> OK
00> 
00> [00:00:54.184,356] [0m<dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:54.184,875] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:54.185,394] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:54.192,413] <dbg> at_cmd.at_write: Sending command AT+CFUN?
00> [00:00:54.199,127] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN?
00> [00:00:54.199,676] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, +CFUN: 4
00> OK
00> 
00> [00:00:54.200,134] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:54.200,622] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:54.201,110] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:54.206,024] <dbg> at_cmd.at_write: Sending command AT+CFUN=21
00> [00:00:54.212,738] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=21
00> [00:00:54.242,523] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:00:54.242,950] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:54.243,499] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:54.243,927] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:55.697,387] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 32 bytes, +CEREG: 2,"8D07","0A459C0F",7
00> 
00> [00:00:55.698,211] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:55.698,638] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:56.669,555] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 56 bytes, +CEREG: 1,"8D07","0A459C0F",7,,,"00001000","11100000"
00> 
00> [00:00:56.670,440] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:56.670,898] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:58.531,799] <dbg> net_http.Data to send
00>                                   50 4f 53 54 20 2f 64 65  76 69 63 65 2f 61 70 69 |POST /de vice/api
00>                                   2f 76 30 2f 73 74 61 74  69 6f 6e 2f 70 6f 77 65 |/v0/stat ion/powe
00>                                   72 6f 6e 74 65 73 74 20  48 54 54 50 2f 31 2e 31 |rontest  HTTP/1.1
00>                                   0d 0a 48 6f 73 74 3a 20  61 70 69 2e 63 6c 6f 75 |..Host:  api.clou
00>                                   64 2e 63 61 6c 61 68 65  61 6c 74 68 2e 63 6f 6d |d.calahe alth.com
00>                                   0d 0a                                            |..               
00> [00:00:58.538,848] <dbg> net_http.Data to send
00>                                   0d 0a                                            |..               
00> [00:00:58.540,496] <inf> slm_at_host: Enter datamode
00> [00:00:58.543,823] <inf> slm_at_host: Raw send 1
00> [00:00:58.544,708] <inf> slm_httpc: datamode send: 0
00> [00:00:58.570,587] <inf> slm_at_host: Raw send 255
00> [00:00:58.571,716] <inf> slm_httpc: datamode send: 0
00> [00:00:58.596,923] <inf> slm_at_host: Raw send 256
00> [00:00:58.598,449] <inf> slm_httpc: datamode send: 0
00> [00:00:58.611,053] <inf> slm_at_host: Raw send 136
00> [00:00:58.612,243] <inf> slm_httpc: datamode send: 0
00> [00:00:58.613,220] <dbg> net_http.http_client_req: (0x200151a8): Sent 782 bytes
00> [00:00:59.096,496] <dbg> net_http.on_message_begin: (0x200151a8): -- HTTP POST response (headers) --
00> [00:00:59.097,015] <dbg> net_http.on_status: (0x200151a8): HTTP response status 200 OK
00> [00:00:59.098,052] <dbg> net_http.print_header_field: (0x200151a8): [4] Date
00> [00:00:59.099,060] <dbg> net_http.print_header_field: (0x200151a8): [29] Fri, 24 Sep 2021 17:57:36 GMT
00> [00:00:59.100,128] <dbg> net_http.print_header_field: (0x200151a8): [12] Content-Type
00> [00:00:59.101,135] <dbg> net_http.print_header_field: (0x200151a8): [16] application/json
00> [00:00:59.102,172] <dbg> net_http.print_header_field: (0x200151a8): [14] Content-Length
00> [00:00:59.103,179] <dbg> net_http.print_header_field: (0x200151a8): [2] 17
00> [00:00:59.104,156] <dbg> net_http.print_header_field: (0x200151a8): [10] Connection
00> [00:00:59.105,163] <dbg> net_http.print_header_field: (0x200151a8): [10] keep-alive
00> [00:00:59.106,140] <dbg> net_http.print_header_field: (0x200151a8): [10] Set-Cookie
00> [00:00:59.107,177] <dbg> net_http.print_header_field: (0x200151a8): [127] AWSALB=VKsmA/DSgDNF1qkNQ0v6IOjc6A4Qkbiy/H/GOFn1B66JllCv0/rKpWjQV3W/A8oig6HC0PmjiJA1/ZUC2Grwnqgcl88H+JHu8a9AzJxLoX/DetaQ8EQI0Gk9
00> [00:00:59.108,337] <dbg> net_http.print_header_field: (0x200151a8): [10] Set-Cookie
00> [00:00:59.109,252] <dbg> net_http.print_header_field: (0x200151a8): [127] AWSALBCORS=VKsmA/DSgDNF1qkNQ0v6IOjc6A4Qkbiy/H/GOFn1B66JllCv0/rKpWjQV3W/A8oig6HC0PmjiJA1/ZUC2Grwnqgcl88H+JHu8a9AzJxLoX/DetaQ8EQI
00> [00:00:59.110,321] <dbg> net_http.print_header_field: (0x200151a8): [6] Server
00> [00:00:59.111,053] <dbg> net_http.print_header_field: (0x200151a8): [12] nginx/1.17.6
00> [00:00:59.111,816] <dbg> net_http.print_header_field: (0x200151a8): [13] Cache-Control
00> [00:00:59.112,579] <dbg> net_http.print_header_field: (0x200151a8): [8] no-store
00> [00:00:59.113,281] <dbg> net_http.print_header_field: (0x200151a8): [15] X-Frame-Options
00> [00:00:59.114,013] <dbg> net_http.print_header_field: (0x200151a8): [10] SAMEORIGIN
00> [00:00:59.114,746] <dbg> net_http.print_header_field: (0x200151a8): [16] X-XSS-Protection
00> [00:00:59.115,447] <dbg> net_http.print_header_field: (0x200151a8): [13] 1; mode=block
00> [00:00:59.116,180] <dbg> net_http.print_header_field: (0x200151a8): [22] X-Content-Type-Options
00> [00:00:59.122,100] <dbg> net_http.print_header_field: (0x200151a8): [7] nosniff
00> [00:00:59.122,772] <dbg> net_http.print_header_field: (0x200151a8): [23] Content-Security-Policy
00> [00:00:59.123,443] <dbg> net_http.print_header_field: (0x200151a8): [18] default-src 'self'
00> [00:00:59.124,114] <dbg> net_http.print_header_field: (0x200151a8): [25] X-Content-Security-Policy
00> [00:00:59.124,816] <dbg> net_http.print_header_field: (0x200151a8): [18] default-src 'self'
00> [00:00:59.125,457] <dbg> net_http.print_header_field: (0x200151a8): [25] Strict-Transport-Security
00> [00:00:59.126,159] <dbg> net_http.print_header_field: (0x200151a8): [35] max-age=31556926; includeSubDomains
00> [00:00:59.126,831] <dbg> net_http.print_header_field: (0x200151a8): [15] Referrer-Policy
00> [00:00:59.127,410] <dbg> net_http.print_header_field: (0x200151a8): [31] strict-origin-when-cross-origin
00> [00:00:59.128,082] <dbg> net_http.print_header_field: (0x200151a8): [27] Access-Control-Allow-Origin
00> [00:00:59.128,692] <dbg> net_http.print_header_field: (0x200151a8): [1] *
00> [00:00:59.129,150] <dbg> net_http.on_headers_complete: (0x200151a8): Headers complete
00> [00:00:59.129,669] <dbg> net_http.on_body: (0x200151a8): Processed 17 length 17
00> [00:00:59.135,314] <dbg> net_http.on_body: (0x200151a8): Calling callback for partitioned 940 len data
00> [00:00:59.220,245] <dbg> net_http.on_message_complete: (0x200151a8): -- HTTP POST response (complete) --
00> [00:00:59.221,771] <dbg> net_http.http_client_req: (0x200151a8): Received 940 bytes
00> [00:00:59.229,949] <inf> slm_at_host: Raw send 16
00> [00:00:59.230,285] <wrn> slm_httpc: send unexpected payload
00> [00:00:59.230,651] <inf> slm_httpc: datamode send: 0
00> [00:00:59.232,391] <inf> slm_at_host: Exit datamode
00> [00:00:59.232,727] <inf> slm_httpc: HTTP thread terminated
00> [00:01:12.242,950] <dbg> at_cmd.at_write: Sending command AT
00> [00:01:12.249,694] <dbg> at_cmd.at_cmd_write: Awaiting response for AT
00> [00:01:12.250,152] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:12.250,579] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:12.251,129] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:12.251,556] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:12.261,596] <dbg> at_cmd.at_write: Sending command AT+CGMR
00> [00:01:12.268,280] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CGMR
00> [00:01:12.268,829] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 24 bytes, mfw_nrf9160_1.3.0
00> OK
00> 
00> [00:01:12.269,317] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:12.269,805] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:12.270,294] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:12.275,970] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
00> [00:01:12.282,684] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
00> [00:01:12.283,233] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:12.283,660] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:12.284,210] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:12.284,637] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:12.287,384] <dbg> at_cmd.at_write: Sending command AT+CEREG?
00> [00:01:12.289,428] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG?
00> [00:01:12.289,978] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 62 bytes, +CEREG: 5,1,"8D07","0A459C0F",7,,,"00001000","11100000"
00> OK
00> 
00> [00:01:12.290,557] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:12.291,076] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:12.291,564] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:12.300,567] <dbg> at_cmd.at_write: Sending command AT+CPSMS?
00> [00:01:12.307,250] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS?
00> [00:01:12.307,800] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 40 bytes, +CPSMS: 1,,,"10101010","00000101"
00> OK
00> 
00> [00:01:12.308,319] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:12.308,837] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:12.309,356] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:12.316,375] <dbg> at_cmd.at_write: Sending command AT+CFUN?
00> [00:01:12.323,089] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN?
00> [00:01:12.323,638] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, +CFUN: 1
00> OK
00> 
00> [00:01:12.324,096] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:12.324,584] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:12.325,073] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:24.330,352] <dbg> at_cmd.at_write: Sending command AT+CFUN=4
00> [00:01:24.337,036] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=4
00> [00:01:25.032,409] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 12 bytes, +CEREG: 0
00> 
00> [00:01:25.033,142] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:25.033,569] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:26.412,200] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:26.412,628] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:26.413,177] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:26.413,574] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:29.859,558] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
00> [00:01:29.866,271] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
00> [00:01:29.866,821] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:29.867,248] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:29.867,797] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:29.868,194] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:29.871,978] <dbg> at_cmd.at_write: Sending command AT+CEREG?
00> [00:01:29.873,016] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG?
00> [00:01:29.873,596] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 18 bytes, +CEREG: 5,0
00> OK
00> 
00> [00:01:29.874,084] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:29.874,572] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:29.875,091] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:29.880,249] <dbg> at_cmd.at_write: Sending command AT+CPSMS?
00> [00:01:29.886,932] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS?
00> [00:01:29.887,481] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 40 bytes, +CPSMS: 1,,,"10101010","00000101"
00> OK
00> 
00> [00:01:29.888,000] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:29.888,488] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:29.889,007] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:29.896,057] <dbg> at_cmd.at_write: Sending command AT+CFUN?
00> [00:01:29.902,770] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN?
00> [00:01:29.903,320] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, +CFUN: 4
00> OK
00> 
00> [00:01:29.903,778] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:29.904,266] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:29.904,754] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:29.909,667] <dbg> at_cmd.at_write: Sending command AT+CFUN=21
00> [00:01:29.916,381] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=21
00> [00:01:29.946,136] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:29.946,563] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:29.947,082] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:29.947,509] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:31.261,260] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 32 bytes, +CEREG: 2,"8D07","0A459C0F",7
00> 
00> [00:01:31.262,115] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:31.262,573] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:31.879,211] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 56 bytes, +CEREG: 1,"8D07","0A459C0F",7,,,"00001000","11100000"
00> 
00> [00:01:31.880,096] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:31.880,523] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:33.835,083] <dbg> net_http.Data to send
00>                                   50 4f 53 54 20 2f 64 65  76 69 63 65 2f 61 70 69 |POST /de vice/api
00>                                   2f 76 30 2f 73 74 61 74  69 6f 6e 2f 70 6f 77 65 |/v0/stat ion/powe
00>                                   72 6f 6e 74 65 73 74 20  48 54 54 50 2f 31 2e 31 |rontest  HTTP/1.1
00>                                   0d 0a 48 6f 73 74 3a 20  61 70 69 2e 63 6c 6f 75 |..Host:  api.clou
00>                                   64 2e 63 61 6c 61 68 65  61 6c 74 68 2e 63 6f 6d |d.calahe alth.com
00>                                   0d 0a                                            |..               
00> [00:01:33.842,132] <dbg> net_http.Data to send
00>                                   0d 0a                                            |..               
00> [00:01:33.843,658] <inf> slm_at_host: Enter datamode
00> [00:01:33.845,611] <dbg> net_http.http_client_req: (0x200151a8): Sent 134 bytes
00> [00:01:33.847,106] <inf> slm_at_host: Raw send 1
00> [00:01:33.847,991] <inf> slm_httpc: datamode send: 0
00> [00:01:33.873,046] <inf> slm_at_host: Raw send 255
00> [00:01:33.874,176] <inf> slm_httpc: datamode send: 0
00> [00:01:33.875,152] <inf> slm_at_host: Raw send 1[0m
00> [00:01:33.876,220] <inf> slm_httpc: datamode send: 0
00> [00:01:43.846,710] <dbg> net_http.http_wait_data: Connection error (116)
00> [00:01:43.847,137] <dbg> net_http.http_client_req: (0x200151a8): Wait data failure (-116)

# Logging stopped @ 24 Sep 2021 11: 0:48

Observations:

* I'm now getting an additional "#XDATAMODE: 0" after the data mode is exited.  This was not part of the protocol before.

* I enabled additional logging: CONFIG_AT_CMD_LOG_LEVEL_DBG=y

* Attached log includes 5-6 https attempts including a 1-2 resets that I initiated to restore the device to its initial state.

* In the attached log looking at the last 2 http sequences at the end of the log, after a reset there is 1 successful http request, and the on the second request the NCS immediately sends 134 bytes before my external mcu has actually sent any data.

First successful https request:

00> [00:00:58.531,799] <dbg> net_http.Data to send
00> 50 4f 53 54 20 2f 64 65 76 69 63 65 2f 61 70 69 |POST /de vice/api
00> 2f 76 30 2f 73 74 61 74 69 6f 6e 2f 70 6f 77 65 |/v0/stat ion/powe
00> 72 6f 6e 74 65 73 74 20 48 54 54 50 2f 31 2e 31 |rontest HTTP/1.1
00> 0d 0a 48 6f 73 74 3a 20 61 70 69 2e 63 6c 6f 75 |..Host: api.clou
00> 64 2e 63 61 6c 61 68 65 61 6c 74 68 2e 63 6f 6d |d.calahe alth.com
00> 0d 0a |..
00> [00:00:58.538,848] <dbg> net_http.Data to send
00> 0d 0a |..
00> [00:00:58.540,496] <inf> slm_at_host: Enter datamode
00> [00:00:58.543,823] <inf> slm_at_host: Raw send 1
00> [00:00:58.544,708] <inf> slm_httpc: datamode send: 0
00> [00:00:58.570,587] <inf> slm_at_host: Raw send 255
00> [00:00:58.571,716] <inf> slm_httpc: datamode send: 0
00> [00:00:58.596,923] <inf> slm_at_host: Raw send 256
00> [00:00:58.598,449] <inf> slm_httpc: datamode send: 0
00> [00:00:58.611,053] <inf> slm_at_host: Raw send 136
00> [00:00:58.612,243] <inf> slm_httpc: datamode send: 0
00> [00:00:58.613,220] <dbg> net_http.http_client_req: (0x200151a8): Sent 782 bytes
00> [00:00:59.096,496] <dbg> net_http.on_message_begin: (0x200151a8): -- HTTP POST response (headers) --
00> [00:00:59.097,015] <dbg> net_http.on_status: (0x200151a8): HTTP response status 200 OK

Second failure with immediate 134 byte transmission:

00> [00:01:31.880,523] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:33.835,083] <dbg> net_http.Data to send
00> 50 4f 53 54 20 2f 64 65 76 69 63 65 2f 61 70 69 |POST /de vice/api
00> 2f 76 30 2f 73 74 61 74 69 6f 6e 2f 70 6f 77 65 |/v0/stat ion/powe
00> 72 6f 6e 74 65 73 74 20 48 54 54 50 2f 31 2e 31 |rontest HTTP/1.1
00> 0d 0a 48 6f 73 74 3a 20 61 70 69 2e 63 6c 6f 75 |..Host: api.clou
00> 64 2e 63 61 6c 61 68 65 61 6c 74 68 2e 63 6f 6d |d.calahe alth.com
00> 0d 0a |..
00> [00:01:33.842,132] <dbg> net_http.Data to send
00> 0d 0a |..
00> [00:01:33.843,658] <inf> slm_at_host: Enter datamode
00> [00:01:33.845,611] <dbg> net_http.http_client_req: (0x200151a8): Sent 134 bytes
00> [00:01:33.847,106] <inf> slm_at_host: Raw send 1
00> [00:01:33.847,991] <inf> slm_httpc: datamode send: 0
00> [00:01:33.873,046] <inf> slm_at_host: Raw send 255
00> [00:01:33.874,176] <inf> slm_httpc: datamode send: 0
00> [00:01:33.875,152] <inf> slm_at_host: Raw send 1[0m
00> [00:01:33.876,220] <inf> slm_httpc: datamode send: 0
00> [00:01:43.846,710] <dbg> net_http.http_wait_data: Connection error (116)
00> [00:01:43.847,137] <dbg> net_http.http_client_req: (0x200151a8): Wait data failure (-116)

[Anthony Ambuehl]

Here is the another log, with only a single sequence:

* reset device

* go through sequence to send http  with successfull ok

* wait for my external mcu to return nrf9160 to idle state

* go through sequence to send http again.. this time external mcu only sends 256 bytes and then receives XHTTPCREQ: 0 when it still has data remaining to send.

In this case I disabled code that was adding extra "\r\n" after the XHTTPREQ body data, so there is no error about "unexpected payload" in ncs log.

Here are logs from my external mcu from the second sequence:

[00:01:01.952,000] <info> MODEM_NRF9160: state=24 rcvd=#XHTTPCCON: 1
[00:01:01.952,000] <info> MODEM_NRF9160: httpccon response matched=1 state=1 host= port=0 sec_tag=0
[00:01:01.953,000] <info> MODEM_NRF9160: state=24 rcvd=
[00:01:01.953,000] <info> MODEM_NRF9160: state=24 rcvd=OK
[00:01:01.953,000] <info> MODEM_NRF9160: Received OK
[00:01:01.953,000] <info> MODEM_NRF9160: state 24->25
[00:01:01.953,000] <info> MODEM_NRF9160: tx:AT
[00:01:01.953,000] <info> MODEM_NRF9160: tx:#XHTTPCREQ
[00:01:01.953,000] <info> MODEM_NRF9160: tx:=
[00:01:01.954,000] <info> MODEM_NRF9160: tx:"POST","/device/api/v0/station/powerontest","User-Agent: SLM/1.2.0
Accept: application/json
Content-Type: application/octet-stream
x-boundary: --[00:01:01.977,000] <info> MODEM_NRF9160: state=26 rcvd=
[00:01:01.977,000] <info> MODEM_NRF9160: state=26 rcvd=OK
[00:01:01.977,000] <info> MODEM_NRF9160: Received OK
[00:01:01.986,000] <info> MODEM_NRF9160: state=26 rcvd=
[00:01:01.987,000] <info> MODEM_NRF9160: state=26 rcvd=#XHTTPCREQ: 1
[00:01:01.988,000] <info> MODEM_NRF9160: httpcreq response matched=1 more_data=1
[00:01:01.988,000] <info> MODEM_NRF9160: state 26->27
[00:01:01.988,000] <info> HTTP_MODEM: evt 0
[00:01:01.988,000] <info> HTTP_MODEM: state 3->5
[00:01:01.989,000] <info> HTTP_MODEM: sent payload 256
[00:01:01.989,000] <info> HTTP_MODEM: state 5->4
[00:01:01.990,000] <info> MODEM_NRF9160: state=27 rcvd=
[00:01:01.993,000] <info> MODEM_NRF9160: state=27 rcvd=#XHTTPCREQ: 0
[00:01:01.993,000] <info> MODEM_NRF9160: httpcreq response matched=1 more_data=0
[00:01:01.993,000] <info> MODEM_NRF9160:
[00:01:01.993,000] <info> MODEM_NRF9160: state=29 rcvd=OK
[00:01:01.993,000] <info> MODEM_NRF9160: Received OK
[00:01:01.993,000] <info> MODEM_NRF9160:
[00:01:02.000,000] <info> HTTP_MODEM: timeout state=4
[00:01:02.000,000] <info> HTTP_MODEM: state 4->5
[00:01:02.000,000] <info> HTTP_MODEM: sent payload 0

NCS log

Fullscreen ncs_sdk_170_2.log Download

# SEGGER J-Link RTT Viewer V6.94b Terminal Log File
# Compiled: 18:05:14 on Jan 26 2021
# Logging started @ 24 Sep 2021 11:15:01
00> *** Booting Zephyr OS build v2.6.99-ncs1  ***
00> 
00> [00:00:00.201,873] <dbg> at_cmd.at_cmd_driver_init: Common AT socket created
00> [00:00:00.202,301] <dbg> at_cmd.at_cmd_driver_init: Common AT socket processing thread created
00> [00:00:00.202,758] <dbg> at_cmd.at_cmd_set_notification_handler: Setting notification handler to 0x33d01
00> [00:00:00.203,277] <inf> slm: Serial LTE Modem
00> [00:00:00.212,493] <err> settings: set-value failure. key: slm/fota_type error(-2)
00> [00:00:00.223,388] <dbg> at_cmd.socket_thread_fn: AT socket thread started
00> [00:00:00.223,785] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:00.224,212] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:00.238,800] <dbg> at_cmd.at_write: Sending command AT+CGSN
00> [00:00:00.245,452] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CGSN
00> [00:00:00.245,971] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 22 bytes, 352656106104584
00> OK
00> 
00> [00:00:00.246,490] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:00.252,197] <inf> slm_at_host: at_host init done
00> [00:00:00.252,624] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:00.253,021] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:24.222,045] <dbg> at_cmd.at_write: Sending command AT
00> [00:00:24.228,790] <dbg> at_cmd.at_cmd_write: Awaiting response for AT
00> [00:00:24.229,248] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:00:24.229,705] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:24.230,255] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:24.230,682] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:24.238,677] <dbg> at_cmd.at_write: Sending command AT+CGMR
00> [00:00:24.245,361] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CGMR
00> [00:00:24.245,910] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 24 bytes, mfw_nrf9160_1.3.0
00> OK
00> 
00> [00:00:24.246,398] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:24.246,917] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:24.247,436] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:24.253,082] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
00> [00:00:24.259,796] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
00> [00:00:24.260,345] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:00:24.260,772] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:24.261,322] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:24.261,718] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:24.264,495] <dbg> at_cmd.at_write: Sending command AT+CEREG?
00> [00:00:24.266,540] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG?
00> [00:00:24.267,089] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 18 bytes, +CEREG: 5,4
00> OK
00> 
00> [00:00:24.267,578] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:24.268,096] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:24.268,585] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:24.273,742] <dbg> at_cmd.at_write: Sending command AT+CPSMS?
00> [00:00:24.280,426] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS?
00> [00:00:24.280,975] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 40 bytes, +CPSMS: 1,,,"10101010","00000101"
00> OK
00> 
00> [00:00:24.281,494] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:24.282,012] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:24.282,501] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:24.289,550] <dbg> at_cmd.at_write: Sending command AT+CFUN?
00> [00:00:24.296,264] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN?
00> [00:00:24.296,813] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, +CFUN: 0
00> OK
00> 
00> [00:00:24.297,271] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:24.297,790] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:24.298,309] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:36.303,558] <dbg> at_cmd.at_write: Sending command AT+CFUN=4
00> [00:00:36.310,241] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=4
00> [00:00:36.310,791] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:00:36.311,218] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:36.311,767] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:36.312,164] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:41.324,157] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
00> [00:00:41.330,871] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
00> [00:00:41.331,420] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:00:41.331,848] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:41.332,427] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:41.332,855] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:41.336,608] <dbg> at_cmd.at_write: Sending command AT+CEREG?
00> [00:00:41.337,615] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG?
00> [00:00:41.338,165] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 18 bytes, +CEREG: 5,4
00> OK
00> 
00> [00:00:41.338,623] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:41.339,141] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:41.339,630] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:41.349,822] <dbg> at_cmd.at_write: Sending command AT+CPSMS?
00> [00:00:41.356,506] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS?
00> [00:00:41.357,055] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 40 bytes, +CPSMS: 1,,,"10101010","00000101"
00> OK
00> 
00> [00:00:41.357,604] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:41.358,123] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:41.358,642] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:41.365,661] <dbg> at_cmd.at_write: Sending command AT+CFUN?
00> [00:00:41.372,375] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN?
00> [00:00:41.372,924] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, +CFUN: 4
00> OK
00> 
00> [00:00:41.373,382] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:41.373,870] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:41.374,359] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:41.379,272] <dbg> at_cmd.at_write: Sending command AT+CFUN=21
00> [00:00:41.385,986] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=21
00> [00:00:41.415,802] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:00:41.416,229] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:41.416,748] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:41.417,175] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:43.198,944] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 32 bytes, +CEREG: 2,"8D07","0A459C0F",7
00> 
00> [00:00:43.199,768] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:43.200,195] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:45.052,307] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 56 bytes, +CEREG: 1,"8D07","0A459C0F",7,,,"00001000","11100000"
00> 
00> [00:00:45.053,192] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:45.053,649] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:46.908,264] <dbg> net_http.Data to send
00>                                   50 4f 53 54 20 2f 64 65  76 69 63 65 2f 61 70 69 |POST /de vice/api
00>                                   2f 76 30 2f 73 74 61 74  69 6f 6e 2f 70 6f 77 65 |/v0/stat ion/powe
00>                                   72 6f 6e 74 65 73 74 20  48 54 54 50 2f 31 2e 31 |rontest  HTTP/1.1
00>                                   0d 0a 48 6f 73 74 3a 20  61 70 69 2e 63 6c 6f 75 |..Host:  api.clou
00>                                   64 2e 63 61 6c 61 68 65  61 6c 74 68 2e 63 6f 6d |d.calahe alth.com
00>                                   0d 0a                                            |..               
00> [00:00:46.915,252] <dbg> net_http.Data to send
00>                                   0d 0a                                            |..               
00> [00:00:46.916,809] <inf> slm_at_host: Enter datamode
00> [00:00:46.920,288] <inf> slm_at_host: Raw send 1
00> [00:00:46.921,173] <inf> slm_httpc: datamode send: 0
00> [00:00:46.946,807] <inf> slm_at_host: Raw send 255
00> [00:00:46.948,120] <inf> slm_httpc: datamode send: 0
00> [00:00:46.973,114] <inf> slm_at_host: Raw send 256
00> [00:00:46.974,792] <inf> slm_httpc: datamode send: 0
00> [00:00:46.987,243] <inf> slm_at_host: Raw send 136
00> [00:00:46.988,311] <inf> slm_httpc: datamode send: 0
00> [00:00:46.989,288] <dbg> net_http.http_client_req: (0x200151a8): Sent 782 bytes
00> [00:00:47.468,719] <dbg> net_http.on_message_begin: (0x200151a8): -- HTTP POST response (headers) --
00> [00:00:47.469,238] <dbg> net_http.on_status: (0x200151a8): HTTP response status 200 OK
00> [00:00:47.470,275] <dbg> net_http.print_header_field: (0x200151a8): [4] Date
00> [00:00:47.471,313] <dbg> net_http.print_header_field: (0x200151a8): [29] Fri, 24 Sep 2021 18:15:52 GMT
00> [00:00:47.472,381] <dbg> net_http.print_header_field: (0x200151a8): [12] Content-Type
00> [00:00:47.473,388] <dbg> net_http.print_header_field: (0x200151a8): [16] application/json
00> [00:00:47.474,426] <dbg> net_http.print_header_field: (0x200151a8): [14] Content-Length
00> [00:00:47.475,433] <dbg> net_http.print_header_field: (0x200151a8): [2] 17
00> [00:00:47.476,409] <dbg> net_http.print_header_field: (0x200151a8): [10] Connection
00> [00:00:47.477,416] <dbg> net_http.print_header_field: (0x200151a8): [10] keep-alive
00> [00:00:47.478,424] <dbg> net_http.print_header_field: (0x200151a8): [10] Set-Cookie
00> [00:00:47.479,461] <dbg> net_http.print_header_field: (0x200151a8): [127] AWSALB=JXTgHPAx8hWmQvP+trSwwHi1CzIPkAFuXLDSMRDWiOKS61fmXVrPGLX0ZaGJW3ukoPvlkKy9KNwSn5Np6eQHARfwCOjDvWP1EyFZKp0dFLz/OYNZwb4xXxht
00> [00:00:47.480,621] <dbg> net_http.print_header_field: (0x200151a8): [10] Set-Cookie
00> [00:00:47.481,536] <dbg> net_http.print_header_field: (0x200151a8): [127] AWSALBCORS=JXTgHPAx8hWmQvP+trSwwHi1CzIPkAFuXLDSMRDWiOKS61fmXVrPGLX0ZaGJW3ukoPvlkKy9KNwSn5Np6eQHARfwCOjDvWP1EyFZKp0dFLz/OYNZwb4x
00> [00:00:47.482,604] <dbg> net_http.print_header_field: (0x200151a8): [6] Server
00> [00:00:47.483,337] <dbg> net_http.print_header_field: (0x200151a8): [12] nginx/1.17.6
00> [00:00:47.484,100] <dbg> net_http.print_header_field: (0x200151a8): [13] Cache-Control
00> [00:00:47.484,863] <dbg> net_http.print_header_field: (0x200151a8): [8] no-store
00> [00:00:47.485,565] <dbg> net_http.print_header_field: (0x200151a8): [15] X-Frame-Options
00> [00:00:47.486,328] <dbg> net_http.print_header_field: (0x200151a8): [10] SAMEORIGIN
00> [00:00:47.492,218] <dbg> net_http.print_header_field: (0x200151a8): [16] X-XSS-Protection
00> [00:00:47.492,980] <dbg> net_http.print_header_field: (0x200151a8): [13] 1; mode=block
00> [00:00:47.493,652] <dbg> net_http.print_header_field: (0x200151a8): [22] X-Content-Type-Options
00> [00:00:47.494,354] <dbg> net_http.print_header_field: (0x200151a8): [7] nosniff
00> [00:00:47.495,056] <dbg> net_http.print_header_field: (0x200151a8): [23] Content-Security-Policy
00> [00:00:47.495,697] <dbg> net_http.print_header_field: (0x200151a8): [18] default-src 'self'
00> [00:00:47.496,398] <dbg> net_http.print_header_field: (0x200151a8): [25] X-Content-Security-Policy
00> [00:00:47.497,100] <dbg> net_http.print_header_field: (0x200151a8): [18] default-src 'self'
00> [00:00:47.497,741] <dbg> net_http.print_header_field: (0x200151a8): [25] Strict-Transport-Security
00> [00:00:47.498,413] <dbg> net_http.print_header_field: (0x200151a8): [35] max-age=31556926; includeSubDomains
00> [00:00:47.499,114] <dbg> net_http.print_header_field: (0x200151a8): [15] Referrer-Policy
00> [00:00:47.499,694] <dbg> net_http.print_header_field: (0x200151a8): [31] strict-origin-when-cross-origin
00> [00:00:47.505,523] <dbg> net_http.print_header_field: (0x200151a8): [27] Access-Control-Allow-Origin
00> [00:00:47.506,134] <dbg> net_http.print_header_field: (0x200151a8): [1] *
00> [00:00:47.506,561] <dbg> net_http.on_headers_complete: (0x200151a8): Headers complete
00> [00:00:47.507,080] <dbg> net_http.on_body: (0x200151a8): Processed 17 length 17
00> [00:00:47.507,537] <dbg> net_http.on_body: (0x200151a8): Calling callback for partitioned 940 len data
00> [00:00:47.592,529] <dbg> net_http.on_message_complete: (0x200151a8): -- HTTP POST response (complete) --
00> [00:00:47.594,055] <dbg> net_http.http_client_req: (0x200151a8): Received 940 bytes
00> [00:00:47.601,257] <inf> slm_at_host: Raw send 16
00> [00:00:47.601,593] <wrn> slm_httpc: send unexpected payload
00> [00:00:47.601,959] <inf> slm_httpc: datamode send: 0
00> [00:00:47.604,705] <inf> slm_at_host: Exit datamode
00> [00:00:47.605,041] <inf> slm_httpc: HTTP thread terminated
00> [00:01:00.615,264] <dbg> at_cmd.at_write: Sending command AT
00> [00:01:00.622,009] <dbg> at_cmd.at_cmd_write: Awaiting response for AT
00> [00:01:00.622,467] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:00.622,894] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:00.623,443] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:00.623,870] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:00.635,925] <dbg> at_cmd.at_write: Sending command AT+CGMR
00> [00:01:00.642,608] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CGMR
00> [00:01:00.643,157] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 24 bytes, mfw_nrf9160_1.3.0
00> OK
00> 
00> [00:01:00.643,646] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:00.644,134] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:00.644,622] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:00.650,299] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
00> [00:01:00.657,012] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
00> [00:01:00.657,562] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:00.657,989] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:00.658,508] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:00.658,966] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:00.661,712] <dbg> at_cmd.at_write: Sending command AT+CEREG?
00> [00:01:00.663,757] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG?
00> [00:01:00.664,306] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 62 bytes, +CEREG: 5,1,"8D07","0A459C0F",7,,,"00001000","11100000"
00> OK
00> 
00> [00:01:00.664,886] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:00.665,405] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:00.665,893] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:00.674,896] <dbg> at_cmd.at_write: Sending command AT+CPSMS?
00> [00:01:00.680,541] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS?
00> [00:01:00.681,091] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 40 bytes, +CPSMS: 1,,,"10101010","00000101"
00> OK
00> 
00> [00:01:00.681,610] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:00.682,128] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:00.682,647] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:00.689,666] <dbg> at_cmd.at_write: Sending command AT+CFUN?
00> [00:01:00.696,380] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN?
00> [00:01:00.696,929] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, +CFUN: 1
00> OK
00> 
00> [00:01:00.697,387] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:00.697,875] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:00.698,364] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:12.703,643] <dbg> at_cmd.at_write: Sending command AT+CFUN=4
00> [00:01:12.710,327] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=4
00> [00:01:13.414,154] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 12 bytes, +CEREG: 0
00> 
00> [00:01:13.414,886] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:13.415,313] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:14.796,966] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:14.797,393] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:14.797,943] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:14.798,370] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:21.692,596] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
00> [00:01:21.699,310] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
00> [00:01:21.699,859] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:21.700,286] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:21.700,836] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:21.701,232] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:21.705,017] <dbg> at_cmd.at_write: Sending command AT+CEREG?
00> [00:01:21.706,054] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG?
00> [00:01:21.706,634] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 18 bytes, +CEREG: 5,0
00> OK
00> 
00> [00:01:21.707,122] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:21.707,611] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:21.708,129] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:21.713,287] <dbg> at_cmd.at_write: Sending command AT+CPSMS?
00> [00:01:21.719,970] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS?
00> [00:01:21.720,520] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 40 bytes, +CPSMS: 1,,,"10101010","00000101"
00> OK
00> 
00> [00:01:21.721,038] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:21.721,557] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:21.722,045] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:21.729,095] <dbg> at_cmd.at_write: Sending command AT+CFUN?
00> [00:01:21.735,809] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN?
00> [00:01:21.736,358] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, +CFUN: 4
00> OK
00> 
00> [00:01:21.736,816] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:21.737,304] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:21.737,792] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:21.742,706] <dbg> at_cmd.at_write: Sending command AT+CFUN=21
00> [00:01:21.749,420] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=21
00> [00:01:21.779,174] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:21.779,602] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:21.780,120] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:21.780,548] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:23.083,190] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 32 bytes, +CEREG: 2,"8D07","0A459C0F",7
00> 
00> [00:01:23.084,045] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:23.084,503] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:23.693,969] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 56 bytes, +CEREG: 1,"8D07","0A459C0F",7,,,"00001000","11100000"
00> 
00> [00:01:23.694,885] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:23.695,281] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:25.658,050] <dbg> net_http.Data to send
00>                                   50 4f 53 54 20 2f 64 65  76 69 63 65 2f 61 70 69 |POST /de vice/api
00>                                   2f 76 30 2f 73 74 61 74  69 6f 6e 2f 70 6f 77 65 |/v0/stat ion/powe
00>                                   72 6f 6e 74 65 73 74 20  48 54 54 50 2f 31 2e 31 |rontest  HTTP/1.1
00>                                   0d 0a 48 6f 73 74 3a 20  61 70 69 2e 63 6c 6f 75 |..Host:  api.clou
00>                                   64 2e 63 61 6c 61 68 65  61 6c 74 68 2e 63 6f 6d |d.calahe alth.com
00>                                   0d 0a                                            |..               
00> [00:01:25.665,008] <dbg> net_http.Data to send
00>                                   0d 0a                                            |..               
00> [00:01:25.666,534] <inf> slm_at_host: Enter datamode
00> [00:01:25.668,457] <dbg> net_http.http_client_req: (0x200151a8): Sent 134 bytes
00> [00:01:25.670,074] <inf> slm_at_host: Raw send 1
00> [00:01:25.670,959] <inf> slm_httpc: datamode send: 0
00> [00:01:25.695,587] <inf> slm_at_host: Raw send 255
00> [00:01:25.696,746] <inf> slm_httpc: datamode send: 0
00> [00:01:25.697,631] <inf> slm_at_host: Raw send 1
00> [00:01:25.698,760] <inf> slm_httpc: datamode send: 0
00> [00:01:35.668,273] <dbg> net_http.http_wait_data: Connection error (116)
00> [00:01:35.668,731] <dbg> net_http.http_client_req: (0x200151a8): Wait data failure (-116)

# Logging stopped @ 24 Sep 2021 11:17:40