zephyr: civetweb hangs when there are no free filedescriptors
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:~$
About this issue
- Original URL
- State: closed
- Created 3 years ago
- Comments: 35 (28 by maintainers)
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…
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.