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?

Parents
  • 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 
  • 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

    # 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
    

Reply
  • 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

    # 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
    

Children
  • 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?

Related