Websocket client does not send MASK and MASKBIT when sending PING to server (IDFGH-1939) #4138

jonasinta · 2019-09-30T20:18:23Z

Environment

Development Kit: ESP32-DevKitC
Kit version: don't know which one
Module or chip used: [ESP32-WROOM-32]
IDF version v4.1-dev-281-g96b96ae24
Build System: CMake
Compiler version xtensa-esp32-elf-gcc (crosstool-NG esp32-2019r1) 8.2.0
Operating System: Linux
Power Supply: [USB]

websocket server is Spring Websocket handler. Problem still occurs if sending to the server in example code. (server in example code is kinder and does not shut down connection)

Problem Description

When the websocket runs any longer than "WEBSOCKET_PING_TIMEOUT_MS" set in component "esp_websocket_client" and defined in file "esp_websocket_client.c", the websocket client sends out a PING at defined time, but the PING has no MASK or MASKBIT set.
So the server promptly sends out a RST and shuts the websocket connection down.

Expected Behavior

Websocket remains open as my app sends an incrementing int.

Actual Behavior

Websocket gets shut down immediately after prescribed websocket ping timeout.

Steps to reproduce

build an app that sends binary data down an open websocket indefinately (incrementing regular send of integer)
run websocket server on an interface that you can monitor with webshark
Connect and open websocket, send data
monitor ip traffic to/from esp32 using webshark filter capture by ip addrtess of esp32 device
as time column in webshark hits websocket ping timeout, server send RST and shuts connection
edit- to check packets going to server in example- i set my module to send packets through a wifi station connected to my development pc so I could sniff the packets passing through my machine to the example server on WWW. Same result, PING goes out with no MASK bit set.

Code to reproduce this issue

//method for sending data down the websocket
//adapted from websocket example code in idf examples
void websocket_send(void *pvParameter) {

	char* data = "             ";
	char tempArray[20];
	int singleChar;
	int i = 0;
	int webSok_count;

	while (1) {

		if (esp_websocket_client_is_connected(client)) {
			//	printf("if has gone true\n");

			// send an incrementing int into this queue from main app
			xQueueReceive(websocketSendQueue, &singleChar, portMAX_DELAY);

			int len = snprintf(tempArray, 20, "hello %04d\n", singleChar);
			//	ESP_LOGI(TAG, "Sending %s", tempArray);
			webSok_count = esp_websocket_client_send(client, tempArray, len,
					1000);
			printf("count, heap %d %d\t", singleChar, esp_get_free_heap_size());

		}  //closeif

		vTaskDelay(1 / portTICK_RATE_MS);

	} //close while(1)
	esp_websocket_client_stop(client);
	websocket_destroy();

} //close method websocket send

Monitor copy and paste

(I set the websocket ping timeout to 100s)

jonas@greg:~/workspace/esp32workspace/blink$ idf.py monitor
Executing action: monitor
Choosing default port /dev/ttyUSB0 (use '-p PORT' option to set a specific serial port)
Running idf_monitor in directory /home/jonas/workspace/esp32workspace/blink
Executing "/home/jonas/.espressif/python_env/idf4.1_py2.7_env/bin/python /home/jonas/esp/esp-idf/tools/idf_monitor.py -p /dev/ttyUSB0 -b 115200 /home/jonas/workspace/esp32workspace/blink/build/blink.elf -m '/home/jonas/.espressif/python_env/idf4.1_py2.7_env/bin/python' '/home/jonas/esp/esp-idf/tools/idf.py'"...
--- idf_monitor on /dev/ttyUSB0 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:6444
load:0x40078000,len:13968
load:0x40080400,len:4252
entry 0x400806e0
I (29) boot: ESP-IDF v4.1-dev-281-g96b96ae24 2nd stage bootloader
I (29) boot: compile time 06:43:16
I (29) boot: Enabling RNG early entropy source...
I (35) boot: SPI Speed      : 40MHz
I (39) boot: SPI Mode       : DIO
I (43) boot: SPI Flash Size : 2MB
I (47) boot: Partition Table:
I (51) boot: ## Label            Usage          Type ST Offset   Length
I (58) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (65) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (73) boot:  2 factory          factory app      00 00 00010000 00100000
I (80) boot: End of partition table
I (85) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x1c018 (114712) map
I (135) esp_image: segment 1: paddr=0x0002c040 vaddr=0x3ffb0000 size=0x03250 ( 12880) load
I (140) esp_image: segment 2: paddr=0x0002f298 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _WindowOverflow4 at /home/jonas/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

I (142) esp_image: segment 3: paddr=0x0002f6a0 vaddr=0x40080400 size=0x00970 (  2416) load
I (152) esp_image: segment 4: paddr=0x00030018 vaddr=0x400d0018 size=0x8ada8 (568744) map
0x400d0018: _stext at ??:?

I (365) esp_image: segment 5: paddr=0x000badc8 vaddr=0x40080d70 size=0x0f9a4 ( 63908) load
I (402) boot: Loaded app from partition at offset 0x10000
I (402) boot: Disabling RNG early entropy source...
I (403) cpu_start: Pro cpu up.
I (406) cpu_start: Application information:
I (411) cpu_start: Project name:     blink
I (416) cpu_start: App version:      1
I (420) cpu_start: Compile time:     Oct  1 2019 06:43:10
I (426) cpu_start: ELF file SHA256:  33a8770fc97dd440...
I (432) cpu_start: ESP-IDF:          v4.1-dev-281-g96b96ae24
I (439) cpu_start: Starting app cpu, entry point is 0x40081288
0x40081288: call_start_cpu1 at /home/jonas/esp/esp-idf/components/esp32/cpu_start.c:271

I (0) cpu_start: App cpu up.
I (449) heap_init: Initializing. RAM available for dynamic allocation:
I (456) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (462) heap_init: At 3FFB9408 len 00026BF8 (154 KiB): DRAM
I (468) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (475) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (481) heap_init: At 40090714 len 0000F8EC (62 KiB): IRAM
I (487) cpu_start: Pro cpu start user code
I (506) spi_flash: detected chip: generic
I (506) spi_flash: flash io: dio
W (506) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (517) cpu_start: Chip Revision: 1
W (521) cpu_start: Chip revision is higher than the one configured in menuconfig. Suggest to upgrade it.
I (531) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (601) wifi station: ESP_WIFI_MODE_STA
I (611) wifi: wifi driver task: 3ffc1118, prio:23, stack:3584, core=0
I (611) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (611) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (641) wifi: wifi firmware version: df55612
I (641) wifi: config NVS flash: enabled
I (641) wifi: config nano formating: disabled
I (641) wifi: Init dynamic tx buffer num: 32
I (641) wifi: Init data frame dynamic rx buffer num: 32
I (651) wifi: Init management frame dynamic rx buffer num: 32
I (661) wifi: Init management short buffer num: 32
I (661) wifi: Init static rx buffer size: 1600
I (661) wifi: Init static rx buffer num: 10
I (671) wifi: Init dynamic rx buffer num: 32
I (761) phy: phy_version: 4102, 2fa7a43, Jul 15 2019, 13:06:06, 0, 0
I (771) wifi: mode : sta (24:0a:c4:0b:71:8c)
I (771) wifi station: wifi_init_sta finished.
I (771) wifi station: connect to ap SSID:xxxxxxx password:XXXXXXX
I (891) wifi: new:<1,1>, old:<1,0>, ap:<255,255>, sta:<1,1>, prof:1
I (891) wifi: state: init -> auth (b0)
I (901) wifi: state: auth -> assoc (0)
I (901) wifi: state: assoc -> run (10)
I (921) wifi: connected with fatherJack, channel 1, 40U, bssid = 10:fe:ed:40:bd:68
I (921) wifi: pm start, type: 1

I (2101) tcpip_adapter: sta ip: 192.168.1.106, mask: 255.255.255.0, gw: 192.168.1.1
I (2101) wifi station: got ip:192.168.1.106
I (2101) WEBSOCKET: [APP] Startup..
I (2111) WEBSOCKET: [APP] Free memory: 235408 bytes
I (2111) WEBSOCKET: [APP] IDF version: v4.1-dev-281-g96b96ae24
I (2121) WEBSOCKET: Connectiong to ws://192.168.1.102:8080/spring-mvc-websocket-example/socketHandler...
I (2411) WEBSOCKET: WEBSOCKET_EVENT_CONNECTED
count, heap 0 219128	count, heap 1 219128	count, heap 2 219128	count, heap 3 218524	count, heap 4 218592	count, heap 5 218708	count, heap 6 218900	count, heap 7 218904	count, heap 8 218592	count, heap 9 218712	count, heap 10 216892	count, heap 11 218900	count, heap 12 218904	count, heap 13 218716	count, heap 14 218900	count, heap 15 218900	count, heap 16 218712	count, heap 17 218712	count, heap 18 218900	count, heap 19 218900	count, heap 20 218712	count, heap 21 218900	count, heap 22 218900	count, heap 23 218900	count, heap 24 218900	count, heap 25 218900	count, heap 26 218900	count, heap 27 218900	count, heap 28 218900	count, heap 29 218900	count, heap 30 218712	count, heap 31 218712	count, heap 32 218592	count, heap 33 218712	count, heap 34 218900	count, heap 35 218592	count, heap 36 218900	count, heap 37 218712	count, heap 38 218900	count, heap 39 218900	count, heap 40 218900	count, heap 41 218900	count, heap 42 218712	count, heap 43 218900	count, heap 44 218592	count, heap 45 218712	count, heap 46 218900	count, heap 47 218592	count, heap 48 218900	count, heap 49 218900	count, heap 50 218708	count, heap 51 218712	count, heap 52 218712	count, heap 53 218712	count, heap 54 218900	count, heap 55 218712	count, heap 56 218900	count, heap 57 218712	count, heap 58 218900	count, heap 59 218900	count, heap 60 218900	count, heap 61 218900	count, heap 62 218900	count, heap 63 218900	count, heap 64 218900	count, heap 65 218900	count, heap 66 218900	count, heap 67 218900	count, heap 68 218900	count, heap 69 218592	count, heap 70 218900	count, heap 71 218900	count, heap 72 218592	count, heap 73 218712	count, heap 74 218900	count, heap 75 218712	count, heap 76 218708	count, heap 77 218900	count, heap 78 218900	count, heap 79 218592	count, heap 80 220464	count, heap 81 218592	count, heap 82 218712	count, heap 83 218900	count, heap 84 218712	count, heap 85 218712	count, heap 86 218712	count, heap 87 218592	count, heap 88 218712	count, heap 89 218712	count, heap 90 218712	count, heap 91 218592	count, heap 92 218900	count, heap 93 216896	count, heap 94 218900	count, heap 95 218900	count, heap 96 218712	count, heap 97 218712	count, heap 98 218900	count, heap 99 218712	count, heap 100 218712	count, heap 101 218712	count, heap 102 218900	count, heap 103 218712	count, heap 104 218900	count, heap 105 218712	count, heap 106 218900	count, heap 107 218900	count, heap 108 218900	count, heap 109 218900	count, heap 110 218712	count, heap 111 218712	count, heap 112 218900	count, heap 113 218900	count, heap 114 218900	count, heap 115 218708	count, heap 116 218900	count, heap 117 218900	count, heap 118 218592	count, heap 119 218900	count, heap 120 218900	count, heap 121 218712	count, heap 122 218900	count, heap 123 218712	count, heap 124 218904	count, heap 125 218900	count, heap 126 218712	count, heap 127 218708	count, heap 128 218900	count, heap 129 218900	count, heap 130 218592	count, heap 131 218900	count, heap 132 218900	count, heap 133 218900	count, heap 134 218900	count, heap 135 218900	W (102421) WEBSOCKET: Received=��The client frame was not masked but all client frames must be masked

count, heap 136 218784	E (103431) TRANS_TCP: tcp_poll_read select error 104, errno = Connection reset by peer, fd = 54
E (103431) WEBSOCKET_CLIENT: Network error, errorno
I (103431) WEBSOCKET_CLIENT: Reconnect after 10000 ms
I (103441) WEBSOCKET: WEBSOCKET_EVENT_DISCONNECTED
E (103541) WEBSOCKET_CLIENT: Websocket client is not connected
count, heap 137 222496	I (119501) WEBSOCKET: WEBSOCKET_EVENT_CONNECTED
count, heap 138 218972	count, heap 139 217228	count, heap 140 218776	count, heap 141 218572	count, heap 142 218968	count, heap 143 218788	count, heap 144 218968	count, heap 145 218972	count, heap 146 218968	count, heap 147 220528	count, heap 148 220340	count, heap 149 218964	count, heap 150 218972	count, heap 151 217228	count, heap 152 217248	count, heap 153 218972	count, heap 154 217276	count, heap 155 220336	count, heap 156 218780	count, heap 157 218584	count, heap 158 218892	count, heap 159 216888	count, heap 160 218892	count, heap 161 218892	count, heap 162 218704	count, heap 163 218704	count, heap 164 218892	count, heap 165 218704	count, heap 166 218704	count, heap 167 218892	count, heap 168 218704	count, heap 169 218704	count, heap 170 218704	count, heap 171 218704	count, heap 172 218704	count, heap 173 218704	count, heap 174 218704	count, heap 175 218704	count, heap 176 218892	count, heap 177 218892	count, heap 178 218892	count, heap 179 218892	count, heap 180 218892	count, heap 181 218584	count, heap 182 218704	count, heap 183 218704	count, heap 184 218584	count, heap 185 218892	count, heap 186 218704	count, heap 187 218704	count, heap 188 218704	count, heap 189 218892	count, heap 190 218892	count, heap 191 218704	count, heap 192 218892	count, heap 193 218580	count, heap 194 218892	count, heap 195 218704	count, heap 196 218584	count, heap 197 218704	count, heap 198 218704	count, heap 199 218704	count, heap 200 218892	count, heap 201 218892	count, heap 202 218704	count, heap 203 218704	count, heap 204 218892	count, heap 205 218704	count, heap 206 218704	count, heap 207 218892	count, heap 208 218704	count, heap 209 218704	count, heap 210 218704	count, heap 211 218704	count, heap 212 218892	count, heap 213 218584	count, heap 214 218704	count, heap 215 218704	count, heap 216 218892	count, heap 217 218892	count, heap 218 218704	count, heap 219 218892	count, heap 220 218892	count, heap 221 218584	count, heap 222 218892	count, heap 223 218704	count, heap 224 218700	count, heap 225 218892	count, heap 226 218892	count, heap 227 218704	count, heap 228 218892	count, heap 229 218892	count, heap 230 216884	count, heap 231 218704	count, heap 232 218892	count, heap 233 218584	count, heap 234 218892	count, heap 235 218892	count, heap 236 218704	count, heap 237 218892	count, heap 238 218892	count, heap 239 218704	count, heap 240 218704	count, heap 241 218892	count, heap 242 218892	count, heap 243 218892	count, heap 244 218892	count, heap 245 218892	count, heap 246 218892	count, heap 247 218892	count, heap 248 218892	count, heap 249 218892	count, heap 250 218892	count, heap 251 218704	count, heap 252 218892	count, heap 253 218892	count, heap 254 218892	count, heap 255 218584	count, heap 256 218704	count, heap 257 218704	count, heap 258 218704	count, heap 259 218892	count, heap 260 218704	count, heap 261 218584	count, heap 262 218892	count, heap 263 218704	count, heap 264 218896	count, heap 265 218892	W (202511) WEBSOCKET: Received=��The client frame was not masked but all client frames must be masked

count, heap 266 218968	E (203521) TRANS_TCP: tcp_poll_read select error 104, errno = Connection reset by peer, fd = 54
E (203521) WEBSOCKET_CLIENT: Network error, errorno
I (203521) WEBSOCKET_CLIENT: Reconnect after 10000 ms
I (203531) WEBSOCKET: WEBSOCKET_EVENT_DISCONNECTED
E (203561) WEBSOCKET_CLIENT: Websocket client is not connected
count, heap 267 222500	I (219591) WEBSOCKET: WEBSOCKET_EVENT_CONNECTED
count, heap 268 220340	count, heap 269 218972	count, heap 270 218972	count, heap 271 218972	count, heap 272 218788	count, heap 273 218968	count, heap 274 218972	count, heap 275 218768	count, heap 276 218968	count, heap 277 218968	count, heap 278 218972	count, heap 279 218968	count, heap 280 217272

The text was updated successfully, but these errors were encountered:

…zero-payload PONG and sending non-zero-payload PING Closes #3890 Closes #4138

@me-no-dev

…cleanly (espressif#4154) SPIFFS causes crashes if you attempt to rmdir. Since there are no true directories in spiffs, this ought to be a noop. It looks like @me-no-dev worked around this by using unlink instead of rmdir, which works in fatfs and doesn't panic spiffs. This behavior is not universal. In order to get littlefs working, it would be good to get this back to conformity. Rather than digging deep into the upstream spiffs, I just check the mountpoint and noop if it is "/spiffs". So, if the user has changed the mountpoint, this will not work, but I think it's a pretty good tradeoff.

github-actions bot changed the title ~~Websocket client does not send MASK and MASKBIT when sending PING to server~~ Websocket client does not send MASK and MASKBIT when sending PING to server (IDFGH-1939) Sep 30, 2019

igrr closed this as completed in ea955e1 Oct 13, 2019

espressif-bot pushed a commit that referenced this issue Nov 19, 2019

ws_client: fix ping-pong mechanism to use mask, support reception of …

1611386

…zero-payload PONG and sending non-zero-payload PING Closes #3890 Closes #4138

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Websocket client does not send MASK and MASKBIT when sending PING to server (IDFGH-1939) #4138

Websocket client does not send MASK and MASKBIT when sending PING to server (IDFGH-1939) #4138

jonasinta commented Sep 30, 2019 •

edited

Loading

Websocket client does not send MASK and MASKBIT when sending PING to server (IDFGH-1939) #4138

Websocket client does not send MASK and MASKBIT when sending PING to server (IDFGH-1939) #4138

Comments

jonasinta commented Sep 30, 2019 • edited Loading

Problem Description

Expected Behavior

Actual Behavior

Steps to reproduce

Code to reproduce this issue

Monitor copy and paste

jonasinta commented Sep 30, 2019 •

edited

Loading