search

zephyrproject-rtos / zephyr

Primary Git Repository for the Zephyr Project. Zephyr is a new generation, scalable, optimized, secure RTOS for multiple hardware architectures.
https://docs.zephyrproject.org
Apache License 2.0
10.97k stars 6.68k forks source link

civetweb hangs when there are no free filedescriptors #31593

Closed xhpohanka closed 3 years ago

xhpohanka commented 3 years ago

Describe the bug Civetweb on zephyr can easilly hang when there are no free filedscriptors. I have noticed it on a page that downloads some styles, javascript etc. Not on a simple text page.

To Reproduce I have prepared a test case, it works in qemu_x86 https://github.com/xhpohanka/cv_test It can be reproduced simply by accessing a page (http://192.0.2.1) with a browser and doing several fast refreshes (ctrl+F5).

When civetweb threads have the same priority the web server will hang because it ends in a loop in master thread where accept() still returns an error. If we add a sleep there (see https://github.com/xhpohanka/cv_test/blob/master/civetweb_dbg.patch) it will continue to run, but it leads to leaks like it can be seen in following logs (check net mem and net allocs outputs)

I do not know yet if the problem is in Zephyr or Civetweb where I have already reported it (civetweb/civetweb#962)

Log with normal operation

SeaBIOS (version rel-1.12.1-0-ga5cab58-dirty-20200625_115407-9426dddc0a1f-zephyr
)
Booting from ROM..*** Booting Zephyr OS build zephyr-v2.4.0-3346-gfd630d70c106  ***
*** 0.010000000            0 1322016 mg_start:18621: [listening_ports] -> [80,443s]
*** 0.010000000            0 1322016 mg_start:18621: [num_threads] -> [1]
*** 0.010000000            0 1322016 mg_start:18621: [max_request_size] -> [4096]
*** 0.020000000     10000000 1322016 mg_start:18621: [enable_keep_alive] -> [yes]
*** 0.020000000            0 1322016 mg_start:18621: [keep_alive_timeout_ms] -> [1000]

uart:~$ *** 0.030000000     10000000 1300184 consume_socket:17825: going idle
[00:00:00.010,000] <inf> net_config: Initializing network
[00:00:00.010,000] <inf> net_config: IPv4 address: 192.0.2.1
[00:00:00.010,000] <inf> net_config: Running dhcpv4 client...
[00:00:00.010,000] <dbg> cv_test.main: Starting civetweb
[00:00:00.020,000] <dbg> net_sock.zsock_socket_internal: (main): socket: ctx=0x13e074, fd=3
[00:00:00.020,000] <dbg> net_sock.z_impl_zsock_getsockname: (main): getsockname: ctx=0x13e074, fd=3
[00:00:00.020,000] <dbg> net_sock.zsock_socket_internal: (main): socket: ctx=0x13e108, fd=4
[00:00:00.020,000] <dbg> net_sock.z_impl_zsock_getsockname: (main): getsockname: ctx=0x13e108, fd=4
[00:00:00.030,000] <dbg> cv_test.init_thread_cb: Master thread started, setting priotity 1
[00:00:00.030,000] <dbg> cv_test.init_thread_cb: Connection thread started, setting priotity 1
uart:~$ 
uart:~$ 
uart:~$ net mem
Fragment length 128 bytes
Network buffer pools:
Address     Total   Avail   Name
0x1c3d70    256 254 RX
0x1c3db8    256 254 TX
0x1c3f5c    96  96  RX DATA (rx_bufs)
0x1c3f98    192 192 TX DATA (tx_bufs)
uart:~$ 
uart:~$ *** 12.370000000  12340000000 1299936 accept_new_connection:18112: Accepted socket 5
*** 12.380000000     10000000 1299936 produce_socket:17875: queued socket 5
*** 12.380000000            0 1300184 consume_socket:17838: grabbed socket 5, going busy
*** 12.380000000            0 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 12.380000000            0 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 12.380000000            0 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
*** 12.380000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 12.380000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 12.380000000            0 1300184 handle_request:13797: URL: /
*** 12.420000000     40000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET / HTTP/1.1" 200
*** 12.420000000            0 1300184 process_new_connection:17585: calling get_request (2 times for this connection)
*** 12.520000000    100000000 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 12.530000000     10000000 1300184 process_new_connection:17650: http: 1.1, error: none
*** 12.530000000            0 1300184 handle_request:13797: URL: /style.css
*** 12.570000000     40000000 1299936 accept_new_connection:18112: Accepted socket 6
*** 12.580000000     10000000 1299936 produce_socket:17875: queued socket 6
*** 12.590000000     10000000 1299936 accept_new_connection:18112: Accepted socket 7
*** 12.590000000            0 1299936 produce_socket:17875: queued socket 7
*** 12.600000000     10000000 1299936 accept_new_connection:18112: Accepted socket 8
*** 12.600000000            0 1299936 produce_socket:17875: queued socket 8
*** 12.610000000     10000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /style.css HTTP/1.1" 200
*** 12.610000000            0 1300184 process_new_connection:17585: calling get_request (3 times for this connection)
--- 1 messages dropped ---
[00:00:12.370,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e19c, pkt=0x175760, st=0, user_data=(nil)
[00:00:12.370,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e19c, fd=5
[00:00:12.370,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13e19c, fd=5
[00:00:12.520,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e19c, pkt=0x175760, st=0, user_data=(nil)
[00:00:12.570,000] <dbg> net_sock.zsock_accepted_cb: (rx_q[0]): parent=0x13e074, ctx=0x13e230, st=0
[00:00:12.570,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e230, fd=6
[00:00:12.580,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13e230, fd=6
[00:00:12.590,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e230, pkt=0x1755b0, st=0, user_data=(nil)
[00:00:12.590,000] <dbg> net_sock.zsock_accepted_cb: (rx_q[0]): parent=0x13e074, ctx=0x13e2c4, st=0
[00:00:12.590,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e2c4, fd=7
[00:00:12.590,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13e2c4, fd=7
[00:00:12.600,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e2c4, pkt=0x175688, st=0, user_data=(nil)
[00:00:12.600,000] <dbg> net_sock.zsock_accepted_cb: (rx_q[0]): parent=0x13e074, ctx=0x13e358, st=0
[00:00:12.600,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e358, pkt=0x1755f8, st=0, user_data=(nil)
[00:00:12.600,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e358, fd=8
[00:00:12.600,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13e358, fd=8
uart:~$ *** 13.620000000   1010000000 1300184 process_new_connection:17650: http: none, error: No data received
*** 13.620000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 13.620000000            0 1300184 worker_thread_run:18033: Connection closed
*** 13.630000000     10000000 1300184 consume_socket:17825: going idle
*** 13.630000000            0 1300184 consume_socket:17838: grabbed socket 6, going busy
*** 13.630000000            0 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 13.630000000            0 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 13.630000000            0 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
*** 13.630000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 13.630000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 13.630000000            0 1300184 handle_request:13797: URL: /jquery-3.5.1.min.js
*** 14.470000000    840000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /jquery-3.5.1.min.js HTTP/1.1" 200
*** 14.470000000            0 1300184 process_new_connection:17585: calling get_request (2 times for this connection)
[00:00:13.620,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e19c
uart:~$ *** 15.480000000   1010000000 1300184 process_new_connection:17650: http: none, error: No data received
*** 15.480000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 15.480000000            0 1300184 worker_thread_run:18033: Connection closed
*** 15.480000000            0 1300184 consume_socket:17825: going idle
*** 15.480000000            0 1300184 consume_socket:17838: grabbed socket 7, going busy
*** 15.480000000            0 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 15.480000000            0 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 15.480000000            0 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
*** 15.490000000     10000000 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 15.490000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 15.490000000            0 1300184 handle_request:13797: URL: /js.cookie-2.2.1.min.js
*** 15.520000000     30000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /js.cookie-2.2.1.min.js HTTP/1.1" 200
*** 15.520000000            0 1300184 process_new_connection:17585: calling get_request (2 times for this connection)
*** 15.520000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 15.520000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 15.520000000            0 1300184 handle_request:13797: URL: /login.js
*** 15.540000000     20000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /login.js HTTP/1.1" 200
*** 15.540000000            0 1300184 process_new_connection:17585: calling get_request (3 times for this connection)
*** 15.540000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 15.540000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 15.540000000            0 1300184 handle_request:13797: URL: /logo.png
*** 16.260000000    720000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /logo.png HTTP/1.1" 200
*** 16.260000000            0 1300184 process_new_connection:17585: calling get_request (4 times for this connection)
[00:00:15.480,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e230
[00:00:15.510,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e2c4, pkt=0x1757a8, st=0, user_data=(nil)
[00:00:15.530,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e2c4, pkt=0x1757a8, st=0, user_data=(nil)
uart:~$ *** 17.270000000   1010000000 1300184 process_new_connection:17650: http: none, error: No data received
*** 17.270000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 17.270000000            0 1300184 worker_thread_run:18033: Connection closed
*** 17.270000000            0 1300184 consume_socket:17825: going idle
*** 17.270000000            0 1300184 consume_socket:17838: grabbed socket 8, going busy
*** 17.270000000            0 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 17.270000000            0 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 17.270000000            0 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
*** 17.270000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 17.270000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 17.270000000            0 1300184 handle_request:13797: URL: /sha1.min.js
*** 17.340000000     70000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /sha1.min.js HTTP/1.1" 200
*** 17.340000000            0 1300184 process_new_connection:17585: calling get_request (2 times for this connection)
*** 17.450000000    110000000 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 17.450000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 17.450000000            0 1300184 handle_request:13797: URL: /favicon.ico
*** 17.450000000            0 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /favicon.ico HTTP/1.1" 404
*** 17.460000000     10000000 1300184 process_new_connection:17585: calling get_request (3 times for this connection)
[00:00:17.270,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e2c4
[00:00:17.450,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e358, pkt=0x175760, st=0, user_data=(nil)
[00:00:17.450,000] <err> cv_test: cannot open /favicon.ico
[00:00:18.270,000] <err> log: argument 0 in source cv_test log message "cannot open %s" missinglog_strdup().
uart:~$ *** 18.470000000   1010000000 1300184 process_new_connection:17650: http: none, error: No data received
*** 18.470000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 18.470000000            0 1300184 worker_thread_run:18033: Connection closed
*** 18.470000000            0 1300184 consume_socket:17825: going idle
[00:00:18.470,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e358
uart:~$ 
uart:~$ net mem
Fragment length 128 bytes
Network buffer pools:
Address     Total   Avail   Name
0x1c3d70    256 254 RX
0x1c3db8    256 254 TX
0x1c3f5c    96  96  RX DATA (rx_bufs)
0x1c3f98    192 192 TX DATA (tx_bufs)

Log with leaks

uart:~$ *** 32.250000000  13780000000 1299936 accept_new_connection:18112: Accepted socket 5
*** 32.250000000            0 1299936 produce_socket:17875: queued socket 5
*** 32.250000000            0 1300184 consume_socket:17838: grabbed socket 5, going busy
*** 32.250000000            0 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 32.250000000            0 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 32.250000000            0 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
*** 32.250000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 32.250000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 32.260000000     10000000 1300184 handle_request:13797: URL: /
*** 32.280000000     20000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET / HTTP/1.1" 200
*** 32.280000000            0 1300184 process_new_connection:17585: calling get_request (2 times for this connection)
*** 32.310000000     30000000 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 32.310000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 32.310000000            0 1300184 handle_request:13797: URL: /style.css
*** 32.360000000     50000000 1299936 accept_new_connection:18112: Accepted socket 6
*** 32.360000000            0 1299936 produce_socket:17875: queued socket 6
*** 32.360000000            0 1299936 accept_new_connection:18112: Accepted socket 7
*** 32.370000000     10000000 1299936 produce_socket:17875: queued socket 7
*** 32.370000000            0 1299936 accept_new_connection:18112: Accepted socket 8
*** 32.380000000     10000000 1299936 produce_socket:17875: queued socket 8
--- 1 messages dropped ---
[00:00:32.240,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e19c, pkt=0x1756d0, st=0, user_data=(nil)
[00:00:32.250,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e19c, fd=5
[00:00:32.250,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13e19c, fd=5
[00:00:32.300,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e19c, pkt=0x1756d0, st=0, user_data=(nil)
[00:00:32.350,000] <dbg> net_sock.zsock_accepted_cb: (rx_q[0]): parent=0x13e074, ctx=0x13e230, st=0
[00:00:32.350,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e230, pkt=0x175760, st=0, user_data=(nil)
[00:00:32.360,000] <dbg> net_sock.zsock_accepted_cb: (rx_q[0]): parent=0x13e074, ctx=0x13e2c4, st=0
[00:00:32.360,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e230, fd=6
[00:00:32.360,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13e230, fd=6
[00:00:32.360,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e2c4, fd=7
[00:00:32.370,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e2c4, pkt=0x1755b0, st=0, user_data=(nil)
[00:00:32.370,000] <dbg> net_sock.zsock_accepted_cb: (rx_q[0]): parent=0x13e074, ctx=0x13e358, st=0
[00:00:32.370,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e358, pkt=0x175718, st=0, user_data=(nil)
[00:00:32.370,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13e2c4, fd=7
[00:00:32.370,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e358, fd=8
[00:00:32.380,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13e358, fd=8
uart:~$ *** 32.420000000     40000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /style.css HTTP/1.1" 200
*** 32.420000000            0 1300184 process_new_connection:17585: calling get_request (3 times for this connection)
*** 32.520000000    100000000 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 32.520000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 32.520000000            0 1300184 handle_request:13797: URL: /
*** 32.550000000     30000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET / HTTP/1.1" 200
*** 32.550000000            0 1300184 process_new_connection:17585: calling get_request (4 times for this connection)
*** 32.560000000     10000000 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 32.570000000     10000000 1300184 process_new_connection:17650: http: 1.1, error: none
*** 32.570000000            0 1300184 handle_request:13797: URL: /style.css
*** 32.590000000     20000000 1299936 accept_new_connection:18112: Accepted socket 9
*** 32.590000000            0 1299936 produce_socket:17875: queued socket 9
[00:00:32.520,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13*** 32.620000000     30000000 1299936 accept_new_connection:18112: Accepted socket 10
*** 32.620000000            0 1299936 produce_socket:17875: queued socket 10
*** 32.620000000            0 1299936 accept_new_connection:18112: Accepted socket 11
*** 32.620000000            0 1299936 produce_socket:17875: queued socket 11
e19c, pkt=0x1755f8, st=0, user_data=(nil)
[00:00:32.540,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e358, pkt=(nil), st=-54, user_data=(nil)
[00:00:32.540,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): Set EOF flag on pkt 0x175718
[00:00:32.540,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e2c4, pkt=(nil), st=-54, user_data=(nil)
[00:00:32.540,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): Set EOF flag on pkt 0x1755b0
[00:00:32.540,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e230, pkt=(nil), st=-54, user_data=(nil)
[00:00:32.540,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): Set EOF flag on pkt 0x175760
[00:00:32.560,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e19c, pkt=0x1756d0, st=0, user_data=(nil)
[00:00:32.580,000] <dbg> net_sock.zsock_accepted_cb: (rx_q[0]): parent=0x13e074, ctx=0x13e3ec, st=0
[00:00:32.590,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e3ec, pkt=0x1757a8, st=0, user_data=(nil)
[00:00:32.590,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e3ec, fd=9
--- 3 messages dropped ---
[00:00:32.610,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e480, pkt=0x175688, st=0, user_data=(nil)
[00:00:32.610,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e514, pkt=0x1755f8, st=0, user_data=(nil)
[00:00:32.620,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e480, fd=10
[00:00:32.620,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13e480, fd=10
[00:00:32.620,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e514, fd=11
[00:00:32.620,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13e514, fd=11
uart:~$ *** 32.660000000     40000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /style.css HTTP/1.1" 200
*** 32.660000000            0 1300184 process_new_connection:17585: calling get_request (5 times for this connection)
*** 32.750000000     90000000 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 32.750000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 32.750000000            0 1300184 handle_request:13797: URL: /
*** 32.770000000     20000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET / HTTP/1.1" 200
*** 32.770000000            0 1300184 process_new_connection:17585: calling get_request (6 times for this connection)
*** 32.790000000     20000000 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 32.790000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 32.800000000     10000000 1300184 handle_request:13797: URL: /style.css
*** 32.860000000     60000000 1299936 accept_new_connection:18112: Accepted socket 12
*** 32.860000000            0 1299936 produce_socket:17875: queued socket 12
*** 32.870000000     10000000 1299936 accept_new_connection:18112: Accepted socket 13
*** 32.870000000            0 1299936 produce_socket:17875: queued socket 13
*** 32.870000000            0 1299936 accept_new_connection:18112: Accepted socket 14
*** 32.870000000            0 1299936 produce_socket:17875: queued socket 14
--- 3 messages dropped ---
[00:00:32.770,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e3ec, pkt=(nil), st=-54, user_data=(nil)
[00:00:32.770,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): Set EOF flag on pkt 0x1757a8
[00:00:32.770,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e514, pkt=(nil), st=-54, user_data=(nil)
[00:00:32.770,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): Set EOF flag on pkt 0x1755f8
[00:00:32.790,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e19c, pkt=0x175568, st=0, user_data=(nil)
uart:~$ *** 32.880000000     10000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /style.css HTTP/1.1" 200
*** 32.880000000            0 1300184 process_new_connection:17585: calling get_request (7 times for this connection)
[00:00:32.850,000] <dbg> net_sock.zsock_accepted_cb: (rx_q[0]): parent=0x13e074, ctx=0x13e5a8, st=0
[00:00:32.850,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e5a8, pkt=0x175448, st=0, user_data=(nil)
[00:00:32.850,000] <dbg> net_sock.zsock_accepted_cb: (rx_q[0]): parent=0x13e074, ctx=0x13e63c, st=0
[00:00:32.860,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e63c, pkt=0x175490, st=0, user_data=(nil)
[00:00:32.860,000] <dbg> net_sock.zsock_accepted_cb: (rx_q[0]): parent=0x13e074, ctx=0x13e6d0, st=0
[00:00:32.860,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e6d0, pkt=0x1754d8, st=0, user_data=(nil)
[00:00:32.860,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e5a8, fd=12
[00:00:32.860,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13e5a8, fd=12
[00:00:32.870,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e63c, fd=13
[00:00:32.870,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13e63c, fd=13
[00:00:32.870,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e6d0, fd=14
[00:00:32.870,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13e6d0, fd=14
uart:~$ *** 32.970000000     90000000 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 32.970000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 32.970000000            0 1300184 handle_request:13797: URL: /
*** 32.990000000     20000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET / HTTP/1.1" 200
*** 32.990000000            0 1300184 process_new_connection:17585: calling get_request (8 times for this connection)
*** 33.030000000     40000000 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 33.030000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 33.030000000            0 1300184 handle_request:13797: URL: /style.css
*** 33.090000000     60000000 1299936 accept_new_connection:18112: Accepted socket 15
*** 33.090000000            0 1299936 produce_socket:17875: queued socket 15
[00:00:32.970,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e19c, pkt=0x175400, st=0, user_data=(nil)
[00:00:32.990,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e63c, pkt=(nil), st=-54, user_data=(nil)
[00:00:32.990,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): Set EOF flag on pkt 0x175490
[00:00:32.990,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e5a8, pkt=(nil), st=-54, user_data=(nil)
[00:00:32.990,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): Set EOF flag on pkt 0x175448
[00:00:32.990,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e6d0, pkt=(nil), st=-54, user_data=(nil)
[00:00:32.990,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): Set EOF flag on pkt 0x1754d8
[00:00:33.030,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e19c, pkt=0x1756d0, st=0, user_data=(nil)
[00:00:33.070,000] <dbg> net_sock.zsock_accepted_cb: (rx_q[0]): parent=0x13e074, ctx=0x13e764, st=0
[00:00:33.070,000] <dbg> net_sock.zsock_accepted_cb: (rx_q[0]): parent=0x13e074, ctx=0x13e7f8, st=0
[00:00:33.070,000] <dbg> net_sock.zsock_accepted_cb: (rx_q[0]): parent=0x13e074, ctx=0x13e88c, st=0
[00:00:33.080,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e764, pkt=0x175400, st=0, user_data=(nil)
[00:00:33.080,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e7f8, pkt=0x1753b8, st=0, user_data=(nil)
[00:00:33.080,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e88c, pkt=0x175370, st=0, user_data=(nil)
[00:00:33.090,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e764, fd=15
[00:00:33.090,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13e764, fd=15
uart:~$ *** 33.130000000     40000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /style.css HTTP/1.1" 200
*** 33.130000000            0 1300184 process_new_connection:17585: calling get_request (9 times for this connection)
*** 33.180000000     50000000 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 33.180000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 33.180000000            0 1300184 handle_request:13797: URL: /
*** 33.210000000     30000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET / HTTP/1.1" 200
*** 33.210000000            0 1300184 process_new_connection:17585: calling get_request (10 times for this connection)
*** 33.230000000     20000000 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 33.230000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 33.230000000            0 1300184 handle_request:13797: URL: /style.css
[00:00:33.180,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e19c, pkt=0x175328, st=0, user_data=(nil)
[00:00:33.210,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e88c, pkt=(nil), st=-54, user_data=(nil)
[00:00:33.210,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): Set EOF flag on pkt 0x175370
[00:00:33.210,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e764, pkt=(nil), st=-54, user_data=(nil)
[00:00:33.210,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): Set EOF flag on pkt 0x175400
[00:00:33.210,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e7f8, pkt=(nil), st=-54, user_data=(nil)
[00:00:33.210,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): Set EOF flag on pkt 0x1753b8
[00:00:33.230,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e19c, pkt=0x175568, st=0, user_data=(nil)
[00:00:33.280,000] <err> net_tcp: net_context_get(): -2
[00:00:33.280,000] <err> net_tcp: Cannot allocate a new TCP connection
[00:00:33.280,000] <dbg> net_sock.zsock_accepted_cb: (rx_q[0]): parent=0x13e074, ctx=0x13e7f8, st=0
[00:00:33.280,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e7f8, pkt=0x175298, st=0, user_data=(nil)
[00:00:33.280,000] <dbg> net_sock.zsock_accepted_cb: (rx_q[0]): parent=0x13e074, ctx=0x13e88c, st=0
[00:00:33.280,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e88c, pkt=0x1752e0, st=0, user_data=(nil)
[00:00:33.300,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e19c, pkt=0x175520, st=0, user_data=(nil)
uart:~$ *** 33.320000000     90000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /style.css HTTP/1.1" 200
*** 33.320000000            0 1300184 process_new_connection:17585: calling get_request (11 times for this connection)
*** 33.320000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 33.320000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 33.320000000            0 1300184 handle_request:13797: URL: /sha1.min.js
*** 33.390000000     70000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /sha1.min.js HTTP/1.1" 200
*** 33.390000000            0 1300184 process_new_connection:17585: calling get_request (12 times for this connection)
*** 34.400000000   1010000000 1300184 process_new_connection:17650: http: none, error: No data received
*** 34.400000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 34.410000000     10000000 1300184 worker_thread_run:18033: Connection closed
*** 34.410000000            0 1300184 consume_socket:17825: going idle
*** 34.410000000            0 1300184 consume_socket:17838: grabbed socket 6, going busy
*** 34.410000000            0 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 34.410000000            0 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 34.410000000            0 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
*** 34.410000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 34.410000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 34.410000000            0 1300184 handle_request:13797: URL: /jquery-3.5.1.min.js
*** 34.420000000     10000000 1299936 accept_new_connection:18112: Accepted socket 5
*** 34.420000000            0 1299936 produce_socket:17875: queued socket 5
[00:00:34.260,000] <err> net_tcp: net_context_get(): -2
[00:00:34.260,000] <err> net_tcp: Cannot allocate a new TCP connection
[00:00:34.400,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e19c
[00:00:34.420,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e7f8, fd=5
[00:00:34.420,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13e7f8, fd=5
[00:00:34.440,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.460,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.480,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.500,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.520,000] <dbg> cv_test.send_file: ferr -1 57
]art:~$ *** 34.540000000    120000000 1300184 mg_send_http_error_impl:4650: Error 500 - [chyba
*** 34.540000000            0 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /jquery-3.5.1.min.js HTTP/1.1" 500
*** 34.540000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 34.540000000            0 1300184 worker_thread_run:18033: Connection closed
*** 34.550000000     10000000 1300184 consume_socket:17825: going idle
*** 34.550000000            0 1300184 consume_socket:17838: grabbed socket 7, going busy
*** 34.550000000            0 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 34.550000000            0 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 34.550000000            0 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
*** 34.550000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 34.550000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 34.550000000            0 1300184 handle_request:13797: URL: /js.cookie-2.2.1.min.js
*** 34.560000000     10000000 1299936 accept_new_connection:18112: Accepted socket 6
*** 34.560000000            0 1299936 produce_socket:17875: queued socket 6
[00:00:34.540,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.540,000] <err> cv_test: file sending error
[00:00:34.540,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e230
[00:00:34.560,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e88c, fd=6
[00:00:34.560,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13e88c, fd=6
[00:00:34.580,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.600,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.620,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.640,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.660,000] <dbg> cv_test.send_file: ferr -1 57
]art:~$ *** 34.680000000    120000000 1300184 mg_send_http_error_impl:4650: Error 500 - [chyba
*** 34.680000000            0 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /js.cookie-2.2.1.min.js HTTP/1.1" 500
*** 34.680000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 34.680000000            0 1300184 worker_thread_run:18033: Connection closed
*** 34.680000000            0 1300184 consume_socket:17825: going idle
*** 34.680000000            0 1300184 consume_socket:17838: grabbed socket 8, going busy
*** 34.680000000            0 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 34.680000000            0 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 34.680000000            0 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
*** 34.680000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 34.680000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 34.680000000            0 1300184 handle_request:13797: URL: /sha1.min.js
]** 34.810000000    130000000 1300184 mg_send_http_error_impl:4650: Error 500 - [chyba
*** 34.810000000            0 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /sha1.min.js HTTP/1.1" 500
*** 34.810000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 34.810000000            0 1300184 worker_thread_run:18033: Connection closed
*** 34.810000000            0 1300184 consume_socket:17825: going idle
*** 34.820000000     10000000 1300184 consume_socket:17838: grabbed socket 9, going busy
*** 34.820000000            0 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 34.820000000            0 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 34.820000000            0 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
*** 34.820000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 34.820000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 34.820000000            0 1300184 handle_request:13797: URL: /jquery-3.5.1.min.js
[00:00:34.680,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.680,000] <err> cv_test: file sending error
[00:00:34.680,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e2c4
[00:00:34.710,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.730,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.750,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.770,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.790,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.810,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.810,000] <err> cv_test: file sending error
[00:00:34.810,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e358
]art:~$ *** 34.950000000    130000000 1300184 mg_send_http_error_impl:4650: Error 500 - [chyba
*** 34.950000000            0 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /jquery-3.5.1.min.js HTTP/1.1" 500
*** 34.950000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 34.950000000            0 1300184 worker_thread_run:18033: Connection closed
*** 34.950000000            0 1300184 consume_socket:17825: going idle
*** 34.950000000            0 1300184 consume_socket:17838: grabbed socket 10, going busy
*** 34.950000000            0 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 34.950000000            0 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 34.960000000     10000000 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
*** 34.960000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 34.960000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 34.960000000            0 1300184 handle_request:13797: URL: /js.cookie-2.2.1.min.js
[00:00:34.850,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.870,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.890,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.910,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.930,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.950,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:34.950,000] <err> cv_test: file sending error
[00:00:34.950,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e3ec
[00:00:34.980,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.000,000] <dbg> cv_test.send_file: ferr -1 57
]art:~$ *** 35.080000000    120000000 1300184 mg_send_http_error_impl:4650: Error 500 - [chyba
*** 35.080000000            0 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /js.cookie-2.2.1.min.js HTTP/1.1" 500
*** 35.080000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 35.080000000            0 1300184 worker_thread_run:18033: Connection closed
*** 35.080000000            0 1300184 consume_socket:17825: going idle
*** 35.080000000            0 1300184 consume_socket:17838: grabbed socket 11, going busy
*** 35.080000000            0 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 35.080000000            0 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 35.080000000            0 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
*** 35.080000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 35.080000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 35.080000000            0 1300184 handle_request:13797: URL: /sha1.min.js
[00:00:35.020,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.040,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.060,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.080,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.080,000] <err> cv_test: file sending error
[00:00:35.080,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e480
[00:00:35.100,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.120,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.140,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.160,000] <dbg> cv_test.send_file: ferr -1 57
]art:~$ *** 35.200000000    120000000 1300184 mg_send_http_error_impl:4650: Error 500 - [chyba
*** 35.200000000            0 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /sha1.min.js HTTP/1.1" 500
*** 35.200000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 35.200000000            0 1300184 worker_thread_run:18033: Connection closed
*** 35.200000000            0 1300184 consume_socket:17825: going idle
*** 35.200000000            0 1300184 consume_socket:17838: grabbed socket 12, going busy
*** 35.200000000            0 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 35.210000000     10000000 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 35.210000000            0 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
*** 35.210000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 35.210000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 35.210000000            0 1300184 handle_request:13797: URL: /jquery-3.5.1.min.js
]** 35.330000000    120000000 1300184 mg_send_http_error_impl:4650: Error 500 - [chyba
*** 35.330000000            0 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /jquery-3.5.1.min.js HTTP/1.1" 500
*** 35.330000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 35.330000000            0 1300184 worker_thread_run:18033: Connection closed
*** 35.330000000            0 1300184 consume_socket:17825: going idle
*** 35.330000000            0 1300184 consume_socket:17838: grabbed socket 13, going busy
*** 35.330000000            0 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 35.340000000     10000000 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 35.340000000            0 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
*** 35.340000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 35.340000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 35.340000000            0 1300184 handle_request:13797: URL: /js.cookie-2.2.1.min.js
[00:00:35.180,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.200,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.200,000] <err> cv_test: file sending error
[00:00:35.200,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e514
[00:00:35.230,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.250,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.270,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.290,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.310,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.330,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.330,000] <err> cv_test: file sending error
[00:00:35.330,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e5a8
[00:00:35.360,000] <dbg> cv_test.send_file: ferr -1 57
]art:~$ *** 35.460000000    120000000 1300184 mg_send_http_error_impl:4650: Error 500 - [chyba
*** 35.460000000            0 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /js.cookie-2.2.1.min.js HTTP/1.1" 500
*** 35.460000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 35.460000000            0 1300184 worker_thread_run:18033: Connection closed
*** 35.460000000            0 1300184 consume_socket:17825: going idle
*** 35.460000000            0 1300184 consume_socket:17838: grabbed socket 14, going busy
*** 35.470000000     10000000 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 35.470000000            0 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 35.470000000            0 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
*** 35.470000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 35.470000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 35.470000000            0 1300184 handle_request:13797: URL: /sha1.min.js
[00:00:35.380,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.400,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.420,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.440,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.460,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.460,000] <err> cv_test: file sending error
[00:00:35.460,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e63c
[00:00:35.490,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.510,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.530,000] <dbg> cv_test.send_file: ferr -1 57
]art:~$ *** 35.590000000    120000000 1300184 mg_send_http_error_impl:4650: Error 500 - [chyba
*** 35.590000000            0 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /sha1.min.js HTTP/1.1" 500
*** 35.590000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 35.590000000            0 1300184 worker_thread_run:18033: Connection closed
*** 35.590000000            0 1300184 consume_socket:17825: going idle
*** 35.590000000            0 1300184 consume_socket:17838: grabbed socket 15, going busy
*** 35.590000000            0 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 35.590000000            0 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 35.590000000            0 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
*** 35.590000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 35.590000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 35.590000000            0 1300184 handle_request:13797: URL: /jquery-3.5.1.min.js
[00:00:35.550,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.570,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.590,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.590,000] <err> cv_test: file sending error
[00:00:35.590,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e6d0
[00:00:35.610,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.630,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.650,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.670,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.690,000] <dbg> cv_test.send_file: ferr -1 57
]art:~$ *** 35.710000000    120000000 1300184 mg_send_http_error_impl:4650: Error 500 - [chyba
*** 35.710000000            0 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /jquery-3.5.1.min.js HTTP/1.1" 500
*** 35.710000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 35.710000000            0 1300184 worker_thread_run:18033: Connection closed
*** 35.710000000            0 1300184 consume_socket:17825: going idle
*** 35.710000000            0 1300184 consume_socket:17838: grabbed socket 5, going busy
*** 35.710000000            0 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 35.710000000            0 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 35.710000000            0 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
*** 35.720000000     10000000 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 35.720000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 35.720000000            0 1300184 handle_request:13797: URL: /jquery-3.5.1.min.js
*** 36.310000000    590000000 1299936 accept_new_connection:18112: Accepted socket 7
*** 36.310000000            0 1299936 produce_socket:17875: queued socket 7
*** 36.580000000    270000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /jquery-3.5.1.min.js HTTP/1.1" 200
*** 36.580000000            0 1300184 process_new_connection:17585: calling get_request (2 times for this connection)
*** 36.580000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 36.580000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 36.580000000            0 1300184 handle_request:13797: URL: /login.js
*** 36.640000000     60000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /login.js HTTP/1.1" 200
*** 36.640000000            0 1300184 process_new_connection:17585: calling get_request (3 times for this connection)
*** 36.650000000     10000000 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 36.650000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 36.650000000            0 1300184 handle_request:13797: URL: /logo.png
[00:00:35.710,000] <dbg> cv_test.send_file: ferr -1 57
[00:00:35.710,000] <err> cv_test: file sending error
[00:00:35.710,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e764
[00:00:36.300,000] <dbg> net_sock.zsock_accepted_cb: (rx_q[0]): parent=0x13e074, ctx=0x13e19c, st=0
[00:00:36.310,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13e19c, fd=7
[00:00:36.310,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13e19c, fd=7
[00:00:36.580,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e7f8, pkt=0x175400, st=0, user_data=0x13e88c
[00:00:36.650,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e7f8, pkt=0x175400, st=0, user_data=0x13e88c
uart:~$ *** 37.280000000    630000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /logo.png HTTP/1.1" 200
*** 37.280000000            0 1300184 process_new_connection:17585: calling get_request (4 times for this connection)
*** 38.290000000   1010000000 1300184 process_new_connection:17650: http: none, error: No data received
*** 38.290000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 38.290000000            0 1300184 worker_thread_run:18033: Connection closed
*** 38.290000000            0 1300184 consume_socket:17825: going idle
*** 38.290000000            0 1300184 consume_socket:17838: grabbed socket 6, going busy
*** 38.290000000            0 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 38.290000000            0 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 38.300000000     10000000 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
*** 38.300000000            0 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 38.300000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 38.300000000            0 1300184 handle_request:13797: URL: /js.cookie-2.2.1.min.js
*** 38.340000000     40000000 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /js.cookie-2.2.1.min.js HTTP/1.1" 200
*** 38.340000000            0 1300184 process_new_connection:17585: calling get_request (2 times for this connection)
*** 38.440000000    100000000 1300184 alloc_get_host:13189: HTTP Host: 192.0.2.1
*** 38.440000000            0 1300184 process_new_connection:17650: http: 1.1, error: none
*** 38.440000000            0 1300184 handle_request:13797: URL: /favicon.ico
*** 38.440000000            0 1300184 process_new_connection:17672: handle_request done
192.0.2.2 - "GET /favicon.ico HTTP/1.1" 404
*** 38.440000000            0 1300184 process_new_connection:17585: calling get_request (3 times for this connection)
[00:00:38.290,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e7f8
[00:00:38.440,000] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x13e88c, pkt=0x175400, st=0, user_data=(nil)
[00:00:38.440,000] <err> cv_test: cannot open /favicon.ico
[00:00:39.290,000] <err> log: argument 0 in source cv_test log message "cannot open %s" missinglog_strdup().
uart:~$ *** 39.450000000   1010000000 1300184 process_new_connection:17650: http: none, error: No data received
*** 39.450000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 39.450000000            0 1300184 worker_thread_run:18033: Connection closed
*** 39.460000000     10000000 1300184 consume_socket:17825: going idle
*** 39.460000000            0 1300184 consume_socket:17838: grabbed socket 7, going busy
*** 39.460000000            0 1300184 worker_thread_run:17985: Start processing connection from 192.0.2.2
*** 39.460000000            0 1300184 process_new_connection:17578: Start processing connection from 192.0.2.2
*** 39.460000000            0 1300184 process_new_connection:17585: calling get_request (1 times for this connection)
[00:00:39.450,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e88c
uart:~$ 
uart:~$ 
uart:~$ net mem
Fragment length 128 bytes
Network buffer pools:
Address     Total   Avail   Name
0x1c3d70    256 253 RX
0x1c3db8    256 251 TX
0x1c3f5c    96  96  RX DATA (rx_bufs)
0x1c3f98    192 184 TX DATA (tx_bufs)
uart:~$ net allocs
Network memory allocations

memory      Status  Pool    Function alloc -> freed
0x17a038/1   used      RX   tcp_conn_alloc():1109
0x175838/1   used      TX   tcp_conn_alloc():1112
0x179ff0/1   used      RX   tcp_conn_alloc():1109
0x1757f0/1   used      TX   tcp_conn_alloc():1112
0x179ed0/1   used      RX   tcp_conn_alloc():1109
0x175298/1   used      TX   tcp_conn_alloc():1112
0x1753b8/1   used      TX   net_pkt_clone():1770
0x175370/1   used      TX   net_pkt_clone():1770
0x16e248     free   RDATA   slip_input_byte():291 -> processing_data():139
0x16e278     free   RDATA   slip_input_byte():263 -> processing_data():139
0x16e248     free   RDATA   slip_input_byte():291 -> processing_data():139
0x179e88     free      RX   slip_input_byte():256 -> processing_data():139
0x16e2c0     free   RDATA   slip_input_byte():263 -> processing_data():139
0x16e230     free   RDATA   slip_input_byte():291 -> processing_data():139
0x16e2c0     free   RDATA   slip_input_byte():291 -> processing_data():139
0x16e248     free   RDATA   slip_input_byte():291 -> processing_data():139
0x16e278     free   RDATA   slip_input_byte():291 -> processing_data():139
0x175400     free      TX   tcp_out_ext():776 -> ethernet_send():685
0x175400     free      TX   net_pkt_clone():1770 -> zsock_recv_stream():1105
0x175298     free      TX   net_pkt_clone():1770 -> zsock_recv_stream():1105
0x1757a8     free      TX   net_pkt_clone():1770 -> zsock_recv_stream():1105
0x175448     free      TX   net_pkt_clone():1770 -> zsock_recv_stream():1105
0x1755b0     free      TX   net_pkt_clone():1770 -> zsock_recv_stream():1105
0x16e278     free   RDATA   slip_input_byte():263 -> processing_data():139
0x179e88     free      RX   tcp_conn_alloc():1109 -> tcp_conn_unref():392
0x175568     free      TX   tcp_conn_alloc():1112 -> tcp_conn_unref():389
0x16a5d0     free   TDATA   ethernet_fill_header():486 -> ethernet_remove_l2_header():566
0x16a600     free   TDATA   ethernet_fill_header():486 -> ethernet_remove_l2_header():566
0x175250     free      TX   tcp_out_ext():776 -> tcp_send():325
0x16a750     free   TDATA   ethernet_fill_header():486 -> ethernet_remove_l2_header():566
0x16e278     free   RDATA   slip_input_byte():291 -> processing_data():139
0x16e2a8     free   RDATA   slip_input_byte():263 -> processing_data():139
0x16e320     free   RDATA   slip_input_byte():291 -> processing_data():139
0x16e260     free   RDATA   slip_input_byte():291 -> processing_data():139
0x16e2d8     free   RDATA   slip_input_byte():291 -> processing_data():139
0x179df8     free      RX   slip_input_byte():256 -> processing_data():139
0x16e290     free   RDATA   slip_input_byte():263 -> processing_data():139
0x16e230     free   RDATA   slip_input_byte():291 -> processing_data():139
0x16e2c0     free   RDATA   slip_input_byte():291 -> processing_data():139
0x16e248     free   RDATA   slip_input_byte():291 -> processing_data():139
uart:~$ *** 69.610000000  30150000000 1300184 process_new_connection:17650: http: none, error: No data received
*** 69.610000000            0 1300184 process_new_connection:17738: Done processing connection from 192.0.2.2 (0.000000 sec)
*** 69.620000000     10000000 1300184 worker_thread_run:18033: Connection closed
*** 69.630000000     10000000 1300184 consume_socket:17825: going idle
[00:01:09.620,000] <dbg> net_sock.zsock_close_ctx: (): close ctx: ctx=0x13e19c
uart:~$
xhpohanka commented 3 years ago

I have also noticed that when I enable ASSERTS there is a strange fail, but it is probably not related with original issue

~/dev/zephyrproject/cv_test_x86$ west build -t run
-- west build: running target run
[0/1] To exit from QEMU enter: 'CTRL+a, x'[QEMU] CPU: qemu32,+nx,+pae
SeaBIOS (version rel-1.12.1-0-ga5cab58-dirty-20200625_115407-9426dddc0a1f-zephyr
)
Booting from ROM..*** Booting Zephyr OS build zephyr-v2.4.0-3346-gfd630d70c106  ***
*** 0.040000000 1359040 mg_start2:19779: [listening_ports] -> [80,443s]
*** 0.040000000 1359040 mg_start2:19779: [num_threads] -> [1]
*** 0.040000000 1359040 mg_start2:19779: [max_request_size] -> [4096]
*** 0.040000000 1359040 mg_start2:19779: [enable_keep_alive] -> [yes]
*** 0.040000000 1359040 mg_start2:19779: [keep_alive_timeout_ms] -> [1000]
[IMPLEMENTATION MISSING : sscanf]
ASSERTION FAIL [!arch_is_in_isr()] @ WEST_TOPDIR/zephyr/kernel/mutex.c:125
    mutexes cannot be used inside ISRs
FAILED: zephyr/CMakeFiles/run 
cd /home/honza/dev/zephyrproject/cv_test_x86/build && /opt/zephyr-sdk/sysroots/x86_64-pokysdk-linux/usr/bin/qemu-system-i386 -m 9 -cpu qemu32,+nx,+pae -device isa-debug-exit,iobase=0xf4,iosize=0x04 -nographic -net none -pidfile qemu.pid -chardev stdio,id=con,mux=on -serial chardev:con -mon chardev=con,mode=readline -serial unix:/tmp/slip.sock -kernel /home/honza/dev/zephyrproject/cv_test_x86/build/zephyr/zephyr.elf
ninja: build stopped: subcommand failed.
FATAL ERROR: command exited with status 1: /usr/bin/cmake --build /home/honza/dev/zephyrproject/cv_test_x86/build --target run
KozhinovAlexander commented 3 years ago

Thank you @xhpohanka for your bug report. Please try first to drastically increase all memory buffers in proj.conf using QEMU, since it is known, that CivetWeb can use big amount of memory. I'll try to get deeper look at the weekend.

xhpohanka commented 3 years ago

Hi @Nukersson, the code I provided is extracted and simplified from my project on STM32H7, it is much easier to break things on the embedded platform then with qemu_x86 but it is still possible so I expect that there are general issues, but sometimes I have a feeling that there can be also other issues related just to stm32h7 (I have already tried recent patches #30403 but it does not help here).

To break it I usally use a combination of a stress testing with wrk (eg wrk -d 5 -t 16 -c 1000 http://192.0.2.1) and simple hitting ctrl+f5 in chromium with hight frequency. The later one is usually (surprisingly) more effective to produce malfuncitons.

I'm noticing these issues

I have played with these civetweb settings

KozhinovAlexander commented 3 years ago

@xhpohanka are u comping with CONFIG_DEBUG or something else like -O3?

xhpohanka commented 3 years ago

are u comping with CONFIG_DEBUG or something else like -O3?

In my case CONFIG_DEBUG has no impact on desribed issues. I use -Os same as on stm32...

jukkar commented 3 years ago

I'm noticing these issues

* network buffers leaks (number of available `tx_bufs` decreases during the testing and never recovers)

* sometimes I get a strange state (a loop) when a `poll` call on listening sockets in civetweb's master thread still returns so `accept_new_connection()` is called even if there are no new requests from a client

* `getsockname()` call inside `accept_new_connection()` sometimes return an error (in that case zephyr's internal net_context does not have a conn_handler registered)

These might be related to other issues in the net stack if we run out of resources, so not just civetweb problems. I suspect that there is resource leak somewhere in the stack if for example a net_buf allocation fails, we might bail out without releasing all the resources properly.

jukkar commented 3 years ago

I just sent a fix that prevented various crashes seen when I tested with dumb_http_server_mt sample and wrk tool. @xhpohanka could you try your scenario with #31777 and report if it helps. The fix should help with the "network buffers leaks (number of available tx_bufs decreases during the testing and never recovers)" case you described above.

xhpohanka commented 3 years ago

Hi @jukkar Thank you for reaching this. I have done a very quick test with your patch. Now I'm not able to reproduce the issue with buffer leaks using wrk, so this is definitely a progress.

I'm still able to get a loop described in my second point (poll is still returning 1). I think that it is related to exhausted file descriptors. Chrome and ctrl+f5 seems to be worse stress than wrk...

UPDATE: I was able to reproduce the buffer leak, but it is much harder now. It was done again with chrome and ctrl+f5 monkey test and increased fd max number from 16 to 64.

uart:~$ net mem
Fragment length 128 bytes
Network buffer pools:
Address     Total   Avail   Name
0x1c1880    256 254 RX
0x1c18c8    256 250 TX
0x1c1a6c    96  96  RX DATA (rx_bufs)
0x1c1aa8    192 173 TX DATA (tx_bufs)
uart:~$ net allocs
Network memory allocations

memory      Status  Pool    Function alloc -> freed
0x177c38/1   used      RX   tcp_conn_alloc():1117
0x173438/1   used      TX   tcp_conn_alloc():1127
0x177bf0/1   used      RX   tcp_conn_alloc():1117
0x1733f0/1   used      TX   tcp_conn_alloc():1127
0x173090/1   used      TX   net_pkt_clone():1770
0x172ee0/1   used      TX   net_pkt_clone():1770
0x1733a8/1   used      TX   net_pkt_clone():1770
0x172ca0/1   used      TX   net_pkt_clone():1770
0x177140     free      RX   slip_input_byte():256 -> processing_data():139
0x16d278     free   RDATA   slip_input_byte():263 -> processing_data():139
jukkar commented 3 years ago

I was able to reproduce the buffer leak, but it is much harder now.

Yep, I was able to see it too. Seems to be related to timings, I am investigating this.

jukkar commented 3 years ago

Managed to find one nasty leak. If the application closed the socket while we were waiting data, the data that was pushed to application was lost. Fixed that in #31777, @xhpohanka please try the lastest version if you can.

KozhinovAlexander commented 3 years ago

Managed to find one nasty leak. If the application closed the socket while we were waiting data, the data that was pushed to application was lost. Fixed that in #31777, @xhpohanka please try the lastest version if you can.

Do we have some ethernet stack test suite? Can you add a test for this case?

jukkar commented 3 years ago

Do we have some ethernet stack test suite? Can you add a test for this case?

We have unit tests, not sure how feasible it would be to add test cases for this. I was only able to see the issue with heavy traffic and when system run out-of network buffers, this complicates the testing.

xhpohanka commented 3 years ago

Managed to find one nasty leak. If the application closed the socket while we were waiting data, the data that was pushed to application was lost. Fixed that in #31777, @xhpohanka please try the lastest version if you can.

I'm still able to reproduce the leaks unfortunately. Still not with wrk, but with Chrome reloading with no problem. Can I somehow provide more information which could help?

xhpohanka commented 3 years ago

but with Chrome reloading with no problem

I just noticed, that firefox behaves in the same way. It is enough to hit ctrl+f5 about 20 times in high frequency to see the buffer leak with the test code that I have provided. It does not seem to me as extra high traffic.

I'm sure on 100% but it seems net allocs is always referring lost buffers in net_pkt_clone()

0x1743b8/1   used      TX   net_pkt_clone():1765
jukkar commented 3 years ago

firefox behaves in the same way

Thanks for the info. I did not try the browser route as the wrk seemed to work fine, but will try using browser.

it seems net allocs is always referring lost buffers in net_pkt_clone()

This was basically the same leak I fixed in latest version of #31777, there is probably some extra code path I missed. I will investigate.

jukkar commented 3 years ago

will try using browser.

I was not able to replicate any leaks with the browser. Actually with the browser, I was not seeing any out-of-buffer scenarios and zephyr was able to reply in time and no errors were seen in the console (this with qemu_x86 and e1000 controller). I was also using the dumb_http_server_mt sample app for this.

xhpohanka commented 3 years ago

I was also using the dumb_http_server_mt sample app for this

I'm afraid that dumb_http_server_mt is not enough to reproduce. That is the reason why I have provided my code with civetweb (check the first post). If you are not able to run it please tell me what other information can I provide.

I'm aware that the issue can be in my application code (hopefully not, it is really simple) or in civetweb itself but as civetweb is the only web server provided with zephyr we should find it.

I noticed the issues only on a page that downloads some css or js, that could be the reason why wrk does not trigger it because it does not parse the server response.

jukkar commented 3 years ago

@xhpohanka When you have the leak issue, what does net conn tell, what are the states of the sockets. If you see something like

TCP        Context   Src port Dst port   Send-Seq   Send-Ack  MSS    State
0x14e688 0x126fe0    8080        0 2016716979          0  1440   LISTEN
0x14e4f4 0x127090    8080    38032 4017182613          0  1460   LISTEN
0x14d6c0 0x1271f0   55257    34238 3129739646 1034923133  1460   SYN_RECEIVED

and the SYN_RECEIVED state is stuck. Then you also need to apply #31806 which should timeout the orphaned connection properly.

jukkar commented 3 years ago

I noticed the issues only on a page that downloads some css or js

That might be related here. I try to use you application next.

xhpohanka commented 3 years ago

I do not see SYN_RECEIVED stuck state...

uart:~$ net mem
Fragment length 128 bytes
Network buffer pools:
Address     Total   Avail   Name
0x1c7c50    256 254 RX
0x1c7c98    256 252 TX
0x1c7e3c    96  96  RX DATA (rx_bufs)
0x1c7e78    192 183 TX DATA (tx_bufs)

uart:~$ net conn
     Context    Iface         Flags Local               Remote
[ 1] 0x140fe0   0x1c7eb4    4DU   224.0.0.251:5353         0.0.0.0:0
[ 2] 0x141074   0x1c7eb4    4ST         0.0.0.0:80   192.0.2.2:33008
[ 3] 0x141108   0x1c7eb4    4ST        0.0.0.0:443         0.0.0.0:0

TCP        Context   Src port Dst port   Send-Seq   Send-Ack  MSS    State
0x18382c 0x141074      80    33008 3001513734          0  1460   LISTEN
0x183698 0x141108     443        0  706889854          0  1460   LISTEN
No active connections.

uart:~$ net allocs
Network memory allocations

memory      Status  Pool    Function alloc -> freed
0x17e038/1   used      RX   tcp_conn_alloc():1104
0x179838/1   used      TX   tcp_conn_alloc():1112
0x17dff0/1   used      RX   tcp_conn_alloc():1104
0x1797f0/1   used      TX   tcp_conn_alloc():1112
0x179400/1   used      TX   net_pkt_clone():1765
0x1795b0/1   used      TX   net_pkt_clone():1765
0x17dfa8     free      RX   slip_input_byte():256 -> processing_data():139
...

update: and #31806 also has no impact here...

jukkar commented 3 years ago

I am probably doing something wrong as I get

cv_test/src/libc_extensions.c:279:5: error: redefinition of 'putc'
  279 | int putc(int c, FILE *stream)
      |     ^~~~
In file included from cv_test/src/libc_extensions.c:9:
cv_test/zephyr/lib/libc/minimal/include/stdio.h:59:19: note: previous definition of 'putc' was here
   59 | static inline int putc(int c, FILE *stream)
      |                   ^~~~
cv_test/src/libc_extensions.c:284:5: error: redefinition of 'putchar'
  284 | int putchar(int c)
      |     ^~~~~~~
In file included from cv_test/src/libc_extensions.c:9:
cv_test/zephyr/lib/libc/minimal/include/stdio.h:63:19: note: previous definition of 'putchar' was here
   63 | static inline int putchar(int c)
      |                   ^~~~~~~
make[3]: *** [CMakeFiles/app.dir/build.make:76: CMakeFiles/app.dir/src/libc_extensions.c.obj] Error 1

How do you compile this?

I tried with this:

cmake -B build -DBOARD=qemu_x86 . -DOVERLAY_CONFIG=zephyr/samples/net/sockets/echo_server/overlay-e1000.conf  -DCONFIG_NET_DEBUG_NET_PKT_ALLOC=y -DCONFIG_LOG_BUFFER_SIZE=65536
make -C build -j 9  run
xhpohanka commented 3 years ago

I see - I'm using slightly older zephyr base (with your patches cherry-picked). There was a commit 98747abf9c3671e9b836dba4c8c8ae48c47f0c23 which added putc and putchar into minimal libc library. Please just comment out my putc and putchar definitions in libc_extensions.c

update: I have just reproduced it again using your branch tcp2-release-resources-when-out-of-mem and firefox and the same build command as you.

jukkar commented 3 years ago

The mkmfs.sh needed xxd and after installing it, I still get this error

In file included from cv_test/src/mfs.c:2:
cv_test/build/zephyr/include/generated/mfs_data.h:3582:1: error: expected expression before ',' token
 3582 | ,
      | ^
make[3]: *** [CMakeFiles/app.dir/build.make:102: CMakeFiles/app.dir/src/mfs.c.obj] Error 1

It seems that the script requires minify ~from https://www.minifier.org/~

I wonder why you have extra generator script, wouldn't the generate_inc_file cmake macros work?

Edit: the minify link does not seem to be proper for the minify program, where should I get it?

xhpohanka commented 3 years ago

Excuse me. It seems, that I have not simplified my example enough... The reason of the last error is probably missing minify (at least I get the same error in such case). Minify is definitely not necessary to run this example. I have pushed a new version to my git, I hope it will work now.

I wonder why you have extra generator script, wouldn't the generate_inc_file cmake macros work?

It probably would, but it was written by my colleague who is not familiar with zephyr build system.

jukkar commented 3 years ago

I managed to see the issue (used firefox, and just kept ctrl-f5 pressed for several seconds). What looks suspicious is that net-shell shows this loop of debug messages

....
[INTERNAL ERROR]: accept_new_connection @ 18117
accept_new_connection: getsockname() failed: EINVAL
[00:12:32.120,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13ee84, fd=7
uart:~$ [INTERNAL ERROR]: accept_new_connection @ 18117
accept_new_connection: getsockname() failed: EINVAL
[00:12:32.140,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13f040, fd=11
[00:12:32.140,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13f040, fd=11
[00:12:33.140,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13ee84, fd=8
[00:12:33.140,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13ee84, fd=8
uart:~$ [INTERNAL ERROR]: accept_new_connection @ 18117
accept_new_connection: getsockname() failed: EINVAL
[INTERNAL ERROR]: accept_new_connection @ 18117
accept_new_connection: getsockname() failed: EINVAL
[INTERNAL ERROR]: accept_new_connection @ 18117
accept_new_connection: getsockname() failed: EINVAL
[00:12:33.160,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13f040, fd=12
[00:12:33.160,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13f040, fd=12
[00:12:34.140,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13ee84, fd=9
[00:12:34.140,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13ee84, fd=9
[00:12:34.160,000] <dbg> net_sock.zsock_accept_ctx: (): accept: ctx=0x13f040, fd=13
[00:12:34.160,000] <dbg> net_sock.z_impl_zsock_getsockname: (): getsockname: ctx=0x13f040, fd=13
....

I do not see anyone reading the data away, thus the net_pkt are just pending in the receive queue even if the connections have died long time ago. Did not investigate civetweb that deeply, but after the accept, it really needs to call recv or similar, otherwise the packets are just hanging there. The net-shell shows that TX packets are running out, don't know what is going on there. It might be that we are using wrong net_pkt pool (TX instead of RX). Anyway, looks like there is something fishy with the civetweb or the application and recv is not called.

xhpohanka commented 3 years ago

Hi @jukkar, the suspicious state from previous comment appears when the app is running out of free file descriptors. Civetweb is probably handling this wrong. I cannot reproduce it when I increase the CONFIG_POSIX_MAX_FDS to some higher number (48).

I noticed that your fixes were merged to master so I rechecked my app again against actual master. It is much better, however I was still able to see a leak. It takes really big effort with ctrl+f5, but it is sometimes there. Next to the number of fds I have also increased a number of ciwetweb worker threads to 4.

jukkar commented 3 years ago

I was still able to see a leak

Yep, I saw that too but it does not look it comes from tcp as I wrote in my earlier comment. After the TCP has received the data, it is put the socket receive queue. If no one is reading that queue, we basically have a "leak". And it looked like that from my limited testing.

xhpohanka commented 3 years ago

I saw that too but it does not look it comes from tcp

Can you give me a hint what is a best way to trace it, please? I'd really like to have this reliable...

jukkar commented 3 years ago

Can you give me a hint what is a best way to trace it, please? I'd really like to have this reliable...

Usually I just place debug prints in relevant places in the code. For the accept loop log above, I needed to disable civetweb debugging prints because there was just too much data printed. If you are using native_posix board, then debugging with gdb is of course quite convenient. I did not verify this, but because there was just lot of prints about accept (in a loop), but no prints about data being read, it looked like the receive queue in subsys/net/lib/sockets/sockets.c was not being read. As the receive queue is shared with accept queue, it is also possible that there is some bug in sockets.c related to accept/read functionality that is seen if we have these net_buf/pkt allocation issues. But after a quick review, I did not spot immediately where such issue would be in sockets.c.

KozhinovAlexander commented 3 years ago

@xhpohanka Sorry, I do not have currently the capacity to work on this topic. How is it going? Does provided changes fixed your problem?

@jukkar Thanks for your very fast support!

xhpohanka commented 3 years ago

Hello @Nukersson,

fixes by @jukkar definitely helped. I still have a feeling that it is not 100% but so far I fixed it just by providing bigger number of fds and praying that our project is not failing in production....

github-actions[bot] commented 3 years ago

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.

neja20 commented 2 years ago

Bump! Still happening on stm32h7xx. Just had a rough few weeks with the same exact problem. Dummy hold F5 key test with Firefox over HTTPS(not HTTP) manages to break things in couple of seconds. There seems to be a race condition in the tcp stack regarding the RX net_pkt leaks between the connection and listen thread when the stack is running out of free net_pkts. It happens with the civetweb and with custom https server aswell. What fixed the issue for me was setting the these threads with Cooperative priority, which isnt nice but at least there are no RX net_pkt leaks.

neja20 commented 2 years ago

Finally i have found a soultion to the leak. Please have a look at my pull request #42328 . I hope the pull request explains it all. All in all it was a simple fix, however damn hard to find :)

I am new to the github contribution system, so excuse me if i am doing something wrong. @jukkar i have seen you under the network related issues, thats why i am mentioning you.

Thank you for cooperation

xhpohanka commented 2 years ago

Hi @neja20, thanks for reaching this out. I will try your patch later this week, from the description it looks reasonable to me, but I'm not so familiar with the stack to comment it deeper.

Regarding the PR, you definitely need to keep zephyr coding style (tab indenting width 8 etc.). You can check if your commit is ok with checkpath.pl script. It will help you to find contributing issues before pushing it to github. I usually use it like this scripts/checkpatch.pl -g HEAD, it checks your latest commit.