websocket_client receives wrong data

Hi, I'm trying to send and receive on a websocket. Sending works fine and is received on the backend, but when I try to receive I just get garbage in my buffer.
I sanity tested the websocket message with both Postman and Python Websockets library, and the response looks correct in both examples. Exactly like this:
{"status":"Checking for new logs.","messageType":"requestCommRules","packets":["[192, 1, 0, 0, 3, 0, 208, 209]"]}

but as you can see in the trace output below, I just get something back that looks encrypted.

My code is extremely similar to the websocket client example:
(I removed irrelevant or sensitive parts of the code, hence why there are configs that seem unrelated to the websockets issue)

BOARD:
nrf9160dk/9160/ns

CONFIG:
# General
CONFIG_HEAP_MEM_POOL_SIZE=4096
CONFIG_MAIN_STACK_SIZE=4096

# Logging
CONFIG_LOG=y
CONFIG_MODEM=y
CONFIG_LOG_MODE_IMMEDIATE=y
# CONFIG_NRF_MODEM_LIB_TRACE=y
CONFIG_MODEM_LOG_LEVEL_DBG=y
CONFIG_NET_LOG=y
CONFIG_NET_SOCKETS_LOG_LEVEL_DBG=y
CONFIG_NET_HTTP_LOG_LEVEL_DBG=y
CONFIG_NET_WEBSOCKET_LOG_LEVEL_DBG=y
CONFIG_NET_CONTEXT_LOG_LEVEL_DBG=y
CONFIG_NET_TCP_LOG_LEVEL_DBG=y
CONFIG_LOG_BACKEND_UART=y

# Network
CONFIG_NETWORKING=y
CONFIG_NET_TCP=y
CONFIG_NET_SOCKETS=y
CONFIG_NET_SOCKETS_POSIX_NAMES=y
CONFIG_NET_IPV4=y
CONFIG_NET_CONNECTION_MANAGER=y
CONFIG_NET_CONNECTION_MANAGER_MONITOR_STACK_SIZE=1024
CONFIG_NET_BUF_DATA_SIZE=4096
CONFIG_LOG_BUFFER_SIZE=6000
CONFIG_NET_STATISTICS=y

# Websocket
CONFIG_WEBSOCKET_CLIENT=y
CONFIG_MQTT_LIB=y
CONFIG_MQTT_LIB_WEBSOCKET=y
CONFIG_MBEDTLS_SHA1_C=y

# UART
CONFIG_UART_ASYNC_API=y
CONFIG_UART_3_ASYNC=y
CONFIG_UART_3_INTERRUPT_DRIVEN=n
CONFIG_UART_3_NRF_HW_ASYNC=y
CONFIG_UART_3_NRF_HW_ASYNC_TIMER=2



SRC:
#define WSS_BODY_SIZE       256
#define WSS_HEADER_SIZE     30
static uint8_t wss_recv_buf[WSS_BODY_SIZE];
static uint8_t wss_temp_recv_buf[WSS_BODY_SIZE + WSS_HEADER_SIZE];

static void recv_data_wso_api(int sock) {
    uint64_t remaining = ULLONG_MAX;
    uint32_t message_type = 0;
    LOG_HEXDUMP_DBG(wss_recv_buf, sizeof(wss_recv_buf), "receive buffer before receiving");
    LOG_DBG("WAITING FOR MESSAGE... on socket: %d", sock);
    while (remaining > 0) {
        int ret = websocket_recv_msg(sock, wss_recv_buf, sizeof(wss_recv_buf), &message_type, &remaining, SYS_FOREVER_MS);
        LOG_DBG("Remaining: %lld, retval: %d", remaining, ret);
        if (ret < 0) {
            if (ret == -EAGAIN) {
                LOG_DBG("EAGAIN");
                k_sleep(K_MSEC(50));
                continue;
            }
            LOG_DBG("IPv4 connection closed while waiting (%d/%d)", ret, errno);
            break;
        }
        LOG_HEXDUMP_DBG(wss_recv_buf, sizeof(wss_recv_buf), "receive buffer after receiving");
        LOG_DBG("Received: %s", wss_recv_buf);
    }
}

static int setup_wss_socket() {
    struct addrinfo *res;
    struct addrinfo hints = {
        .ai_flags = AI_NUMERICSERV, /* Let getaddrinfo() set port */
        .ai_socktype = SOCK_STREAM,
    };
    char peer_addr[INET6_ADDRSTRLEN];

    LOG_DBG("Looking up %s", WSS_HOSTNAME);

    int err = getaddrinfo(WSS_HOSTNAME, HTTPS_PORT, &hints, &res);
    if (err) {
        LOG_ERR("getaddrinfo() failed, err %d", errno);
        return -1;
    }

    inet_ntop(res->ai_family, &((struct sockaddr_in *)(res->ai_addr))->sin_addr, peer_addr, INET6_ADDRSTRLEN);
    LOG_DBG("Resolved %s (%s)", peer_addr, net_family2str(res->ai_family));

    int fd = socket(res->ai_family, SOCK_STREAM, IPPROTO_TLS_1_2);
    LOG_DBG("Socket created: %d", fd);
    if (fd == -1) {
        LOG_ERR("Failed to open socket!");
        cleanup(fd, res);
        return -1;
    }

    int verify = NONE;
    err = setsockopt(fd, SOL_TLS, TLS_PEER_VERIFY, &verify, sizeof(verify));
    if (err) {
        LOG_ERR("Failed to setup peer verification, err %d", errno);
        cleanup(fd, res);
        return -1;
    }

    err = setsockopt(fd, SOL_TLS, TLS_HOSTNAME, WSS_HOSTNAME, sizeof(WSS_HOSTNAME) - 1);
    if (err) {
        LOG_ERR("Failed to setup TLS hostname, err %d", errno);
        cleanup(fd, res);
        return -1;
    }

    LOG_DBG("Connecting to %s:%d", WSS_HOSTNAME, ntohs(((struct sockaddr_in *)(res->ai_addr))->sin_port));
    err = connect(fd, res->ai_addr, res->ai_addrlen);
    if (err) {
        LOG_ERR("connect() failed, err: %d", errno);
        cleanup(fd, res);
        return -1;
    }
    return fd;
}

void start_websocket_communication() {
    int ws = -1;
    int32_t timeout = 10 * MSEC_PER_SEC;
    snprintf(auth_header, sizeof(auth_header), "Authorization: Bearer %s\r\n", auth_token);
    const char *extra_headers[] = {
        auth_header,
        "Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits\r\n",
        NULL
    };

    int fd = setup_wss_socket();

    if (fd < 0) {
        LOG_ERR("Cannot create HTTP connection.");
        k_sleep(K_FOREVER);
    }

    if (fd >= 0 && IS_ENABLED(CONFIG_NET_IPV4)) {
        struct websocket_request req;

        memset(&req, 0, sizeof(req));

        req.host = WSS_HOSTNAME;
        req.url = "/dev?appUUID=XXXXXX-XXXXXX-XXXXXX-XXXXXX";
        req.optional_headers = extra_headers;
        req.cb = wss_connect_cb;
        req.tmp_buf = wss_temp_recv_buf;
        req.tmp_buf_len = sizeof(wss_temp_recv_buf);

        ws = websocket_connect(fd, &req, timeout, "IPv4");
        if (ws < 0) {
            LOG_ERR("Cannot connect to %s", WSS_HOSTNAME);
            close(fd);
        }
    }

    if (ws < 0) {
        LOG_ERR("No IPv4 connectivity");
        k_sleep(K_FOREVER);
    }

    LOG_INF("Websocket IPv4 %d", ws);

    char initMsg[] = "{\"messageType\":\"init\",\"id\":\"id\",\"name\":\"name\"}";
    memcpy(wss_temp_recv_buf, initMsg, sizeof(initMsg));
    LOG_DBG("Sending JSON initMsg: %s", wss_temp_recv_buf);
    int ret = websocket_send_msg(ws, wss_temp_recv_buf, sizeof(wss_temp_recv_buf), WEBSOCKET_OPCODE_DATA_TEXT, true, true, SYS_FOREVER_MS);
   
    if (ret <= 0) {
        if (ret < 0) {
            LOG_ERR("IPv4 failed to send data using ws API");
        } else {
            LOG_DBG("IPv4 connection closed");
        }
        close(ws);
        close(fd);
        return;
    } else {
        LOG_DBG("IPv4 sent %d bytes", ret);
    }
   
    recv_data_wso_api(ws);

    close(ws);
    close(fd);
}

void setup_callbacks(void)
{
    /* Setup handler for Zephyr NET Connection Manager events. */
    net_mgmt_init_event_callback(&l4_cb, l4_event_handler, L4_EVENT_MASK);
    net_mgmt_add_event_callback(&l4_cb);

    /* Setup handler for Zephyr NET Connection Manager Connectivity layer. */
    net_mgmt_init_event_callback(&conn_cb, connectivity_event_handler, CONN_LAYER_EVENT_MASK);
    net_mgmt_add_event_callback(&conn_cb);
}

int main(void)
{

    LOG_INF("Starting LTE Application");
    LOG_INF("Software compilation date: %s %s", __DATE__, __TIME__);

    setup_callbacks();  

    LOG_INF("Bringing network interface up");

    conn_mgr_all_if_up(true);

    LOG_INF("Connecting to the network");
    conn_mgr_all_if_connect(true);

    k_sem_take(&network_connected_sem, K_FOREVER);

    start_websocket_communication();
}

TRACE OUTPUT:
[00:00:09.150,543] <ESC>[0m<dbg> lte_app: setup_wss_socket: Looking up XXXX.XXXX.com<ESC>[0m
[00:00:09.323,699] <ESC>[0m<dbg> lte_app: setup_wss_socket: Resolved XX.XX.XX.XX (AF_INET)<ESC>[0m
[00:00:09.331,970] <ESC>[0m<dbg> lte_app: setup_wss_socket: Socket created: 1<ESC>[0m
[00:00:09.338,836] <ESC>[0m<dbg> lte_app: setup_wss_socket: Connecting to XXXX.XXXX.com:443<ESC>[0m
[00:00:12.077,667] <ESC>[0m<dbg> net_http_client: http_send_data: Data to send
                                          47 45 54 20 2f 64 65 76  3f 61 70 70 55 55 49 44 |GET /dev ?appUUID
                                          3d 38 64 37 39 35 31 37  30 2d 38 30 39 37 2d 34 |=XXXXXXX X-XXXX-X
                                          62 39 65 2d 38 62 64 30  2d 61 38 32 34 65 31 65 |XXX-XXXX -XXXXXXX
                                          32 37 64 37 33 20 48 54  54 50 2f 31 2e 31 0d 0a |XXXXX HT TP/1.1..
                                          48 6f 73 74 3a 20 35 76  36 76 64 64 38 63 6c 69 |Host: XX XXXXXXXX
                                          2e 65 78 65 63 75 74 65  2d 61 70 69 2e 65 75 2d |XXXXXXXX -XXXXXX-
                                          63 65 6e 74 72 61 6c 2d  31 2e 61 6d 61 7a 6f 6e |XXXXXXX- XXXXXXXX
                                          61 77 73 2e 63 6f 6d 0d  0a 41 75 74 68 6f 72 69 |XXXXXXX. .Authori
                                          7a 61 74 69 6f 6e 3a 20  42 65 61 72 65 72 20 65 |zation:  Bearer e
                                          79 4a 72 61 57 51 69 4f  69 4a 45 63 48 41 7a 52 |y
                                         


<REDACTED>


                                                                                                ..Se c-WebSoc
                                          6b 65 74 2d 45 78 74 65  6e 73 69 6f 6e 73 3a 20 |ket-Exte nsions:
                                          70 65 72 6d 65 73 73 61  67 65 2d 64 65 66 6c 61 |permessa ge-defla
                                          74 65 3b 20 63 6c 69 65  6e 74 5f 6d 61 78 5f 77 |te; clie nt_max_w
                                          69 6e 64 6f 77 5f 62 69  74 73 0d 0a 53 65 63 2d |indow_bi ts..Sec-
                                          57 65 62 53 6f 63 6b 65  74 2d 4b 65 79 3a 20 67 |WebSocke t-Key: g<ESC>[0m
[00:00:12.944,427] <ESC>[0m<dbg> net_http_client: http_flush_data: Data to send
                                          42 66 44 33 47 58 4c 6a  64 46 30 41 73 4f 65 54 |BfD3GXLj dF0AsOeT
                                          33 55 42 41 51 3d 3d 0d  0a 55 70 67 72 61 64 65 |3UBAQ==. .Upgrade
                                          3a 20 77 65 62 73 6f 63  6b 65 74 0d 0a 43 6f 6e |: websoc ket..Con
                                          6e 65 63 74 69 6f 6e 3a  20 55 70 67 72 61 64 65 |nection:  Upgrade
                                          0d 0a 53 65 63 2d 57 65  62 53 6f 63 6b 65 74 2d |..Sec-We bSocket-
                                          56 65 72 73 69 6f 6e 3a  20 31 33 0d 0a 0d 0a    |Version:  13.... <ESC>[0m
[00:00:13.009,826] <ESC>[0m<dbg> net_http_client: http_client_req: (0x2000d2e0): Sent 1439 bytes<ESC>[0m
[00:00:13.264,099] <ESC>[0m<dbg> net_http_client: on_message_begin: (0x2000d2e0): -- HTTP GET response (headers) --<ESC>[0m
[00:00:13.274,291] <ESC>[0m<dbg> net_http_client: on_status: (0x2000d2e0): HTTP response status 101 Switching Protocols<ESC>[0m
[00:00:13.284,881] <ESC>[0m<dbg> net_http_client: print_header_field: (0x2000d2e0): [4] Date<ESC>[0m
[00:00:13.293,151] <ESC>[0m<dbg> net_http_client: print_header_field: (0x2000d2e0): [29] Tue, 22 Oct 2024 10:48:33 GMT<ESC>[0m
[00:00:13.303,649] <ESC>[0m<dbg> net_http_client: print_header_field: (0x2000d2e0): [10] Connection<ESC>[0m
[00:00:13.312,500] <ESC>[0m<dbg> net_http_client: print_header_field: (0x2000d2e0): [7] upgrade<ESC>[0m
[00:00:13.320,983] <ESC>[0m<dbg> net_http_client: print_header_field: (0x2000d2e0): [7] upgrade<ESC>[0m
[00:00:13.329,467] <ESC>[0m<dbg> net_http_client: print_header_field: (0x2000d2e0): [9] websocket<ESC>[0m
[00:00:13.338,134] <ESC>[0m<dbg> net_http_client: print_header_field: (0x2000d2e0): [20] sec-websocket-accept<ESC>[0m
[00:00:13.347,839] <ESC>[0m<dbg> net_http_client: print_header_field: (0x2000d2e0): [28] 8hDDT21JDC5jDoPXslfSJW3xfv4=<ESC>[0m
[00:00:13.358,215] <ESC>[0m<dbg> net_http_client: print_header_field: (0x2000d2e0): [24] sec-websocket-extensions<ESC>[0m
[00:00:13.368,225] <ESC>[0m<dbg> net_http_client: print_header_field: (0x2000d2e0): [18] permessage-deflate<ESC>[0m
[00:00:13.377,685] <ESC>[0m<dbg> net_http_client: on_headers_complete: (0x2000d2e0): Headers complete<ESC>[0m
[00:00:13.386,657] <ESC>[0m<dbg> net_http_client: on_message_complete: (0x2000d2e0): -- HTTP GET response (complete) --<ESC>[0m
[00:00:13.397,216] <ESC>[0m<dbg> net_http_client: http_report_complete: (0x2000d2e0): Calling callback for 212 len data<ESC>[0m
[00:00:13.407,745] <ESC>[0m<dbg> net_websocket: response_cb: (0x2000d2e0): [0x2000cfd8] All the data received (212 bytes)<ESC>[0m
[00:00:13.418,457] <ESC>[0m<dbg> net_http_client: http_client_req: (0x2000d2e0): Received 212 bytes<ESC>[0m
[00:00:13.427,246] <ESC>[0m<inf> lte_app: Websocket 2 for IPv4 connected.<ESC>[0m
[00:00:13.433,776] <ESC>[0m<dbg> net_websocket: websocket_connect: (0x2000d2e0): [0x2000cfd8] WS connection to peer established (fd 2)<ESC>[0m
[00:00:13.445,587] <ESC>[0m<inf> lte_app: Websocket IPv4 2<ESC>[0m
[00:00:13.450,866] <ESC>[0m<dbg> lte_app: start_websocket_communication: Sending JSON initMsg: {"messageType":"init","id":"id","name":"name"}<ESC>[0m
[00:00:13.465,728] <ESC>[0m<dbg> net_websocket: websocket_send_msg: (0x2000d2e0): [0x2000cfd8] Len 286 TEXT/1/final<ESC>[0m
[00:00:13.477,935] <ESC>[0m<dbg> lte_app: start_websocket_communication: IPv4 sent 286 bytes<ESC>[0m
[00:00:13.486,114] <ESC>[0m<dbg> lte_app: recv_data_wso_api: receive buffer before receiving
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........<ESC>[0m
[00:00:13.637,786] <ESC>[0m<dbg> lte_app: recv_data_wso_api: WAITING FOR MESSAGE... on socket: 2<ESC>[0m
[00:00:13.755,950] <ESC>[0m<dbg> net_websocket: websocket_recv_msg: (0x2000d2e0): [0x2000cfd8] Received 103 bytes<ESC>[0m
[00:00:13.765,930] <ESC>[0m<dbg> lte_app: recv_data_wso_api: Remaining: 0, retval: 101<ESC>[0m
[00:00:13.773,590] <ESC>[0m<dbg> lte_app: recv_data_wso_api: receive buffer after receiving
                                  aa 56 2a 2e 49 2c 29 2d  56 b2 52 72 ce 48 4d ce |.V*.I,)- V.Rr.HM.
                                  ce cc 4b 57 48 cb 2f 52  c8 4b 2d 57 c8 c9 4f 2f |..KWH./R .K-W..O/
                                  d6 53 d2 51 ca 4d 2d 2e  4e 4c 4f 0d a9 2c 48 05 |.S.Q.M-. NLO..,H.
                                  2a 2b 4a 2d 2c 4d 2d 2e  71 ce cf cd 0d 2a cd 49 |*+J-,M-. q....*.I
                                  2d 06 2a 28 48 4c ce 4e  2d 01 9a 11 ad 14 6d 68 |-.*(HL.N -.....mh
                                  69 a4 a3 00 44 06 60 64  0c 26 8d 2c 80 d8 c0 24 |i...D.`d .&.,...$
                                  56 29 b6 16 00 00 00 00  00 00 00 00 00 00 00 00 |V)...... ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........<ESC>[0m
[00:00:13.925,201] <ESC>[0m<dbg> net_sock: z_impl_zsock_close: (0x2000d2e0): close: ctx=0x2000cfd8, fd=2<ESC>[0m
[00:00:13.934,387] <ESC>[0m<dbg> net_websocket: websocket_interal_disconnect: (0x2000d2e0): [0x2000cfd8] Disconnecting<ESC>[0m


Parents
  • Hi,

    I have tried to build the websocket_client sample on nrf9160-dk (board target nrf9160dk/nrf9160/ns) in NCS v2.7.0 but build was not successful. Here is my build command
    west build -b nrf9160dk/nrf9160/ns --sysbuild -- -DCONF_FILE="prj.conf overlay-tls.conf"
    Build was also not successful without --sysbuild.

    Which NCS version do you use? If it is NCS v2.7.0, did you build your project with --sysbuild?
    Did you include overlay-tls.conf in your build command? 
    Can you provide your build command?

    Best regards,
    Dejan


Reply
  • Hi,

    I have tried to build the websocket_client sample on nrf9160-dk (board target nrf9160dk/nrf9160/ns) in NCS v2.7.0 but build was not successful. Here is my build command
    west build -b nrf9160dk/nrf9160/ns --sysbuild -- -DCONF_FILE="prj.conf overlay-tls.conf"
    Build was also not successful without --sysbuild.

    Which NCS version do you use? If it is NCS v2.7.0, did you build your project with --sysbuild?
    Did you include overlay-tls.conf in your build command? 
    Can you provide your build command?

    Best regards,
    Dejan


Children
  • Hi, 
    I didn't build the websocket client example, I integrated it into my own application with some modifications. I am using ncs v2.7.0 and I'm building with the vscode nrf connect tool. the complete config is attached in my post. I'm not adding any other overlays or configs

  • Hi,

    but as you can see in the trace output below, I just get something back that looks encrypted.

    Can you specify exact place of "something encrypted" in the trace?

    What do you expect to see in the trace instead of "something encrypted"?

    Best regards,
    Dejan

  • Near the end of the trace output I dump the receive buffer before and after receiving, to verify that it is empty and then it reads in the bytes received from the websocket. I expect to see:


    {"status":"Checking for new logs.","messageType":"requestCommRules","packets":["[192, 1, 0, 0, 3, 0, 208, 209]"]}

    but I get:
                                      aa 56 2a 2e 49 2c 29 2d  56 b2 52 72 ce 48 4d ce |.V*.I,)- V.Rr.HM.
                                      ce cc 4b 57 48 cb 2f 52  c8 4b 2d 57 c8 c9 4f 2f |..KWH./R .K-W..O/
                                      d6 53 d2 51 ca 4d 2d 2e  4e 4c 4f 0d a9 2c 48 05 |.S.Q.M-. NLO..,H.
                                      2a 2b 4a 2d 2c 4d 2d 2e  71 ce cf cd 0d 2a cd 49 |*+J-,M-. q....*.I
                                      2d 06 2a 28 48 4c ce 4e  2d 01 9a 11 ad 14 6d 68 |-.*(HL.N -.....mh
                                      69 a4 a3 00 44 06 60 64  0c 26 8d 2c 80 d8 c0 24 |i...D.`d .&.,...$
                                      56 29 b6 16 00 00 00 00  00 00 00 00 00 00 00 00 |V)...... ........

    when inspecting the memory, it looks encrypted. I can tell that it is not just garbage data because it looks very similar over many runs and if I perform a malformed request, I get back something else (likely an error message that I can't read either)

Related