This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

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?

0 Anthony Ambuehl over 2 years ago in reply to Anthony Ambuehl

I'm also finding that the datamode drops 1 byte and I have to send some additional data to get the send to complete. It seems the UART communication is not reliable even with HWFC enabled.

Here is an example where the data was sent, but the datamode is only completed after a timeout in my external mcu triggered sending an additional "\r\n"

00> [00:21:42.418,487] <inf> slm_at_host: Enter datamode
00> [00:21:42.448,516] <inf> slm_at_host: Raw send 256
00> [00:21:42.449,615] <inf> slm_httpc: datamode send: 0
00> [00:21:42.474,700] <inf> slm_at_host: Raw send 256
00> [00:21:42.476,409] <inf> slm_httpc: datamode send: 0
00> [00:21:42.498,901] <inf> slm_at_host: Raw send 135
00> [00:21:42.499,908] <inf> slm_httpc: datamode send: 0
00> [00:21:47.477,905] <inf> slm_at_host: Raw send 2
00> [00:21:47.478,240] <wrn> slm_httpc: send unexpected payload
00> [00:21:47.479,248] <inf> slm_httpc: datamode send: 0
00> [00:21:47.480,194] <dbg> net_http.http_client_req: (0x200151a8): Sent 782 bytes

I suppose I could force exit from data mode in this case and hopefully abort the http request, but the fundamental issue is that nrf9160 seems to be dropping 1 byte occasionally.

I will try to capture trace with logic analayzer next week to confirm the data is actually sent and dropped by nrf9160.

This seems to occur more often when I have my internal data send timer set to the same value as the UART_RX_TIMEOUT_MS, so potentially this is an issue that occurs when a UART_RX_TIMEOUT occurs. Does the UART_RX_TIMEOUT disable the uart port temporarily?
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel

0 Charlie over 2 years ago

Hi Anthony,

It seems you forgot to enable "CONFIG_SLM_LOG_LEVEL_DBG=y" on your prj.conf file. You should see messages like below when DEBUG level is set successfully.

[00:02:23.396,026] <dbg> slm_at_host.TX

I also did some tests with this issue recently, here are my steps:

1. Build and program the SLM application by adding the following configurations, modem firmware version 1.3.0, nRF9160DK 1.0.0.

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

2. Open LTE Link Monitor and J-Link RTT Viewer, program example.com CA Root, sec_tag 11.

3.Connect LTE newwork, build HTTPS connection to example.com through 443 prot, and send GET "index.html" requests three times.

Here you can find the AT Commands log from LinkMonitor and RTT log. The logs show that I can receive responses to GET requests from exmaple.com without any error.

Could you repeat this test? If everything is fine maybe you need to check from the server-side.

Fullscreen 2021-09-27T11_35_55.930Z-log.txt Download

2021-09-27T11:35:56.414Z INFO Application data folder: C:\Users\chs1\AppData\Roaming\nrfconnect\pc-nrfconnect-linkmonitor
2021-09-27T11:35:56.433Z DEBUG App pc-nrfconnect-linkmonitor v1.1.10 official
2021-09-27T11:35:56.433Z DEBUG App path: C:\Users\chs1\.nrfconnect-apps\node_modules\pc-nrfconnect-linkmonitor
2021-09-27T11:35:56.433Z DEBUG nRFConnect 3.7.1, required by the app is (^3.6.0)
2021-09-27T11:35:56.433Z DEBUG nRFConnect path: C:\Users\chs1\AppData\Local\Programs\nrfconnect\resources\app.asar
2021-09-27T11:35:56.433Z DEBUG HomeDir: C:\Users\chs1
2021-09-27T11:35:56.433Z DEBUG TmpDir: C:\Users\chs1\AppData\Local\Temp
2021-09-27T11:35:56.438Z VERBOSE Could not fetch serial number for serial port at COM1
2021-09-27T11:35:56.438Z VERBOSE Could not fetch serial number for serial port at COM3
2021-09-27T11:35:58.306Z INFO Modem port is opened
2021-09-27T11:35:58.311Z DEBUG modem >> AT+CFUN?
2021-09-27T11:35:58.330Z DEBUG modem << +CFUN: 0
2021-09-27T11:35:58.331Z DEBUG modem << OK
2021-09-27T11:36:05.882Z DEBUG modem << Ready
2021-09-27T11:36:24.973Z DEBUG modem << Ready
2021-09-27T11:36:31.329Z DEBUG modem >> AT+CFUN?
2021-09-27T11:36:31.346Z DEBUG modem << +CFUN: 0
2021-09-27T11:36:31.356Z DEBUG modem << OK
2021-09-27T11:36:56.888Z INFO Updating CA certificate...
2021-09-27T11:36:56.891Z DEBUG modem >> AT%CMNG=0,11,0,"-----BEGIN CERTIFICATE-----
2021-09-27T11:36:56.905Z DEBUG modem >> MIIDrzCCApegAwIBAgIQCDvgVpBCRrGhdWrJWZHHSjANBgkqhkiG9w0BAQUFADBh
2021-09-27T11:36:56.919Z DEBUG modem >> MQswCQYDVQQGEwJVUzEVMBMGA1UEChMMRGlnaUNlcnQgSW5jMRkwFwYDVQQLExB3
2021-09-27T11:36:56.932Z DEBUG modem >> d3cuZGlnaWNlcnQuY29tMSAwHgYDVQQDExdEaWdpQ2VydCBHbG9iYWwgUm9vdCBD
2021-09-27T11:36:56.947Z DEBUG modem >> QTAeFw0wNjExMTAwMDAwMDBaFw0zMTExMTAwMDAwMDBaMGExCzAJBgNVBAYTAlVT
2021-09-27T11:36:56.960Z DEBUG modem >> MRUwEwYDVQQKEwxEaWdpQ2VydCBJbmMxGTAXBgNVBAsTEHd3dy5kaWdpY2VydC5j
2021-09-27T11:36:56.975Z DEBUG modem >> b20xIDAeBgNVBAMTF0RpZ2lDZXJ0IEdsb2JhbCBSb290IENBMIIBIjANBgkqhkiG
2021-09-27T11:36:56.989Z DEBUG modem >> 9w0BAQEFAAOCAQ8AMIIBCgKCAQEA4jvhEXLeqKTTo1eqUKKPC3eQyaKl7hLOllsB
2021-09-27T11:36:57.003Z DEBUG modem >> CSDMAZOnTjC3U/dDxGkAV53ijSLdhwZAAIEJzs4bg7/fzTtxRuLWZscFs3YnFo97
2021-09-27T11:36:57.019Z DEBUG modem >> nh6Vfe63SKMI2tavegw5BmV/Sl0fvBf4q77uKNd0f3p4mVmFaG5cIzJLv07A6Fpt
2021-09-27T11:36:57.032Z DEBUG modem >> 43C/dxC//AH2hdmoRBBYMql1GNXRor5H4idq9Joz+EkIYIvUX7Q6hL+hqkpMfT7P
2021-09-27T11:36:57.046Z DEBUG modem >> T19sdl6gSzeRntwi5m3OFBqOasv+zbMUZBfHWymeMr/y7vrTC0LUq7dBMtoM1O/4
2021-09-27T11:36:57.059Z DEBUG modem >> gdW7jVg/tRvoSSiicNoxBN33shbyTApOB6jtSj1etX+jkMOvJwIDAQABo2MwYTAO
2021-09-27T11:36:57.072Z DEBUG modem >> BgNVHQ8BAf8EBAMCAYYwDwYDVR0TAQH/BAUwAwEB/zAdBgNVHQ4EFgQUA95QNVbR
2021-09-27T11:36:57.094Z DEBUG modem >> TLtm8KPiGxvDl7I90VUwHwYDVR0jBBgwFoAUA95QNVbRTLtm8KPiGxvDl7I90VUw
2021-09-27T11:36:57.107Z DEBUG modem >> DQYJKoZIhvcNAQEFBQADggEBAMucN6pIExIK+t1EnE9SsPTfrgT1eXkIoyQY/Esr
2021-09-27T11:36:57.123Z DEBUG modem >> hMAtudXH/vTBH1jLuG2cenTnmCmrEbXjcKChzUyImZOMkXDiqw8cvpOp/2PV5Adg
2021-09-27T11:36:57.139Z DEBUG modem >> 06O/nVsJ8dWO41P0jmP6P6fbtGbfYmbW0W5BjfIttep3Sp+dWOIrWcBAI+0tKIJF
2021-09-27T11:36:57.153Z DEBUG modem >> PnlUkiaY4IBIqDfv8NZ5YBberOgOzW6sRBc4L0na4UU+Krk2U886UAb3LujEV0ls
2021-09-27T11:36:57.167Z DEBUG modem >> YSEY1QSteDwsOoBrp+uvFRTp2InBuThs4pFsiv9kuXclVzDAGySj4dzp30d8tbQk
2021-09-27T11:36:57.181Z DEBUG modem >> CAUw7C29C79Fv1C5qfPrmAESrciIxpg0X40KPMbp1ZWVbd4=
2021-09-27T11:36:57.193Z DEBUG modem >> -----END CERTIFICATE-----"
2021-09-27T11:36:57.365Z DEBUG modem << OK
2021-09-27T11:36:57.366Z INFO Certificate update completed
2021-09-27T11:37:09.633Z DEBUG modem >> AT+CFUN?
2021-09-27T11:37:09.651Z DEBUG modem << +CFUN: 0
2021-09-27T11:37:09.657Z DEBUG modem << OK
2021-09-27T11:37:12.321Z DEBUG modem >> AT+CFUN=1
2021-09-27T11:37:12.373Z DEBUG modem << OK
2021-09-27T11:37:27.345Z DEBUG modem >> AT+CFUN?
2021-09-27T11:37:27.364Z DEBUG modem << +CFUN: 1
2021-09-27T11:37:27.369Z DEBUG modem << OK
2021-09-27T11:37:27.373Z DEBUG modem >> AT+CGSN=1
2021-09-27T11:37:27.389Z DEBUG modem << +CGSN: "352656106107108"
2021-09-27T11:37:27.392Z DEBUG modem << OK
2021-09-27T11:37:27.394Z DEBUG modem >> AT+CGMI
2021-09-27T11:37:27.411Z DEBUG modem << Nordic Semiconductor ASA
2021-09-27T11:37:27.412Z DEBUG modem << OK
2021-09-27T11:37:27.414Z DEBUG modem >> AT+CGMM
2021-09-27T11:37:27.424Z DEBUG modem << nRF9160-SICA
2021-09-27T11:37:27.425Z DEBUG modem << OK
2021-09-27T11:37:27.428Z DEBUG modem >> AT+CGMR
2021-09-27T11:37:27.443Z DEBUG modem << mfw_nrf9160_1.3.0
2021-09-27T11:37:27.444Z DEBUG modem << OK
2021-09-27T11:37:27.445Z INFO Nordic Semiconductor ASA nRF9160-SICA [mfw_nrf9160_1.3.0] SerNr: 352656106107108
2021-09-27T11:37:27.447Z DEBUG modem >> AT+CEMODE?
2021-09-27T11:37:27.458Z DEBUG modem << +CEMODE: 2
2021-09-27T11:37:27.459Z DEBUG modem << OK
2021-09-27T11:37:27.463Z DEBUG modem >> AT%XCBAND=?
2021-09-27T11:37:27.484Z DEBUG modem << %XCBAND: (1,2,3,4,5,8,12,13,18,19,20,25,26,28,66)
2021-09-27T11:37:27.485Z DEBUG modem << OK
2021-09-27T11:37:27.493Z DEBUG modem >> AT+CMEE?
2021-09-27T11:37:27.506Z DEBUG modem << +CMEE: 0
2021-09-27T11:37:27.507Z DEBUG modem << OK
2021-09-27T11:37:27.510Z DEBUG modem >> AT+CMEE=1
2021-09-27T11:37:27.518Z DEBUG modem << OK
2021-09-27T11:37:27.523Z DEBUG modem >> AT+CNEC?
2021-09-27T11:37:27.541Z DEBUG modem << +CNEC: 0
2021-09-27T11:37:27.542Z DEBUG modem << OK
2021-09-27T11:37:27.544Z DEBUG modem >> AT+CNEC=24
2021-09-27T11:37:27.560Z DEBUG modem << OK
2021-09-27T11:37:27.564Z DEBUG modem >> AT+CGEREP?
2021-09-27T11:37:27.583Z DEBUG modem << +CGEREP: 0,0
2021-09-27T11:37:27.584Z DEBUG modem << OK
2021-09-27T11:37:27.589Z DEBUG modem >> AT+CGDCONT?
2021-09-27T11:37:27.616Z DEBUG modem << +CGDCONT: 0,"IP","ibasis.iot","10.160.178.243",0,0
2021-09-27T11:37:27.617Z DEBUG modem << OK
2021-09-27T11:37:27.625Z DEBUG modem >> AT+CGACT?
2021-09-27T11:37:27.643Z DEBUG modem << +CGACT: 0,1
2021-09-27T11:37:27.644Z DEBUG modem << OK
2021-09-27T11:37:27.647Z DEBUG modem >> AT+CGEREP=1
2021-09-27T11:37:27.664Z DEBUG modem << OK
2021-09-27T11:37:27.666Z DEBUG modem >> AT+CIND=1,1,1
2021-09-27T11:37:27.683Z DEBUG modem << OK
2021-09-27T11:37:27.686Z DEBUG modem >> AT+CEREG=5
2021-09-27T11:37:27.700Z DEBUG modem << OK
2021-09-27T11:37:27.703Z DEBUG modem >> AT+CEREG?
2021-09-27T11:37:27.727Z DEBUG modem << +CEREG: 5,5,"0AF1","02010E16",7,,,"11100000","11100000"
2021-09-27T11:37:27.732Z DEBUG modem << OK
2021-09-27T11:37:27.745Z DEBUG modem >> AT+COPS=3,2
2021-09-27T11:37:27.756Z DEBUG modem << OK
2021-09-27T11:37:27.758Z DEBUG modem >> AT+COPS?
2021-09-27T11:37:27.773Z DEBUG modem << +COPS: 0,2,"24202",7
2021-09-27T11:37:27.775Z DEBUG modem << OK
2021-09-27T11:37:27.779Z DEBUG modem >> AT%XCBAND
2021-09-27T11:37:27.791Z DEBUG modem << %XCBAND: 20
2021-09-27T11:37:27.792Z DEBUG modem << OK
2021-09-27T11:37:27.796Z DEBUG modem >> AT+CGDCONT?
2021-09-27T11:37:27.812Z DEBUG modem << +CGDCONT: 0,"IP","ibasis.iot","10.160.178.243",0,0
2021-09-27T11:37:27.816Z DEBUG modem << 
2021-09-27T11:37:27.817Z DEBUG modem << OK
2021-09-27T11:37:27.820Z DEBUG modem >> AT+CGACT?
2021-09-27T11:37:27.835Z DEBUG modem << +CGACT: 0,1
2021-09-27T11:37:27.842Z DEBUG modem << OK
2021-09-27T11:37:27.849Z DEBUG modem >> AT%CESQ=1
2021-09-27T11:37:27.860Z DEBUG modem << OK
2021-09-27T11:37:27.863Z DEBUG modem >> AT+CESQ
2021-09-27T11:37:27.882Z DEBUG modem << +CESQ: 99,99,255,255,14,60
2021-09-27T11:37:27.886Z DEBUG modem << OK
2021-09-27T11:37:27.900Z DEBUG modem >> AT%XSIM=1
2021-09-27T11:37:27.913Z DEBUG modem << OK
2021-09-27T11:37:27.919Z DEBUG modem >> AT%XSIM?
2021-09-27T11:37:27.932Z DEBUG modem << %XSIM: 1
2021-09-27T11:37:27.933Z DEBUG modem << OK
2021-09-27T11:37:27.937Z DEBUG modem >> AT+CPIN?
2021-09-27T11:37:27.958Z DEBUG modem << +CPIN: READY
2021-09-27T11:37:27.960Z DEBUG modem << OK
2021-09-27T11:37:27.975Z DEBUG modem >> AT+CPINR="SIM PIN"
2021-09-27T11:37:28.005Z DEBUG modem << +CPINR: "SIM PIN",3
2021-09-27T11:37:28.006Z DEBUG modem << OK
2021-09-27T11:37:28.010Z DEBUG modem >> AT+CIMI
2021-09-27T11:37:28.032Z DEBUG modem << 204080813554054
2021-09-27T11:37:28.034Z DEBUG modem << OK
2021-09-27T11:37:28.036Z INFO IMSIdentity: 204080813554054
2021-09-27T11:37:28.072Z DEBUG modem << %CESQ: 60,3,11,1
2021-09-27T11:37:31.763Z DEBUG modem << %CESQ: 58,2,16,2
2021-09-27T11:37:49.410Z DEBUG modem >> AT#XHTTPCCON=1,"example.com",443,11
2021-09-27T11:37:50.411Z ERROR Error: 'AT#XHTTPCCON=1,"example.com",443,11
' timed out
2021-09-27T11:37:52.097Z DEBUG modem << #XHTTPCCON: 1
2021-09-27T11:37:52.099Z DEBUG modem << OK
2021-09-27T11:37:52.149Z DEBUG modem << %CESQ: 60,3,21,3
2021-09-27T11:38:00.565Z DEBUG modem << %CESQ: 58,2,16,2
2021-09-27T11:38:17.073Z DEBUG modem >> AT#XHTTPCREQ="GET","/index.html",""
2021-09-27T11:38:17.091Z DEBUG modem << OK
2021-09-27T11:38:17.107Z DEBUG modem << #XHTTPCREQ: 0
2021-09-27T11:38:19.166Z DEBUG modem << #XHTTPCRSP:335,0
2021-09-27T11:38:19.196Z DEBUG modem << HTTP/1.1 200 OK
2021-09-27T11:38:19.201Z DEBUG modem << Age: 481860
2021-09-27T11:38:19.202Z DEBUG modem << Cache-Control: max-age=604800
2021-09-27T11:38:19.204Z DEBUG modem << Content-Type: text/html; charset=UTF-8
2021-09-27T11:38:19.210Z DEBUG modem << Date: Mon, 27 Sep 2021 11:38:18 GMT
2021-09-27T11:38:19.211Z DEBUG modem << Etag: "3147526947+ident"
2021-09-27T11:38:19.212Z DEBUG modem << Expires: Mon, 04 Oct 2021 11:38:18 GMT
2021-09-27T11:38:19.216Z DEBUG modem << Last-Modified: Thu, 17 Oct 2019 07:18:26 GMT
2021-09-27T11:38:19.218Z DEBUG modem << Server: ECS (dcb/7F83)
2021-09-27T11:38:19.220Z DEBUG modem << Vary: Accept-Encoding
2021-09-27T11:38:19.225Z DEBUG modem << X-Cache: HIT
2021-09-27T11:38:19.227Z DEBUG modem << Content-Length: 1256
2021-09-27T11:38:19.228Z DEBUG modem << #XHTTPCRSP:689,0
2021-09-27T11:38:19.281Z DEBUG modem << <!doctype html>
2021-09-27T11:38:19.283Z DEBUG modem << <html>
2021-09-27T11:38:19.283Z DEBUG modem << <head>
2021-09-27T11:38:19.288Z DEBUG modem <<     <title>Example Domain</title>
2021-09-27T11:38:19.291Z DEBUG modem <<     <meta charset="utf-8" />
2021-09-27T11:38:19.293Z DEBUG modem <<     <meta http-equiv="Content-type" content="text/html; charset=utf-8" />
2021-09-27T11:38:19.298Z DEBUG modem <<     <m="viewport" content="width=device-width, initial-scale=1" />
2021-09-27T11:38:19.300Z DEBUG modem <<     <style type="text/css">
2021-09-27T11:38:19.303Z DEBUG modem <<     body {
2021-09-27T11:38:19.309Z DEBUG modem <<         background-color: #f0f0f2;
2021-09-27T11:38:19.310Z DEBUG modem <<         margin: 0;
2021-09-27T11:38:19.311Z DEBUG modem <<         padding: 0;
2021-09-27T11:38:19.321Z DEBUG modem <<         font-family: -apple-system, system-ui, BlinkMacSystemFont, "Segoe UI", "Open Sans", "Helvetica Neue", Helvetica, Arial, sans-serif;
2021-09-27T11:38:19.325Z DEBUG modem <<     }
2021-09-27T11:38:19.326Z DEBUG modem <<     div {
2021-09-27T11:38:19.327Z DEBUG modem <<         width: 600px;
2021-09-27T11:38:19.328Z DEBUG modem <<         margin: 5em auto;
2021-09-27T11:38:19.329Z DEBUG modem <<         padding: 2em;
2021-09-27T11:38:19.332Z DEBUG modem <<         background-color: #fdfdff;
2021-09-27T11:38:19.335Z DEBUG modem <<         border-radius: 0.5em;
2021-09-27T11:38:19.338Z DEBUG modem <<         box-shadow: 2px 3px 7px 2
2021-09-27T11:38:19.343Z DEBUG modem << #XHTTPCRSP:567,0
2021-09-27T11:38:19.392Z DEBUG modem << px rgba(0,0,0,0.02);
2021-09-27T11:38:19.394Z DEBUG modem <<     }
2021-09-27T11:38:19.394Z DEBUG modem <<     a:link, a:visited {
2021-09-27T11:38:19.398Z DEBUG modem <<         color: #38488f;
2021-09-27T11:38:19.399Z DEBUG modem <<         text-decoration: none;
2021-09-27T11:38:19.399Z DEBUG modem <<     }
2021-09-27T11:38:19.400Z DEBUG modem <<     @media (max-width: 700px) {
2021-09-27T11:38:19.400Z DEBUG modem <<         div {
2021-09-27T11:38:19.401Z DEBUG modem <<             margin: 0 auto;
2021-09-27T11:38:19.403Z DEBUG modem <<             width: auto;
2021-09-27T11:38:19.404Z DEBUG modem <<         }
2021-09-27T11:38:19.404Z DEBUG modem <<     }
2021-09-27T11:38:19.410Z DEBUG modem <<     </style>    
2021-09-27T11:38:19.412Z DEBUG modem << </head>
2021-09-27T11:38:19.412Z DEBUG modem << <body>
2021-09-27T11:38:19.412Z DEBUG modem << <div>
2021-09-27T11:38:19.412Z DEBUG modem <<     <h1>Example Domain</h1>
2021-09-27T11:38:19.418Z DEBUG modem <<     <p>This domain is for use in illustrative examples in documents. You may use this
2021-09-27T11:38:19.426Z DEBUG modem <<     domain in literature without prior coordination or asking for permission.</p>
2021-09-27T11:38:19.432Z DEBUG modem <<     <p><a href="https://www.iana.org/domains/example">More information...</a></p>
2021-09-27T11:38:19.433Z DEBUG modem << </div>
2021-09-27T11:38:19.433Z DEBUG modem << </body>
2021-09-27T11:38:19.434Z DEBUG modem << </html>
2021-09-27T11:38:19.437Z DEBUG modem << #XHTTPCRSP:0,1
2021-09-27T11:38:22.789Z DEBUG modem << %CESQ: 60,3,21,3
2021-09-27T11:38:23.479Z DEBUG modem << %CESQ: 59,2,16,2
2021-09-27T11:38:24.243Z DEBUG modem << %CESQ: 60,3,21,3
2021-09-27T11:38:29.065Z DEBUG modem >> AT#XHTTPCREQ="GET","/index.html",""
2021-09-27T11:38:29.079Z DEBUG modem << OK
2021-09-27T11:38:29.095Z DEBUG modem << #XHTTPCREQ: 0
2021-09-27T11:38:29.181Z DEBUG modem << %CESQ: 59,2,15,2
2021-09-27T11:38:30.387Z DEBUG modem << #XHTTPCRSP:335,0
2021-09-27T11:38:30.408Z DEBUG modem << HTTP/1.1 200 OK
2021-09-27T11:38:30.410Z DEBUG modem << Age: 481871
2021-09-27T11:38:30.413Z DEBUG modem << Cache-Control: max-age=604800
2021-09-27T11:38:30.414Z DEBUG modem << Content-Type: text/html; charset=UTF-8
2021-09-27T11:38:30.420Z DEBUG modem << Date: Mon, 27 Sep 2021 11:38:29 GMT
2021-09-27T11:38:30.421Z DEBUG modem << Etag: "3147526947+ident"
2021-09-27T11:38:30.422Z DEBUG modem << Expires: Mon, 04 Oct 2021 11:38:29 GMT
2021-09-27T11:38:30.423Z DEBUG modem << Last-Modified: Thu, 17 Oct 2019 07:18:26 GMT
2021-09-27T11:38:30.425Z DEBUG modem << Server: ECS (dcb/7F83)
2021-09-27T11:38:30.427Z DEBUG modem << Vary: Accept-Encoding
2021-09-27T11:38:30.428Z DEBUG modem << X-Cache: HIT
2021-09-27T11:38:30.431Z DEBUG modem << Content-Length: 1256
2021-09-27T11:38:30.437Z DEBUG modem << #XHTTPCRSP:689,0
2021-09-27T11:38:30.496Z DEBUG modem << <!doctype html>
2021-09-27T11:38:30.497Z DEBUG modem << <html>
2021-09-27T11:38:30.502Z DEBUG modem << <head>
2021-09-27T11:38:30.504Z DEBUG modem <<     <title>Example Domain</title>
2021-09-27T11:38:30.504Z DEBUG modem <<     <meta charset="utf-8" />
2021-09-27T11:38:30.505Z DEBUG modem <<     <meta http-equiv="Content-type" content="text/html; charset=utf-8" />
2021-09-27T11:38:30.511Z DEBUG modem <<     <meta name="viewport" content="width=device-width, initial-scale=1" />
2021-09-27T11:38:30.514Z DEBUG modem <<     <style type="text/css">
2021-09-27T11:38:30.520Z DEBUG modem <<     body {
2021-09-27T11:38:30.522Z DEBUG modem <<         background-color: #f0f0f2;
2021-09-27T11:38:30.522Z DEBUG modem <<         margin: 0;
2021-09-27T11:38:30.522Z DEBUG modem <<         padding: 0;
2021-09-27T11:38:30.537Z DEBUG modem <<         font-family: -apple-system, system-ui, BlinkMacSystemFont, "Segoe UI", "Open Sans", "Helvetica Neue", Helvetica, Arial, sans-serif;
2021-09-27T11:38:30.538Z DEBUG modem <<     }
2021-09-27T11:38:30.539Z DEBUG modem <<     div {
2021-09-27T11:38:30.540Z DEBUG modem <<         width: 600px;
2021-09-27T11:38:30.540Z DEBUG modem <<         margin: 5em auto;
2021-09-27T11:38:30.542Z DEBUG modem <<         padding: 2em;
2021-09-27T11:38:30.545Z DEBUG modem <<         background-color: #fdfdff;
2021-09-27T11:38:30.548Z DEBUG modem <<         border-radius: 0.5em;
2021-09-27T11:38:30.555Z DEBUG modem <<         box-shadow: 2px 3px 7px 2
2021-09-27T11:38:30.556Z DEBUG modem << #XHTTPCRSP:567,0
2021-09-27T11:38:30.599Z DEBUG modem << px rgba(0,0,0,0.02);
2021-09-27T11:38:30.600Z DEBUG modem <<     }
2021-09-27T11:38:30.606Z DEBUG modem <<     a:link, a:visited {
2021-09-27T11:38:30.607Z DEBUG modem <<         color: #38488f;
2021-09-27T11:38:30.608Z DEBUG modem <<         text-decoration: none;
2021-09-27T11:38:30.609Z DEBUG modem <<     }
2021-09-27T11:38:30.610Z DEBUG modem <<     @media (max-width: 700px) {
2021-09-27T11:38:30.611Z DEBUG modem <<         div {
2021-09-27T11:38:30.613Z DEBUG modem <<             margin: 0 auto;
2021-09-27T11:38:30.615Z DEBUG modem <<             width: auto;
2021-09-27T11:38:30.621Z DEBUG modem <<         }
2021-09-27T11:38:30.622Z DEBUG modem <<     }
2021-09-27T11:38:30.622Z DEBUG modem <<     </style>    
2021-09-27T11:38:30.622Z DEBUG modem << </head>
2021-09-27T11:38:30.623Z DEBUG modem << <body>
2021-09-27T11:38:30.623Z DEBUG modem << <div>
2021-09-27T11:38:30.624Z DEBUG modem <<     <h1>Example Domain</h1>
2021-09-27T11:38:30.630Z DEBUG modem <<     <p>This domain is for use in illustrative examples in documents. You may use this
2021-09-27T11:38:30.638Z DEBUG modem <<     domain in literature without prior coordination or asking for permission.</p>
2021-09-27T11:38:30.645Z DEBUG modem <<     <p><a href="https://www.iana.org/domains/example">More information...</a></p>
2021-09-27T11:38:30.646Z DEBUG modem << </div>
2021-09-27T11:38:30.647Z DEBUG modem << </body>
2021-09-27T11:38:30.647Z DEBUG modem << </html>
2021-09-27T11:38:30.648Z DEBUG modem << #XHTTPCRSP:0,1
2021-09-27T11:38:33.349Z DEBUG modem << %CESQ: 60,3,20,2
2021-09-27T11:38:38.964Z DEBUG modem << %CESQ: 59,2,15,2
2021-09-27T11:38:46.848Z DEBUG modem >> AT#XHTTPCREQ="GET","/index.html",""
2021-09-27T11:38:46.865Z DEBUG modem << OK
2021-09-27T11:38:46.879Z DEBUG modem << #XHTTPCREQ: 0
2021-09-27T11:38:46.964Z DEBUG modem << %CESQ: 58,2,21,3
2021-09-27T11:38:47.902Z DEBUG modem << #XHTTPCRSP:335,0
2021-09-27T11:38:47.938Z DEBUG modem << HTTP/1.1 200 OK
2021-09-27T11:38:47.939Z DEBUG modem << Age: 481889
2021-09-27T11:38:47.944Z DEBUG modem << Cache-Control: max-age=604800
2021-09-27T11:38:47.945Z DEBUG modem << Content-Type: text/html; charset=UTF-8
2021-09-27T11:38:47.946Z DEBUG modem << Date: Mon, 27 Sep 2021 11:38:47 GMT
2021-09-27T11:38:47.947Z DEBUG modem << Etag: "3147526947+ident"
2021-09-27T11:38:47.950Z DEBUG modem << Expires: Mon, 04 Oct 2021 11:38:47 GMT
2021-09-27T11:38:47.956Z DEBUG modem << Last-Modified: Thu, 17 Oct 2019 07:18:26 GMT
2021-09-27T11:38:47.957Z DEBUG modem << Server: ECS (dcb/7F83)
2021-09-27T11:38:47.958Z DEBUG modem << Vary: Accept-Encoding
2021-09-27T11:38:47.960Z DEBUG modem << X-Cache: HIT
2021-09-27T11:38:47.960Z DEBUG modem << Content-Length: 1256
2021-09-27T11:38:47.965Z DEBUG modem << #XHTTPCRSP:689,0
2021-09-27T11:38:48.022Z DEBUG modem << <!doctype html>
2021-09-27T11:38:48.023Z DEBUG modem << <html>
2021-09-27T11:38:48.030Z DEBUG modem << <head>
2021-09-27T11:38:48.031Z DEBUG modem <<     <title>Example Domain</title>
2021-09-27T11:38:48.032Z DEBUG modem <<     <meta charset="utf-8" />
2021-09-27T11:38:48.039Z DEBUG modem <<     <meta http-equiv="Content-type" content="text/html; charset=utf-8" />
2021-09-27T11:38:48.041Z DEBUG modem <<     <meta name="viewport" content="width=device-width, initial-scale=1" />
2021-09-27T11:38:48.044Z DEBUG modem <<     <style type="text/css">
2021-09-27T11:38:48.045Z DEBUG modem <<     body {
2021-09-27T11:38:48.047Z DEBUG modem <<         background-color: #f0f0f2;
2021-09-27T11:38:48.055Z DEBUG modem <<         margin: 0;
2021-09-27T11:38:48.057Z DEBUG modem <<         padding: 0;
2021-09-27T11:38:48.063Z DEBUG modem <<         font-family: -apple-system, system-ui, BlinkMacSystemFont, "Segoe UI", "Open Sans", "Helvetica Neue", Helvetica, Arial, sans-serif;
2021-09-27T11:38:48.064Z DEBUG modem <<     }
2021-09-27T11:38:48.065Z DEBUG modem <<     div {
2021-09-27T11:38:48.072Z DEBUG modem <<         width: 600px;
2021-09-27T11:38:48.074Z DEBUG modem <<         margin: 5em auto;
2021-09-27T11:38:48.074Z DEBUG modem <<         padding: 2em;
2021-09-27T11:38:48.076Z DEBUG modem <<         background-color: #fdfdff;
2021-09-27T11:38:48.077Z DEBUG modem <<         border-radius: 0.5em;
2021-09-27T11:38:48.081Z DEBUG modem <<         box-shadow: 2px 3px 7px 2
2021-09-27T11:38:48.083Z DEBUG modem << #XHTTPCRSP:567,0
2021-09-27T11:38:48.137Z DEBUG modem << px rgba(0,0,0,0.02);
2021-09-27T11:38:48.137Z DEBUG modem <<     }
2021-09-27T11:38:48.138Z DEBUG modem <<     a:link, a:visited {
2021-09-27T11:38:48.138Z DEBUG modem <<         color: #38488f;
2021-09-27T11:38:48.138Z DEBUG modem <<         text-decoration: none;
2021-09-27T11:38:48.139Z DEBUG modem <<     }
2021-09-27T11:38:48.140Z DEBUG modem <<     @media (max-width: 700px) {
2021-09-27T11:38:48.140Z DEBUG modem <<         div {
2021-09-27T11:38:48.143Z DEBUG modem <<             margin: 0 auto;
2021-09-27T11:38:48.145Z DEBUG modem <<             width: auto;
2021-09-27T11:38:48.146Z DEBUG modem <<         }
2021-09-27T11:38:48.146Z DEBUG modem <<     }
2021-09-27T11:38:48.148Z DEBUG modem <<     </style>    
2021-09-27T11:38:48.149Z DEBUG modem << </head>
2021-09-27T11:38:48.150Z DEBUG modem << <body>
2021-09-27T11:38:48.157Z DEBUG modem << <div>
2021-09-27T11:38:48.157Z DEBUG modem <<     <h1>Example Domain</h1>
2021-09-27T11:38:48.160Z DEBUG modem <<     <p>This domain is for use in illustrative examples in documents. You may use this
2021-09-27T11:38:48.172Z DEBUG modem <<     domain in literature without prior coordination or asking for permission.</p>
2021-09-27T11:38:48.175Z DEBUG modem <<     <p><a href="https://www.iana.org/domains/example">More information...</a></p>
2021-09-27T11:38:48.176Z DEBUG modem << </div>
2021-09-27T11:38:48.176Z DEBUG modem << </body>
2021-09-27T11:38:48.177Z DEBUG modem << </html>
2021-09-27T11:38:48.178Z DEBUG modem << #XHTTPCRSP:0,1
2021-09-27T11:38:48.233Z DEBUG modem << %CESQ: 60,3,16,2
2021-09-27T11:38:52.404Z DEBUG modem << %CESQ: 59,2,21,3
2021-09-27T11:38:54.391Z INFO Modem port is closed
2021-09-27T12:13:03.468Z INFO Restoring from C:\Users\chs1\AppData\Roaming\nrfconnect\pc-nrfconnect-linkmonitor\logs\2021-09-27T11_35_55.930Z-log.txt

RTT_Log.txt

Best regards,

Charlie

0 Anthony Ambuehl over 2 years ago in reply to Charlie

Charlie,

The issue occurs when client is sending data to http server as HTTPS POST. You would also see this issue with PUT, but you will not see it with GET since there is no data body sent in a GET operation.

I found, that Invalid data is sent by the SLM if the external mcu has a delay after receiving #XHTTPCREQ: 1. When the UART_RX_TIMEOUT_MS occurs the slm_at_host sometimes send an old rx buffer even though no data has been sent yet.

In my environment, I was able to confirm that if I increase UART_RX_TIMEOUT_MS and guarantee that my external MCU sends data before the UART_RX_TIMEOUT_MS then the corrupt data is not sent. This demonstrates that the slm_at_host has issues with the timeout.

Furthermore I'm also finding that occasionally a single byte is lost in datamode when the data payload is larger such as 1550 bytes. This leads to the SLM remaining in datamode even though the external MCU has already sent all of the data. To recover from this scenario the external mcu must send extra bytes of data that is not part of the intended payload.
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel

0 Anthony Ambuehl over 2 years ago in reply to Charlie

Fullscreen ncs_sdk_170_4.log Download

# SEGGER J-Link RTT Viewer V6.94b Terminal Log File
# Compiled: 18:05:14 on Jan 26 2021
# Logging started @ 27 Sep 2021 10:55:00
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 0x341d1
00> [00:00:00.203,308] <inf> slm: Serial LTE Modem
00> [00:00:00.212,554] <err> settings: set-value failure. key: slm/fota_type error(-2)
00> [00:00:00.223,266] <dbg> slm_at_host.slm_at_host_init: UART baud: 115200 d/p/s-bits: 3/0/1 HWFC: 1
00> [00:00:00.224,060] <dbg> at_cmd.socket_thread_fn: AT socket thread started
00> [00:00:00.224,456] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:00.224,914] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:00.239,532] <dbg> at_cmd.at_write: Sending command AT+CGSN
00> [00:00:00.246,215] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CGSN
00> [00
(Connection lost)
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 0x341d1
00> [00:00:00.203,308] <inf> slm: Serial LTE Modem
00> [00:00:00.212,554] <err> settings: set-value failure. key: slm/fota_type error(-2)
00> [00:00:00.223,236] <dbg> slm_at_host.slm_at_host_init: UART baud: 115200 d/p/s-bits: 3/0/1 HWFC: 1
00> [00:00:00.224,029] <dbg> at_cmd.socket_thread_fn: AT socket thread started
00> [00:00:00.224,426] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:00.224,884] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:00.239,471] <dbg> at_cmd.at_write: Sending command AT+CGSN
00> [00:00:00.246,154] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CGSN
00> [00[00:00:21.731,079] <dbg> slm_at_host.RX
00>                                      41 54                                            |AT               
00> [00:00:21.731,994] <dbg> at_cmd.at_write: Sending command AT
00> [00:00:21.738,739] <dbg> at_cmd.at_cmd_write: Awaiting response for AT
00> [00:00:21.739,196] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:00:21.739,654] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:21.740,112] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:21.741,119] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:21.741,546] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:21.744,171] <dbg> slm_at_host.RX
00>                                      41 54 [00:00:21.744,659] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 23 58 53 4c 4d 56  45 52                   |AT#XSLMV ER      
00> [00:00:21.745,849] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 53 4c 4d 56  45 52 3a 20 22 31 2e 37 |..#XSLMV ER: "1.7
00>                                      2e 30 22 0d 0a                                   |.0"..            
00> [00:00:21.747,650] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:21.752,655] <dbg> slm_at_host.RX
00>                                      41 54[00:00:21.753,143] <dbg> slm_at_host.uart_callback: RX_DISABLED
00>  2b 43 47 4d 52                             |AT+CGMR          
00> [00:00:21.754,089] <dbg> at_cmd.at_write: Sending command AT+CGMR
00> [00:00:21.760,772] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CGMR
00> [00:00:21.761,322] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 24 bytes, mfw_nrf9160_1.3.0
00> OK
00> 
00> [00:00:21.761,810] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:21.762,268] <dbg> slm_at_host.TX
00>                                      0d 0a                                            |..               
00> [00:00:21.763,061] <dbg> slm_at_host.TX
00>                                      6d 66 77 5f 6e 72 66 39  31 36 30 5f 31 2e 33 2e |mfw_nrf9 160_1.3.
00>                                      30 0d 0a                                         |0..              
00> [00:00:21.764,831] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:21.765,777] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:21.766,204] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:21.769,653] <dbg> slm_at_host.RX
00>                                      41 5[00:00:21.770,141] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 4 2b 43 45 52 45 47  3d 35                   |AT+CEREG =5      
00> [00:00:21.771,240] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
00> [00:00:21.777,923] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
00> [00:00:21.778,472] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:00:21.778,900] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:21.779,357] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:21.780,334] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:21.780,761] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:21.783,355] <dbg> slm_at_host.RX
00>                                      41 54[00:00:21.783,843] <dbg> slm_at_host.uart_callback: RX_DISABLED
00>  2b 43 45 52 45 47  3f                      |AT+CEREG ?       
00> [00:00:21.784,881] <dbg> at_cmd.at_write: Sending command AT+CEREG?
00> [00:00:21.791,564] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG?
00> [00:00:21.792,114] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 18 bytes, +CEREG: 5,4
00> OK
00> 
00> [00:00:21.792,602] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:21.793,060] <dbg> slm_at_host.TX
00>                                      0d 0a                                            |..               
00> [00:00:21.793,884] <dbg> slm_at_host.TX
00>                                      2b 43 45 52 45 47 3a 20  35 2c 34 0d 0a          |+CEREG:  5,4..   
00> [00:00:21.795,074] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:21.795,989] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:21.796,569] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:21.799,377] <dbg> slm_at_host.RX
00>                                      41 54 [00:00:21.799,865] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 2b 43 50 53 4d 53  3f                      |AT+CPSMS ?       
00> [00:00:21.800,903] <dbg> at_cmd.at_write: Sending command AT+CPSMS?
00> [00:00:21.807,586] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS?
00> [00:00:21.808,135] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 40 bytes, +CPSMS: 1,,,"10101010","00000101"
00> OK
00> 
00> [00:00:21.808,685] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:21.809,112] <dbg> slm_at_host.TX
00>                                      0d 0a                                            |..               
00> [00:00:21.809,906] <dbg> slm_at_host.TX
00>                                      2b 43 50 53 4d 53 3a 20  31 2c 2c 2c 22 31 30 31 |+CPSMS:  1,,,"101
00>                                      30 31 30 31 30 22 2c 22  30 30 30 30 30 31 30 31 |01010"," 00000101
00>                                      22 0d 0a                                         |"..              
00> [00:00:21.812,530] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:21.813,415] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:21.813,873] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:21.818,725] <dbg> slm_at_host.RX
00>                                      41 [00:00:21.819,213] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 54 2b 43 46 55 4e 3f                          |AT+CFUN?         
00> [00:00:21.820,251] <dbg> at_cmd.at_write: Sending command AT+CFUN?
00> [00:00:21.826,934] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN?
00> [00:00:21.827,484] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, +CFUN: 0
00> OK
00> 
00> [00:00:21.827,941] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:21.828,399] <dbg> slm_at_host.TX
00>                                      0d 0a                                            |..               
00> [00:00:21.829,162] <dbg> slm_at_host.TX
00>                                      2b 43 46 55 4e 3a 20 30  0d 0a                   |+CFUN: 0 ..      
00> [00:00:21.830,261] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:21.831,268] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:21.831,726] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:33.835,693] <dbg> slm_at_host.RX
00>                                      41 54 [00:00:33.836,181] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 2b 43 46 55 4e 3d  34                      |AT+CFUN= 4       
00> [00:00:33.837,219] <dbg> at_cmd.at_write: Sending command AT+CFUN=4
00> [00:00:33.843,902] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=4
00> [00:00:33.844,451] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:00:33.844,879] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:33.845,336] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:33.846,313] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:33.846,771] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:35.538,238] <dbg> slm_at_host.RX
00>                                      41 54 [00:00:35.538,726] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 2b 43 45 52 45 47  3d 35                   |AT+CEREG =5      
00> [00:00:35.539,825] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
00> [00:00:35.546,478] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
00> [00:00:35.547,027] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:00:35.547,454] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:35.547,912] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:35.548,889] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:35.549,316] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:35.552,917] <dbg> slm_at_host.RX
00>                                      41 [00:00:35.553,405] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 54 2b 43 45 52 45 47  3f                      |AT+CEREG ?       
00> [00:00:35.554,473] <dbg> at_cmd.at_write: Sending command AT+CEREG?
00> [00:00:35.561,157] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG?
00> [00:00:35.561,706] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 18 bytes, +CEREG: 5,4
00> OK
00> 
00> [00:00:35.562,194] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:35.562,622] <dbg> slm_at_host.TX
00>                                      0d 0a                                            |..               
00> [00:00:35.563,415] <dbg> slm_at_host.TX
00>                                      2b 43 45 52 45 47 3a 20  35 2c 34 0d 0a          |+CEREG:  5,4..   
00> [00:00:35.564,575] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:35.565,490] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:35.566,040] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:35.568,847] <dbg> slm_at_host.RX
00>                                      41 [00:00:35.569,335] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 54 2b 43 50 53 4d 53  3f                      |AT+CPSMS ?       
00> [00:00:35.570,434] <dbg> at_cmd.at_write: Sending command AT+CPSMS?
00> [00:00:35.577,117] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS?
00> [00:00:35.577,667] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 40 bytes, +CPSMS: 1,,,"10101010","00000101"
00> OK
00> 
00> [00:00:35.578,216] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:35.578,643] <dbg> slm_at_host.TX
00>                                      0d 0a                                            |..               
00> [00:00:35.579,437] <dbg> slm_at_host.TX
00>                                      2b 43 50 53 4d 53 3a 20  31 2c 2c 2c 22 31 30 31 |+CPSMS:  1,,,"101
00>                                      30 31 30 31 30 22 2c 22  30 30 30 30 30 31 30 31 |01010"," 00000101
00>                                      22 0d 0a                                         |"..              
00> [00:00:35.582,122] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:35.583,068] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:35.583,496] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:35.588,348] <dbg> slm_at_host.RX
00>                                      41 5[00:00:35.588,836] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 4 2b 43 46 55 4e 3f                          |AT+CFUN?         
00> [00:00:35.589,843] <dbg> at_cmd.at_write: Sending command AT+CFUN?
00> [00:00:35.596,496] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN?
00> [00:00:35.597,076] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, +CFUN: 4
00> OK
00> 
00> [00:00:35.597,534] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:35.598,022] <dbg> slm_at_host.TX
00>                                      0d 0a                                            |..               
00> [00:00:35.598,815] <dbg> slm_at_host.TX
00>                                      2b 43 46 55 4e 3a 20 34  0d 0a                   |+CFUN: 4 ..      
00> [00:00:35.599,884] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:35.600,860] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:35.601,287] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:35.603,912] <dbg> slm_at_host.RX
00>                                      41 5[00:00:35.604,400] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 4 2b 43 46 55 4e 3d  32 31                   |AT+CFUN= 21      
00> [00:00:35.605,499] <dbg> at_cmd.at_write: Sending command AT+CFUN=21
00> [00:00:35.612,213] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=21
00> [00:00:35.642,028] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:00:35.642,456] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:00:35.642,913] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:35.643,890] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:35.644,287] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:37.097,259] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 32 bytes, +CEREG: 2,"8D07","0A459C0F",7
00> 
00> [00:00:37.097,778] <dbg> slm_at_host.TX
00>                                      0d 0a                                            |..               
00> [00:00:37.098,602] <dbg> slm_at_host.TX
00>                                      2b 43 45 52 45 47 3a 20  32 2c 22 38 44 30 37 22 |+CEREG:  2,"8D07"
00>                                      2c 22 30 41 34 35 39 43  30 46 22 2c 37 0d 0a    |,"0A459C 0F",7.. 
00> [00:00:37.100,860] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:37.101,318] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:38.167,144] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 56 bytes, +CEREG: 1,"8D07","0A459C0F",7,,,"00001000","11100000"
00> 
00> [00:00:38.167,785] <dbg> slm_at_host.TX
00>                                      0d 0a                                            |..               
00> [00:00:38.168,548] <dbg> slm_at_host.TX
00>                                      2b 43 45 52 45 47 3a 20  31 2c 22 38 44 30 37 22 |+CEREG:  1,"8D07"
00>                                      2c 22 30 41 34 35 39 43  30 46 22 2c 37 2c 2c 2c |,"0A459C 0F",7,,,
00>                                      22 30 30 30 30 31 30 30  30 22 2c 22 31 31 31 30 |"0000100 0","1110
00>                                      30 30 30 30 22 0d 0a                             |0000"..          
00> [00:00:38.172,393] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:00:38.172,882] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:00:38.182,739] <dbg> slm_at_host.RX
00>                                      41 [00:00:38.183,227] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 54 23 58 48 54 54 50  43 43 4f 4e 3f          |AT#XHTTP CCON?   
00> [00:00:38.184,783] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 48 54 54 50  43 43 4f 4e 3a 20 30 2c |..#XHTTP CCON: 0,
00>                                      22 22 2c 30 2c 30 0d 0a                          |"",0,0..         
00> [00:00:38.186,645] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:38.196,929] <dbg> slm_at_host.RX
00>                                      41 5[00:00:38.197,448] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 4 23 58 48 54 54 50  43 43 4f 4e 3d 31 2c 22 |AT#XHTTP CCON=1,"
00>                                      61 70 69 2e 63 6c 6f 75  64 2e 63 61 6c 61 68 65 |api.clou d.calahe
00>                                      61 6c 74 68 2e 63 6f 6d  22 2c 34 34 33 2c 31    |alth.com ",443,1 
00> [00:00:38.201,354] <dbg> slm_httpc.do_http_connect: Configuring socket timeout (10 s)
00> [00:00:40.603,668] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 48 54 54 50  43 43 4f 4e 3a 20 31 0d |..#XHTTP CCON: 1.
00>                                      0a                                               |.                
00> [00:00:40.605,316] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:40.629,180] <dbg> slm_at_host.RX
00>                                      41 54 [00:00:40.629,699] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 23 58 48 54 54 50  43 52 45 51 3d 22 50 4f |AT#XHTTP CREQ="PO
00>                                      53 54 22 2c 22 2f 64 65  76 69 63 65 2f 61 70 69 |ST","/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 22  2c 22 55 73 65 72 2d 41 |rontest" ,"User-A
00>                                      67 65 6e 74 3a 20 53 4c  4d 2f 31 2e 32 2e 30 0d |gent: SL M/1.2.0.
00>                                      0a 41 63 63 65 70 74 3a  20 61 70 70 6c 69 63 61 |.Accept:  applica
00>                                      74 69 6f 6e 2f 6a 73 6f  6e 0d 0a 43 6f 6e 74 65 |tion/jso n..Conte
00>                                      6e 74 2d 54 79 70 65 3a  20 61 70 70 6c 69 63 61 |nt-Type:  applica
00>                                      74 69 6f 6e 2f 6f 63 74  65 74 2d 73 74 72 65 61 |tion/oct et-strea
00>                                      6d 0d 0a 78 2d 62 6f 75  6e 64 61 72 79 3a 20 2d |m..x-bou ndary: -
00>                                      2d 2d 2d 63 41 4c 61 42  30 75 4e 64 34 52 79 32 |---cALaB 0uNd4Ry2
00>                                      30 31 38 0d 0a 43 6f 6e  74 65 6e 74 2d 4c 65 6e |018..Con tent-Len
00>                                      67 74 68 3a 20 31 35 38  35 0d 0a 22 2c 31 35 38 |gth: 158 5..",158
00>                                      35                                               |5                
00> [00:00:40.643,615] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:40.644,683] <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:40.652,099] <dbg> slm_httpc.headers_cb: send header: 145 bytes
00> [00:00:40.652,526] <dbg> net_http.Data to send
00>                                   0d 0a                                            |..               
00> [00:00:40.654,022] <inf> slm_at_host: Enter datamode
00> [00:00:40.654,388] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 48 54 54 50  43 52 45 51 3a 20 31 0d |..#XHTTP CREQ: 1.
00>                                      0a                                               |.                
00> [00:00:40.656,127] <dbg> slm_httpc.payload_cb: wait until payload is ready
00> [00:00:40.686,706] <dbg> slm_at_host.uart_callback: RX_RDY 256
00> [00:00:40.687,164] <inf> slm_at_host: Raw send 256
00> [00:00:40.687,530] <dbg> slm_at_host.RX-DATAMODE
00>                                      2d 2d 2d 2d 2d 2d 63 41  4c 61 42 30 75 4e 64 34 |------cA LaB0uNd4
00> [00:00:40.689,605] <dbg> slm_httpc.do_send_payload: send 256 bytes payload
00> [00:00:40.690,032] <inf> slm_httpc: datamode send: 0
00> [00:00:40.690,429] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:40.713,958] <dbg> slm_at_host.uart_callback: RX_RDY 256
00> [00:00:40.714,447] <inf> slm_at_host: Raw send 256
00> [00:00:40.714,782] <dbg> slm_at_host.RX-DATAMODE
00>                                      37 34 35 36 36 34 33 31  44 37 30 44 33 31 41 43 |74566431 D70D31AC
00> [00:00:40.717,010] <dbg> slm_httpc.do_send_payload: send 256 bytes payload
00> [00:00:40.717,407] <inf> slm_httpc: datamode send: 0
00> [00:00:40.717,803] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:40.741,546] <dbg> slm_at_host.uart_callback: RX_RDY 256
00> [00:00:40.742,004] <inf> slm_at_host: Raw send 256
00> [00:00:40.742,370] <dbg> slm_at_host.RX-DATAMODE
00>                                      20 22 30 39 2d 38 39 2d  31 36 38 22 2c 0d 0a 22 | "09-89- 168",.."
00> [00:00:40.744,506] <dbg> slm_httpc.do_send_payload: send 256 bytes payload
00> [00:00:40.744,934] <inf> slm_httpc: datamode send: 0
00> [00:00:40.745,330] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:40.768,798] <dbg> slm_at_host.uart_callback: RX_RDY 256
00> [00:00:40.769,287] <inf> slm_at_host: Raw send 256
00> [00:00:40.769,622] <dbg> slm_at_host.RX-DATAMODE
00>                                      0d 0a 22 72 74 63 22 3a  20 7b 0d 0a 20 20 20 20 |.."rtc":  {..    
00> [00:00:40.771,820] <dbg> slm_httpc.do_send_payload: send 256 bytes payload
00> [00:00:40.772,247] <inf> slm_httpc: datamode send: 0
00> [00:00:40.772,644] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:40.796,081] <dbg> slm_at_host.uart_callback: RX_RDY 256
00> [00:00:40.796,539] <inf> slm_at_host: Raw send 256
00> [00:00:40.796,905] <dbg> slm_at_host.RX-DATAMODE
00>                                      22 2b 43 53 51 3a 20 31  39 2c 39 39 22 2c 0d 0a |"+CSQ: 1 9,99",..
00> [00:00:40.799,102] <dbg> slm_httpc.do_send_payload: send 256 bytes payload
00> [00:00:40.799,530] <inf> slm_httpc: datamode send: 0
00> [00:00:40.799,926] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:40.821,594] <dbg> slm_at_host.uart_callback: RX_RDY 256
00> [00:00:40.822,082] <inf> slm_at_host: Raw send 256
00> [00:00:40.822,418] <dbg> slm_at_host.RX-DATAMODE
00>                                      22 2c 0d 0a 20 20 22 73  75 62 73 79 73 74 65 6d |",..  "s ubsystem
00> [00:00:40.825,012] <dbg> slm_httpc.do_send_payload: send 256 bytes payload
00> [00:00:40.825,500] <inf> slm_httpc: datamode send: 0
00> [00:00:40.825,866] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:40.828,094] <dbg> slm_at_host.uart_callback: RX_RDY 48
00> [00:00:40.828,552] <inf> slm_at_host: Raw send 48
00> [00:00:40.828,887] <dbg> slm_at_host.RX-DATAMODE
00>                                      5a 22 2c 0d 0a 22 6c 61  73 74 5f 6b 65 79 22 3a |Z",.."la st_key":
00> [00:00:40.831,024] <dbg> slm_httpc.do_send_payload: send 48 bytes payload
00> [00:00:40.831,481] <inf> slm_httpc: datamode send: 0
00> [00:00:40.831,848] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:45.808,105] <dbg> slm_at_host.uart_callback: RX_RDY 2
00> [00:00:45.808,532] <inf> slm_at_host: Raw send 2
00> [00:00:45.808,898] <dbg> slm_at_host.RX-DATAMODE
00>                                      0d 0a                                            |..               
00> [00:00:45.809,722] <wrn> slm_httpc: send unexpected payload
00> [00:00:45.816,864] <dbg> slm_httpc.do_send_payload: send 1 bytes payload
00> [00:00:45.817,321] <dbg> slm_httpc.do_send_payload: Successfully send 1585 bytes payload
00> [00:00:45.817,779] <inf> slm_httpc: datamode send: 0
00> [00:00:45.818,145] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:45.819,122] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 48 54 54 50  43 52 45 51 3a 20 30 0d |..#XHTTP CREQ: 0.
00>                                      0a                                               |.                
00> [00:00:45.820,861] <dbg> net_http.http_client_req: (0x200151a8): Sent 1719 bytes
00> [00:00:47.578,063] <dbg> net_http.on_message_begin: (0x200151a8): -- HTTP POST response (headers) --
00> [00:00:47.578,643] <dbg> net_http.on_status: (0x200151a8): HTTP response status 200 OK
00> [00:00:47.579,681] <dbg> net_http.print_header_field: (0x200151a8): [4] Date
00> [00:00:47.580,718] <dbg> net_http.print_header_field: (0x200151a8): [29] Mon, 27 Sep 2021 17:56:05 GMT
00> [00:00:47.581,787] <dbg> net_http.print_header_field: (0x200151a8): [12] Content-Type
00> [00:00:47.582,824] <dbg> net_http.print_header_field: (0x200151a8): [16] application/json
00> [00:00:47.583,862] <dbg> net_http.print_header_field: (0x200151a8): [14] Content-Length
00> [00:00:47.584,869] <dbg> net_http.print_header_field: (0x200151a8): [2] 17
00> [00:00:47.585,845] <dbg> net_http.print_header_field: (0x200151a8): [10] Connection
00> [00:00:47.586,853] <dbg> net_http.print_header_field: (0x200151a8): [10] keep-alive
00> [00:00:47.587,829] <dbg> net_http.print_header_field: (0x200151a8): [10] Set-Cookie
00> [00:00:47.588,897] <dbg> net_http.print_header_field: (0x200151a8): [127] AWSALB=ogqvlB99Y029/2XO1WvhcREkIQWzAh8gFlN7+rKppsR7LfrC2U5efMhpekUV+PW+xL2r4jahuJBETpgn0NRxInf7cKZZzQIO8r4j8RYH3l9PBA/aW/znzHQt
00> [00:00:47.590,118] <dbg> net_http.print_header_field: (0x200151a8): [10] Set-Cookie
00> [00:00:47.591,094] <dbg> net_http.print_header_field: (0x200151a8): [127] AWSALBCORS=ogqvlB99Y029/2XO1WvhcREkIQWzAh8gFlN7+rKppsR7LfrC2U5efMhpekUV+PW+xL2r4jahuJBETpgn0NRxInf7cKZZzQIO8r4j8RYH3l9PBA/aW/zn
00> [00:00:47.592,193] <dbg> net_http.print_header_field: (0x200151a8): [6] Server
00> [00:00:47.592,926] <dbg> net_http.print_header_field: (0x200151a8): [12] nginx/1.17.6
00> [00:00:47.593,688] <dbg> net_http.print_header_field: (0x200151a8): [13] Cache-Control
00> [00:00:47.594,390] <dbg> net_http.print_header_field: (0x200151a8): [8] no-store
00> [00:00:47.595,153] <dbg> net_http.print_header_field: (0x200151a8): [15] X-Frame-Options
00> [00:00:47.595,886] <dbg> net_http.print_header_field: (0x200151a8): [10] SAMEORIGIN
00> [00:00:47.601,837] <dbg> net_http.print_header_field: (0x200151a8): [16] X-XSS-Protection
00> [00:00:47.602,539] <dbg> net_http.print_header_field: (0x200151a8): [13] 1; mode=block
00> [00:00:47.603,240] <dbg> net_http.print_header_field: (0x200151a8): [22] X-Content-Type-Options
00> [00:00:47.603,973] <dbg> net_http.print_header_field: (0x200151a8): [7] nosniff
00> [00:00:47.604,644] <dbg> net_http.print_header_field: (0x200151a8): [23] Content-Security-Policy
00> [00:00:47.605,346] <dbg> net_http.print_header_field: (0x200151a8): [18] default-src 'self'
00> [00:00:47.606,048] <dbg> net_http.print_header_field: (0x200151a8): [25] X-Content-Security-Policy
00> [00:00:47.606,689] <dbg> net_http.print_header_field: (0x200151a8): [18] default-src 'self'
00> [00:00:47.607,360] <dbg> net_http.print_header_field: (0x200151a8): [25] Strict-Transport-Security
00> [00:00:47.608,062] <dbg> net_http.print_header_field: (0x200151a8): [35] max-age=31556926; includeSubDomains
00> [00:00:47.608,703] <dbg> net_http.print_header_field: (0x200151a8): [15] Referrer-Policy
00> [00:00:47.609,344] <dbg> net_http.print_header_field: (0x200151a8): [31] strict-origin-when-cross-origin
00> [00:00:47.610,015] <dbg> net_http.print_header_field: (0x200151a8): [27] Access-Control-Allow-Origin
00> [00:00:47.610,595] <dbg> net_http.print_header_field: (0x200151a8): [1] *
00> [00:00:47.616,302] <dbg> net_http.on_headers_complete: (0x200151a8): Headers complete
00> [00:00:47.616,760] <dbg> net_http.on_body: (0x200151a8): Processed 17 length 17
00> [00:00:47.617,309] <dbg> net_http.on_body: (0x200151a8): Calling callback for partitioned 940 len data
00> [00:00:47.617,858] <dbg> slm_httpc.response_cb: Response data received (940 bytes)
00> [00:00:47.618,499] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 48 54 54 50  43 52 53 50 3a 39 32 33 |..#XHTTP CRSP:923
00>                                      2c 30 0d 0a                                      |,0..             
00> [00:00:47.620,361] <dbg> slm_at_host.TX
00>                                      48 54 54 50 2f 31 2e 31  20 32 30 30 20 4f 4b 0d |HTTP/1.1  200 OK.
00>                                      0a 44 61 74 65 3a 20 4d  6f 6e 2c 20 32 37 20 53 |.Date: M on, 27 S
00>                                      65 70 20 32 30 32 31 20  31 37 3a 35 36 3a 30 35 |ep 2021  17:56:05
00>                                      20 47 4d 54 0d 0a 43 6f  6e 74 65 6e 74 2d 54 79 | GMT..Co ntent-Ty
00>                                      70 65 3a 20 61 70 70 6c  69 63 61 74 69 6f 6e 2f |pe: appl ication/
00>                                      6a 73 6f 6e 0d 0a 43 6f  6e 74 65 6e 74 2d 4c 65 |json..Co ntent-Le
00>                                      6e 67 74 68 3a 20 31 37  0d 0a 43 6f 6e 6e 65 63 |ngth: 17 ..Connec
00>                                      74 69 6f 6e 3a 20 6b 65  65 70 2d 61 6c 69 76 65 |tion: ke ep-alive
00>                                      0d 0a 53 65 74 2d 43 6f  6f 6b 69 65 3a 20 41 57 |..Set-Co okie: AW
00>                                      53 41 4c 42 3d 6f 67 71  76 6c 42 39 39 59 30 32 |SALB=ogq vlB99Y02
00>                                      39 2f 32 58 4f 31 57 76  68 63 52 45 6b 49 51 57 |9/2XO1Wv hcREkIQW
00>                                      7a 41 68 38 67 46 6c 4e  37 2b 72 4b 70 70 73 52 |zAh8gFlN 7+rKppsR
00>                                      37 4c 66 72 43 32 55 35  65 66 4d 68 70 65 6b 55 |7LfrC2U5 efMhpekU
00>                                      56 2b 50 57 2b 78 4c 32  72 34 6a 61 68 75 4a 42 |V+PW+xL2 r4jahuJB
00>                                      45 54 70 67 6e 30 4e 52  78 49 6e 66 37 63 4b 5a |ETpgn0NR xInf7cKZ
00>                                      5a 7a 51 49 4f 38 72 34  6a 38 52 59 48 33 6c 39 |ZzQIO8r4 j8RYH3l9
00>                                      50 42 41 2f 61 57 2f 7a  6e 7a 48 51 74 43 31 70 |PBA/aW/z nzHQtC1p
00>                                      64 3b 20 45 78 70 69 72  65 73 3d 4d 6f 6e 2c 20 |d; Expir es=Mon, 
00>                                      30 34 20 4f 63 74 20 32  30 32 31 20 31 37 3a 35 |04 Oct 2 021 17:5
00>                                      35 3a 35 38 20 47 4d 54  3b 20 50 61 74 68 3d 2f |5:58 GMT ; Path=/
00>                                      0d 0a 53 65 74 2d 43 6f  6f 6b 69 65 3a 20 41 57 |..Set-Co okie: AW
00>                                      53 41 4c 42 43 4f 52 53  3d 6f 67 71 76 6c 42 39 |SALBCORS =ogqvlB9
00>                                      39 59 30 32 39 2f 32 58  4f 31 57 76 68 63 52 45 |9Y029/2X O1WvhcRE
00>                                      6b 49 51 57 7a 41 68 38  67 46 6c 4e 37 2b 72 4b |kIQWzAh8 gFlN7+rK
00>                                      70 70 73 52 37 4c 66 72  43 32 55 35 65 66 4d 68 |ppsR7Lfr C2U5efMh
00>                                      70 65 6b 55 56 2b 50 57  2b 78 4c 32 72 34 6a 61 |pekUV+PW +xL2r4ja
00>                                      68 75 4a 42 45 54 70 67  6e 30 4e 52 78 49 6e 66 |huJBETpg n0NRxInf
00>                                      37 63 4b 5a 5a 7a 51 49  4f 38 72 34 6a 38 52 59 |7cKZZzQI O8r4j8RY
00>                                      48 33 6c 39 50 42 41 2f  61 57 2f 7a 6e 7a 48 51 |H3l9PBA/ aW/znzHQ
00>                                      74 43 31 70 64 3b 20 45  78 70 69 72 65 73 3d 4d |tC1pd; E xpires=M
00>                                      6f 6e 2c 20 30 34 20 4f  63 74 20 32 30 32 31 20 |on, 04 O ct 2021 
00>                                      31 37 3a 35 35 3a 35 38  20 47 4d 54 3b 20 50 61 |17:55:58  GMT; Pa
00>                                      74 68 3d 2f 3b 20 53 61  6d 65 53 69 74 65 3d 4e |th=/; Sa meSite=N
00>                                      6f 6e 65 3b 20 53 65 63  75 72 65 0d 0a 53 65 72 |one; Sec ure..Ser
00>                                      76 65 72 3a 20 6e 67 69  6e 78 2f 31 2e 31 37 2e |ver: ngi nx/1.17.
00>                                      36 0d 0a 43 61 63 68 65  2d 43 6f 6e 74 72 6f 6c |6..Cache -Control
00>                                      3a 20 6e 6f 2d 73 74 6f  72 65 0d 0a 58 2d 46 72 |: no-sto re..X-Fr
00>                                      61 6d 65 2d 4f 70 74 69  6f 6e 73 3a 20 53 41 4d |ame-Opti ons: SAM
00>                                      45 4f 52 49 47 49 4e 0d  0a 58 2d 58 53 53 2d 50 |EORIGIN. .X-XSS-P
00>                                      72 6f 74 65 63 74 69 6f  6e 3a 20 31 3b 20 6d 6f |rotectio n: 1; mo
00>                                      64 65 3d 62 6c 6f 63 6b  0d 0a 58 2d 43 6f 6e 74 |de=block ..X-Cont
00>                                      65 6e 74 2d 54 79 70 65  2d 4f 70 74 69 6f 6e 73 |ent-Type -Options
00>                                      3a 20 6e 6f 73 6e 69 66  66 0d 0a 43 6f 6e 74 65 |: nosnif f..Conte
00>                                      6e 74 2d 53 65 63 75 72  69 74 79 2d 50 6f 6c 69 |nt-Secur ity-Poli
00>                                      63 79 3a 20 64 65 66 61  75 6c 74 2d 73 72 63 20 |cy: defa ult-src 
00>                                      27 73 65 6c 66 27 0d 0a  58 2d 43 6f 6e 74 65 6e |'self'.. X-Conten
00>                                      74 2d 53 65 63 75 72 69  74 79 2d 50 6f 6c 69 63 |t-Securi ty-Polic
00>                                      79 3a 20 64 65 66 61 75  6c 74 2d 73 72 63 20 27 |y: defau lt-src '
00>                                      73 65 6c 66 27 0d 0a 53  74 72 69 63 74 2d 54 72 |self'..S trict-Tr
00>                                      61 6e 73 70 6f 72 74 2d  53 65 63 75 72 69 74 79 |ansport- Security
00>                                      3a 20 6d 61 78 2d 61 67  65 3d 33 31 35 35 36 39 |: max-ag e=315569
00>                                      32 36 3b 20 69 6e 63 6c  75 64 65 53 75 62 44 6f |26; incl udeSubDo
00>                                      6d 61 69 6e 73 0d 0a 52  65 66 65 72 72 65 72 2d |mains..R eferrer-
00>                                      50 6f 6c 69 63 79 3a 20  73 74 72 69 63 74 2d 6f |Policy:  strict-o
00>                                      72 69 67 69 6e 2d 77 68  65 6e 2d 63 72 6f 73 73 |rigin-wh en-cross
00>                                      2d 6f 72 69 67 69 6e 0d  0a 41 63 63 65 73 73 2d |-origin. .Access-
00>                                      43 6f 6e 74 72 6f 6c 2d  41 6c 6c 6f 77 2d 4f 72 |Control- Allow-Or
00>                                      69 67 69 6e 3a 20 2a 0d  0a 0d 0a                |igin: *. ...     
00> [00:00:47.690,643] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 48 54 54 50  43 52 53 50 3a 31 37 2c |..#XHTTP CRSP:17,
00>                                      30 0d 0a                                         |0..              
00> [00:00:47.771,270] <dbg> slm_at_host.TX
00>                                      7b 22 73 74 61 74 75 73  22 3a 20 22 4f 4b 22 7d |{"status ": "OK"}
00>                                      0a                                               |.                
00> [00:00:47.773,010] <dbg> net_http.on_message_complete: (0x200151a8): -- HTTP POST response (complete) --
00> [00:00:47.773,559] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 48 54 54 50  43 52 53 50 3a 30 2c 31 |..#XHTTP CRSP:0,1
00>                                      0d 0a                                            |..               
00> [00:00:47.775,360] <dbg> net_http.http_client_req: (0x200151a8): Received 940 bytes
00> [00:00:47.776,397] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> [00:00:47.780,853] <dbg> slm_at_host.uart_callback: RX_RDY 16
00> [00:00:47.781,311] <inf> slm_at_host: Raw send 16
00> [00:00:47.781,646] <dbg> slm_at_host.RX-DATAMODE
00>                                      41 54 23 58 48 54 54 50  43 43 4f 4e 3d 30 0d 0a |AT#XHTTP CCON=0..
00> [00:00:47.782,958] <wrn> slm_httpc: send unexpected payload
00> [00:00:47.783,325] <dbg> slm_httpc.do_send_payload: Successfully send 1585 bytes payload
00> [00:00:47.783,782] <inf> slm_httpc: datamode send: 0
00> [00:00:47.784,179] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:00:47.786,010] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 44 41 54 41  4d 4f 44 45 3a 20 30 0d |..#XDATA MODE: 0.
00>                                      0a                                               |.                
00> [00:00:47.787,719] <inf> slm_at_host: Exit datamode
00> [00:00:47.788,085] <inf> slm_httpc: HTTP thread terminated
00> [00:01:00.792,480] <dbg> slm_at_host.RX
00>                                      41 54[00:01:00.792,968] <dbg> slm_at_host.uart_callback: RX_DISABLED
00>                                             |AT               
00> [00:01:00.793,731] <dbg> at_cmd.at_write: Sending command AT
00> [00:01:00.800,445] <dbg> at_cmd.at_cmd_write: Awaiting response for AT
00> [00:01:00.800,933] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:00.801,361] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:00.801,788] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:01:00.802,764] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:00.803,192] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:00.805,786] <dbg> slm_at_host.RX
00>                                      41 [00:01:00.806,274] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 54 23 58 53 4c 4d 56  45 52                   |AT#XSLMV ER      
00> [00:01:00.807,525] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 53 4c 4d 56  45 52 3a 20 22 31 2e 37 |..#XSLMV ER: "1.7
00>                                      2e 30 22 0d 0a                                   |.0"..            
00> [00:01:00.809,295] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:01:00.814,270] <dbg> slm_at_host.RX
00>                                      41 54 [00:01:00.814,758] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 2b 43 47 4d 52                             |AT+CGMR          
00> [00:01:00.815,704] <dbg> at_cmd.at_write: Sending command AT+CGMR
00> [00:01:00.822,387] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CGMR
00> [00:01:00.822,937] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 24 bytes, mfw_nrf9160_1.3.0
00> OK
00> 
00> [00:01:00.823,425] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:00.823,883] <dbg> slm_at_host.TX
00>                                      0d 0a                                            |..               
00> [00:01:00.824,645] <dbg> slm_at_host.TX
00>                                      6d 66 77 5f 6e 72 66 39  31 36 30 5f 31 2e 33 2e |mfw_nrf9 160_1.3.
00>                                      30 0d 0a                                         |0..              
00> [00:01:00.826,385] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:01:00.827,270] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:00.827,697] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:00.831,176] <dbg> slm_at_host.RX
00>                                      41 [00:01:00.831,665] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 54 2b 43 45 52 45 47  3d 35                   |AT+CEREG =5      
00> [00:01:00.832,794] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
00> [00:01:00.839,477] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
00> [00:01:00.840,026] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
00> 
00> [00:01:00.840,454] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:00.840,911] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:01:00.841,857] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:00.842,285] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:00.844,909] <dbg> slm_at_host.RX
00>                                      41 [00:01:00.845,397] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 54 2b 43 45 52 45 47  3f                      |AT+CEREG ?       
00> [00:01:00.846,466] <dbg> at_cmd.at_write: Sending command AT+CEREG?
00> [00:01:00.853,149] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG?
00> [00:01:00.853,698] <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.854,278] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:00.854,736] <dbg> slm_at_host.TX
00>                                      0d 0a                                            |..               
00> [00:01:00.855,529] <dbg> slm_at_host.TX
00>                                      2b 43 45 52 45 47 3a 20  35 2c 31 2c 22 38 44 30 |+CEREG:  5,1,"8D0
00>                                      37 22 2c 22 30 41 34 35  39 43 30 46 22 2c 37 2c |7","0A45 9C0F",7,
00>                                      2c 2c 22 30 30 30 30 31  30 30 30 22 2c 22 31 31 |,,"00001 000","11
00>                                      31 30 30 30 30 30 22 0d  0a                      |100000". .       
00> [00:01:00.859,283] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:01:00.860,198] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:00.860,626] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:00.867,401] <dbg> slm_at_host.RX
00>                                      41 54 2b 43 50 53 4d 53  3f                      |AT+CPSMS ?       
00> [00:01:00.868,927] <dbg> at_cmd.at_write: Sending command AT+CPSMS?
00> [00:01:00.875,610] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS?
00> [00:01:00.876,159] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 40 bytes, +CPSMS: 1,,,"10101010","00000101"
00> OK
00> 
00> [00:01:00.876,708] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:00.877,136] <dbg> slm_at_host.TX
00>                                      0d 0a                                            |..               
00> [00:01:00.877,960] <dbg> slm_at_host.TX
00>                                      2b 43 50 53 4d 53 3a 20  31 2c 2c 2c 22 31 30 31 |+CPSMS:  1,,,"101
00>                                      30 31 30 31 30 22 2c 22  30 30 30 30 30 31 30 31 |01010"," 00000101
00>                                      22 0d 0a                                         |"..              
00> [00:01:00.880,645] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:01:00.881,561] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:00.882,019] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:00.886,871] <dbg> slm_at_host.RX
00>                                      41 54 [00:01:00.887,359] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 2b 43 46 55 4e 3f                          |AT+CFUN?         
00> [00:01:00.888,366] <dbg> at_cmd.at_write: Sending command AT+CFUN?
00> [00:01:00.895,050] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN?
00> [00:01:00.895,599] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, +CFUN: 1
00> OK
00> 
00> [00:01:00.896,057] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
00> [00:01:00.896,514] <dbg> slm_at_host.TX
00>                                      0d 0a                                            |..               
00> [00:01:00.897,277] <dbg> slm_at_host.TX
00>                                      2b 43 46 55 4e 3a 20 31  0d 0a                   |+CFUN: 1 ..      
00> [00:01:00.898,345] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:01:00.899,322] <dbg> at_cmd.socket_thread_fn: Writing any pending command
00> [00:01:00.899,749] <dbg> at_cmd.socket_thread_fn: Listening on socket
00> [00:01:11.488,800] <dbg> slm_at_host.RX
00>                                      41 54[00:01:11.489,288] <dbg> slm_at_host.uart_callback: RX_DISABLED
00>  23 58 48 54 54 50  43 43 4f 4e 3f          |AT#XHTTP CCON?   
00> [00:01:11.490,844] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 48 54 54 50  43 43 4f 4e 3a 20 31 2c |..#XHTTP CCON: 1,
00>                                      22 61 70 69 2e 63 6c 6f  75 64 2e 63 61 6c 61 68 |"api.clo ud.calah
00>                                      65 61 6c 74 68 2e 63 6f  6d 22 2c 34 34 33 2c 31 |ealth.co m",443,1
00>                                      0d 0a                                            |..               
00> [00:01:11.494,293] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:01:11.502,838] <dbg> slm_at_host.RX
00>                                      41 5[00:01:11.503,326] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 4 23 58 48 54 54 50  43 43 4f 4e 3d 30       |AT#XHTTP CCON=0  
00> [00:01:11.512,390] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 48 54 54 50  43 43 4f 4e 3a 20 30 0d |..#XHTTP CCON: 0.
00>                                      0a                                               |.                
00> [00:01:11.514,007] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:01:11.519,653] <dbg> slm_at_host.RX
00>                                      41 54[00:01:11.520,141] <dbg> slm_at_host.uart_callback: RX_DISABLED
00>  23 58 48 54 54 50  43 43 4f 4e 3f          |AT#XHTTP CCON?   
00> [00:01:11.521,697] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 48 54 54 50  43 43 4f 4e 3a 20 30 2c |..#XHTTP CCON: 0,
00>                                      22 61 70 69 2e 63 6c 6f  75 64 2e 63 61 6c 61 68 |"api.clo ud.calah
00>                                      65 61 6c 74 68 2e 63 6f  6d 22 2c 34 34 33 2c 31 |ealth.co m",443,1
00>                                      0d 0a                                            |..               
00> [00:01:11.525,207] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:01:11.536,743] <dbg> slm_at_host.RX
00>                                      41 54 [00:01:11.537,261] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> 23 58 48 54 54 50  43 43 4f 4e 3d 31 2c 22 |AT#XHTTP CCON=1,"
00>                                      61 70 69 2e 63 6c 6f 75  64 2e 63 61 6c 61 68 65 |api.clou d.calahe
00>                                      61 6c 74 68 2e 63 6f 6d  22 2c 34 34 33 2c 31    |alth.com ",443,1 
00> [00:01:11.541,076] <dbg> slm_httpc.do_http_connect: Configuring socket timeout (10 s)
00> [00:01:14.420,227] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 48 54 54 50  43 43 4f 4e 3a 20 31 0d |..#XHTTP CCON: 1.
00>                                      0a                                               |.                
00> [00:01:14.421,905] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:01:14.445,739] <dbg> slm_at_host.RX
00>                                      41 54[00:01:14.446,258] <dbg> slm_at_host.uart_callback: RX_DISABLED
00>  23 58 48 54 54 50  43 52 45 51 3d 22 50 4f |AT#XHTTP CREQ="PO
00>                                      53 54 22 2c 22 2f 64 65  76 69 63 65 2f 61 70 69 |ST","/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 22  2c 22 55 73 65 72 2d 41 |rontest" ,"User-A
00>                                      67 65 6e 74 3a 20 53 4c  4d 2f 31 2e 32 2e 30 0d |gent: SL M/1.2.0.
00>                                      0a 41 63 63 65 70 74 3a  20 61 70 70 6c 69 63 61 |.Accept:  applica
00>                                      74 69 6f 6e 2f 6a 73 6f  6e 0d 0a 43 6f 6e 74 65 |tion/jso n..Conte
00>                                      6e 74 2d 54 79 70 65 3a  20 61 70 70 6c 69 63 61 |nt-Type:  applica
00>                                      74 69 6f 6e 2f 6f 63 74  65 74 2d 73 74 72 65 61 |tion/oct et-strea
00>                                      6d 0d 0a 78 2d 62 6f 75  6e 64 61 72 79 3a 20 2d |m..x-bou ndary: -
00>                                      2d 2d 2d 63 41 4c 61 42  30 75 4e 64 34 52 79 32 |---cALaB 0uNd4Ry2
00>                                      30 31 38 0d 0a 43 6f 6e  74 65 6e 74 2d 4c 65 6e |018..Con tent-Len
00>                                      67 74 68 3a 20 31 35 38  35 0d 0a 22 2c 31 35 38 |gth: 158 5..",158
00>                                      35                                               |5                
00> [00:01:14.460,174] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:01:14.461,212] <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:14.468,627] <dbg> slm_httpc.headers_cb: send header: 145 bytes
00> [00:01:14.469,055] <dbg> net_http.Data to send
00>                                   0d 0a                                            |..               
00> [00:01:14.470,611] <inf> slm_at_host: Enter datamode
00> [00:01:14.470,977] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 48 54 54 50  43 52 45 51 3a 20 31 0d |..#XHTTP CREQ: 1.
00>                                      0a                                               |.                
00> [00:01:14.472,686] <dbg> slm_httpc.payload_cb: wait until payload is ready
00> [00:01:14.473,114] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 48 54 54 50  43 52 45 51 3a 20 30 0d |..#XHTTP CREQ: 0.
00>                                      0a                                               |.                
00> [00:01:14.474,914] <dbg> net_http.http_client_req: (0x200151a8): Sent 134 bytes
00> [00:01:14.501,647] <dbg> slm_at_host.uart_callback: RX_RDY 256
00> [00:01:14.502,136] <inf> slm_at_host: Raw send 256
00> [00:01:14.502,471] <dbg> slm_at_host.RX-DATAMODE
00>                                      2d 2d 2d 2d 2d 2d 63 41  4c 61 42 30 75 4e 64 34 |------cA LaB0uNd4
00> [00:01:14.504,150] <dbg> slm_at_host.uart_callback: RX_RDY 1
00> [00:01:14.504,730] <dbg> slm_httpc.do_send_payload: send 256 bytes payload
00> [00:01:14.505,218] <inf> slm_httpc: datamode send: 0
00> [00:01:14.505,584] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:01:14.506,530] <inf> slm_at_host: Raw send 1
00> [00:01:14.506,896] <dbg> slm_at_host.RX-DATAMODE
00>                                      37                                               |7                
00> [00:01:14.508,514] <dbg> slm_httpc.do_send_payload: send 1 bytes payload
00> [00:01:14.508,941] <inf> slm_httpc: datamode send: 0
00> [00:01:14.509,338] <dbg> slm_at_host.TX
00>                                      0d 0a 4f 4b 0d 0a                                |..OK..           
00> [00:01:24.475,463] <dbg> net_http.http_wait_data: Connection error (116)
00> [00:01:24.475,891] <dbg> net_http.http_client_req: (0x200151a8): Wait data failure (-116)
00> [00:01:24.476,440] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 48 54 54 50  43 52 53 50 3a 20 30 2c |..#XHTTP CRSP: 0,
00>                                      2d 31 30 34 0d 0a                                |-104..           
00> [00:01:24.478,912] <dbg> slm_at_host.uart_callback: RX_DISABLED
00> [00:01:24.488,464] <dbg> slm_at_host.TX
00>                                      0d 0a 23 58 44 41 54 41  4d 4f 44 45 3a 20 30 0d |..#XDATA MODE: 0.
00>                                      0a                                               |.                

# Logging stopped @ 27 Sep 2021 11: 1:44

If you noticed in this log file, on the second HTTP, before any UART_RX_RDY there is line from http_cliet_req saying it has sent 134 bytes. This is actually data from the previous transfer that is being re-sent. That data is invalid and not part of this request.

00> [00:01:14.470,611] <inf> slm_at_host: Enter datamode
00> [00:01:14.470,977] <dbg> slm_at_host.TX
00> 0d 0a 23 58 48 54 54 50 43 52 45 51 3a 20 31 0d |..#XHTTP CREQ: 1.
00> 0a |.
00> [00:01:14.472,686] <dbg> slm_httpc.payload_cb: wait until payload is ready
00> [00:01:14.473,114] <dbg> slm_at_host.TX
00> 0d 0a 23 58 48 54 54 50 43 52 45 51 3a 20 30 0d |..#XHTTP CREQ: 0.
00> 0a |.
00> [00:01:14.474,914] <dbg> net_http.http_client_req: (0x200151a8): Sent 134 bytes
00> [00:01:14.501,647] <dbg> slm_at_host.uart_callback: RX_RDY 256
00> [00:01:14.502,136] <inf> slm_at_host: Raw send 256
00> [00:01:14.502,471] <dbg> slm_at_host.RX-DATAMODE
00> 2d 2d 2d 2d 2d 2d 63 41 4c 61 42 30 75 4e 64 34 |------cA LaB0uNd4
00> [00:01:14.504,150] <dbg> slm_at_host.uart_callback: RX_RDY 1

0 Anthony Ambuehl over 2 years ago in reply to Anthony Ambuehl

Here is the log showing the "better" behavior, if I increase UART_RX_TIMEOUT_MS to 10.

ncs_sdk_170_5.log

My code always sends the same data load. I ran the test multiple times in this log, and got different responses since the data was corrupted by dropped bytes.
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel