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,

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)