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

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?

  • Hi Anthony,

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

    Best regards,

    Charlie

  • 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

    2021-09-21T18_19_00.340Z-log.txt
    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
    
    nrfconnect-system-report-2021-09-21T18-25-02.054Z.txt
    # 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
    

  • 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 
  • I setup to test with 1.7.0 today.  I am getting interesting logs via J-Link RTT-Viewer.

    ncs_sdk_170.log
    # 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)

  • 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

    ncs_sdk_170_2.log
    # 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
    

Related