websocket_client receives wrong data

Question

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 ", auth_token); const char *extra_headers[] = { auth_header, "Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits ", 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] [0m lte_app: setup_wss_socket: Looking up XXXX.XXXX.com[0m [00:00:09.323,699] [0m lte_app: setup_wss_socket: Resolved XX.XX.XX.XX (AF_INET)[0m [00:00:09.331,970] [0m lte_app: setup_wss_socket: Socket created: 1[0m [00:00:09.338,836] [0m lte_app: setup_wss_socket: Connecting to XXXX.XXXX.com:443[0m [00:00:12.077,667] [0m 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 ..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[0m [00:00:12.944,427] [0m 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.... [0m [00:00:13.009,826] [0m net_http_client: http_client_req: (0x2000d2e0): Sent 1439 bytes[0m [00:00:13.264,099] [0m net_http_client: on_message_begin: (0x2000d2e0): -- HTTP GET response (headers) --[0m [00:00:13.274,291] [0m net_http_client: on_status: (0x2000d2e0): HTTP response status 101 Switching Protocols[0m [00:00:13.284,881] [0m net_http_client: print_header_field: (0x2000d2e0): [4] Date[0m [00:00:13.293,151] [0m net_http_client: print_header_field: (0x2000d2e0): [29] Tue, 22 Oct 2024 10:48:33 GMT[0m [00:00:13.303,649] [0m net_http_client: print_header_field: (0x2000d2e0): [10] Connection[0m [00:00:13.312,500] [0m net_http_client: print_header_field: (0x2000d2e0): [7] upgrade[0m [00:00:13.320,983] [0m net_http_client: print_header_field: (0x2000d2e0): [7] upgrade[0m [00:00:13.329,467] [0m net_http_client: print_header_field: (0x2000d2e0): [9] websocket[0m [00:00:13.338,134] [0m net_http_client: print_header_field: (0x2000d2e0): [20] sec-websocket-accept[0m [00:00:13.347,839] [0m net_http_client: print_header_field: (0x2000d2e0): [28] 8hDDT21JDC5jDoPXslfSJW3xfv4=[0m [00:00:13.358,215] [0m net_http_client: print_header_field: (0x2000d2e0): [24] sec-websocket-extensions[0m [00:00:13.368,225] [0m net_http_client: print_header_field: (0x2000d2e0): [18] permessage-deflate[0m [00:00:13.377,685] [0m net_http_client: on_headers_complete: (0x2000d2e0): Headers complete[0m [00:00:13.386,657] [0m net_http_client: on_message_complete: (0x2000d2e0): -- HTTP GET response (complete) --[0m [00:00:13.397,216] [0m net_http_client: http_report_complete: (0x2000d2e0): Calling callback for 212 len data[0m [00:00:13.407,745] [0m net_websocket: response_cb: (0x2000d2e0): [0x2000cfd8] All the data received (212 bytes)[0m [00:00:13.418,457] [0m net_http_client: http_client_req: (0x2000d2e0): Received 212 bytes[0m [00:00:13.427,246] [0m lte_app: Websocket 2 for IPv4 connected.[0m [00:00:13.433,776] [0m net_websocket: websocket_connect: (0x2000d2e0): [0x2000cfd8] WS connection to peer established (fd 2)[0m [00:00:13.445,587] [0m lte_app: Websocket IPv4 2[0m [00:00:13.450,866] [0m lte_app: start_websocket_communication: Sending JSON initMsg: {"messageType":"init","id":"id","name":"name"}[0m [00:00:13.465,728] [0m net_websocket: websocket_send_msg: (0x2000d2e0): [0x2000cfd8] Len 286 TEXT/1/final[0m [00:00:13.477,935] [0m lte_app: start_websocket_communication: IPv4 sent 286 bytes[0m [00:00:13.486,114] [0m 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 |........ ........[0m [00:00:13.637,786] [0m lte_app: recv_data_wso_api: WAITING FOR MESSAGE... on socket: 2[0m [00:00:13.755,950] [0m net_websocket: websocket_recv_msg: (0x2000d2e0): [0x2000cfd8] Received 103 bytes[0m [00:00:13.765,930] [0m lte_app: recv_data_wso_api: Remaining: 0, retval: 101[0m [00:00:13.773,590] [0m 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 |........ ........[0m [00:00:13.925,201] [0m net_sock: z_impl_zsock_close: (0x2000d2e0): close: ctx=0x2000cfd8, fd=2[0m [00:00:13.934,387] [0m net_websocket: websocket_interal_disconnect: (0x2000d2e0): [0x2000cfd8] Disconnecting[0m

Anders Reiche · Accepted Answer

I was able to resolve this issue myself. I was naively copying websocket headers from my working postman request into my code. So the header: " Sec-WebSocket-Extensions: permessage-deflate" was enabled, causing the response to be compressed. When testing the websocket on python I forgot to add this header, and failed to realize that this was what was making it work in python too.

websocket_client receives wrong data

Top Replies