search

Stiffstream / restinio

Cross-platform, efficient, customizable, and robust asynchronous HTTP(S)/WebSocket server C++ library with the right balance between performance and ease of use
Other
1.15k stars 93 forks source link

Error when handling cancelled request #72

Closed lpc921 closed 4 years ago

lpc921 commented 4 years ago

I am not sure the way I am using the library is correct. I have a following scenario that causes segfault on the server. Could you tell me how to prevent it from happening? I am using Ubuntu 18.04 gcc 8.3.0 restinio 0.6.3

  1. Run the server on a single thread
  2. The client sends a request (request 1) that will take the server some time to process
  3. Before request 1 is processed, the client sends a get file request (request 2)
  4. Then the client cancels request 2, closing the socket
  5. Server finished processing request 1, Restinio sends the response to request 1
  6. Restinio receives request 2 from asio io_context
  7. Restinio starts to send the file, but socket has already closed.
  8. SIGPIPE signal received by program. I added custom signal handler to ignored SIGPIPE.
  9. Somehow the program segfaults

Here is the debugger output:

Thread 2 "my_application" received signal SIGPIPE, Broken pipe.
[Switching to Thread 0x7fffd43d4700 (LWP 81744)]
0x00007ffff527920a in sendfile64 () at ../sysdeps/unix/syscall-template.S:78
Execute debugger commands using "-exec <command>", for example "-exec info registers" will list registers in use (when GDB is the debugger)

Thread 2 "my_application" received signal SIGSEGV, Segmentation fault.
0x0000555555663b06 in restinio::impl::connection_t<restinio::traits_t<restinio::asio_timer_manager_t, restinio::ostream_logger_t<std::mutex>, restinio::router::express_router_t<restinio::router::std_regex_engine_t>, asio::strand<asio::executor>, asio::basic_stream_socket<asio::ip::tcp> > >::trigger_error_and_close<restinio::impl::connection_t<restinio::traits_t<restinio::asio_timer_manager_t, restinio::ostream_logger_t<std::mutex>, restinio::router::express_router_t<restinio::router::std_regex_engine_t>, asio::strand<asio::executor>, asio::basic_stream_socket<asio::ip::tcp> > >::after_write(std::error_code const&)::{lambda()#1}>(restinio::impl::connection_t<restinio::traits_t<restinio::asio_timer_manager_t, restinio::ostream_logger_t<std::mutex>, restinio::router::express_router_t<restinio::router::std_regex_engine_t>, asio::strand<asio::executor>, asio::basic_stream_socket<asio::ip::tcp> > >::after_write(std::error_code const&)::{lambda()#1}) (this=0x7265206174616420, msg_builder=...) at /home/user/.conan/data/restinio/0.6.3/stiffstream/stable/package/2b1655ba4f04bdcb7f354392a000e3c3a7cc4674/include/restinio/impl/connection.hpp:1357

Console logger. The long request starts at [2020-02-07 11:04:14.673] 

[2020-02-07 11:04:05.361] TRACE: starting server on 0.0.0.0:9000
[2020-02-07 11:04:05.361]  INFO: init accept #0
[2020-02-07 11:04:05.361]  INFO: server started on 0.0.0.0:9000
[2020-02-07 11:04:11.214] TRACE: accept connection from 192.168.229.1:14398 on socket #0
[2020-02-07 11:04:11.214] TRACE: [connection:1] start connection with 192.168.229.1:14398
[2020-02-07 11:04:11.214] TRACE: [connection:1] start waiting for request
[2020-02-07 11:04:11.214] TRACE: [connection:1] continue reading request
[2020-02-07 11:04:11.215] TRACE: [connection:1] received 473 bytes
[2020-02-07 11:04:11.215] TRACE: [connection:1] request received (#0): GET /trigger
[2020-02-07 11:04:11.215] TRACE: [connection:1] append response (#0), flags: { final_parts, connection_keepalive }, write group size: 2
[2020-02-07 11:04:11.215] TRACE: [connection:1] start next write group for response (#0), size: 2
[2020-02-07 11:04:11.215] TRACE: [connection:1] start response (#0): HTTP/1.1 200 OK
[2020-02-07 11:04:11.215] TRACE: [connection:1] sending resp data, buf count: 2, total size: 219
[2020-02-07 11:04:11.215] TRACE: [connection:1] start waiting for request
[2020-02-07 11:04:11.215] TRACE: [connection:1] continue reading request
[2020-02-07 11:04:11.215] TRACE: [connection:1] outgoing data was sent: 219 bytes
[2020-02-07 11:04:11.215] TRACE: [connection:1] finishing current write group
[2020-02-07 11:04:11.215] TRACE: [connection:1] should keep alive
[2020-02-07 11:04:11.215] TRACE: [connection:1] start waiting for request
[2020-02-07 11:04:11.215] TRACE: [connection:1] skip read operation: already running
[2020-02-07 11:04:11.278] TRACE: accept connection from 192.168.229.1:14399 on socket #0
[2020-02-07 11:04:11.278] TRACE: [connection:2] start connection with 192.168.229.1:14399
[2020-02-07 11:04:11.278] TRACE: [connection:2] start waiting for request
[2020-02-07 11:04:11.278] TRACE: [connection:2] continue reading request
[2020-02-07 11:04:11.279] TRACE: [connection:2] received 459 bytes
[2020-02-07 11:04:11.280] TRACE: [connection:2] request received (#0): GET /frame/1
[2020-02-07 11:04:11.280] TRACE: [connection:2] append response (#0), flags: { final_parts, connection_keepalive }, write group size: 2
[2020-02-07 11:04:11.280] TRACE: [connection:2] start next write group for response (#0), size: 2
[2020-02-07 11:04:11.280] TRACE: [connection:2] start response (#0): HTTP/1.1 200 OK
[2020-02-07 11:04:11.280] TRACE: [connection:2] sending resp data, buf count: 1, total size: 200
[2020-02-07 11:04:11.280] TRACE: [connection:2] start waiting for request
[2020-02-07 11:04:11.280] TRACE: [connection:2] continue reading request
[2020-02-07 11:04:11.280] TRACE: [connection:2] outgoing data was sent: 200 bytes
[2020-02-07 11:04:11.280] TRACE: [connection:2] sending resp file data, total size: 32425
[2020-02-07 11:04:11.280] TRACE: [connection:2] file data was sent: 32425 bytes
[2020-02-07 11:04:11.280] TRACE: [connection:2] finishing current write group
[2020-02-07 11:04:11.280] TRACE: [connection:2] should keep alive
[2020-02-07 11:04:11.280] TRACE: [connection:2] start waiting for request
[2020-02-07 11:04:11.280] TRACE: [connection:2] skip read operation: already running
[2020-02-07 11:04:14.673] TRACE: [connection:1] received 493 bytes
[2020-02-07 11:04:14.673] TRACE: [connection:1] request received (#1): POST /trigger
[2020-02-07 11:04:17.737] TRACE: [connection:1] append response (#1), flags: { final_parts, connection_keepalive }, write group size: 2
[2020-02-07 11:04:17.737] TRACE: [connection:1] start next write group for response (#1), size: 2
[2020-02-07 11:04:17.737] TRACE: [connection:1] start response (#1): HTTP/1.1 503 Service Unavailable
[2020-02-07 11:04:17.737] TRACE: [connection:1] sending resp data, buf count: 2, total size: 299
[2020-02-07 11:04:17.738] TRACE: [connection:1] start waiting for request
[2020-02-07 11:04:17.738] TRACE: [connection:1] continue reading request
[2020-02-07 11:04:17.738] TRACE: [connection:1] outgoing data was sent: 299 bytes
[2020-02-07 11:04:17.738] TRACE: [connection:1] finishing current write group
[2020-02-07 11:04:17.738] TRACE: [connection:1] should keep alive
[2020-02-07 11:04:17.738] TRACE: [connection:1] start waiting for request
[2020-02-07 11:04:17.738] TRACE: [connection:1] skip read operation: already running
[2020-02-07 11:04:17.738] TRACE: [connection:2] received 459 bytes
[2020-02-07 11:04:17.738] TRACE: [connection:2] request received (#1): GET /frame/2
[2020-02-07 11:04:17.738] TRACE: [connection:2] append response (#1), flags: { final_parts, connection_keepalive }, write group size: 2
[2020-02-07 11:04:17.738] TRACE: [connection:2] start next write group for response (#1), size: 2
[2020-02-07 11:04:17.738] TRACE: [connection:2] start response (#1): HTTP/1.1 200 OK
[2020-02-07 11:04:17.738] TRACE: [connection:2] sending resp data, buf count: 1, total size: 200
[2020-02-07 11:04:17.738] TRACE: [connection:2] start waiting for request
[2020-02-07 11:04:17.738] TRACE: [connection:2] continue reading request
[2020-02-07 11:04:17.738] TRACE: accept connection from 192.168.229.1:14412 on socket #0
[2020-02-07 11:04:17.738] TRACE: [connection:3] start connection with 192.168.229.1:14412
[2020-02-07 11:04:17.739] TRACE: [connection:3] start waiting for request
[2020-02-07 11:04:17.739] TRACE: [connection:3] continue reading request
[2020-02-07 11:04:17.739] TRACE: [connection:2] outgoing data was sent: 200 bytes
[2020-02-07 11:04:17.739] TRACE: [connection:2] sending resp file data, total size: 32425
[2020-02-07 11:04:46.576] ERROR: [connection:2] send file data error: 32 (Broken pipe) bytes
eao197 commented 4 years ago

Hi! Thanks for reporting.

We'll investigate that case as soon as we get some time for it.

eao197 commented 4 years ago

Hi, @lpc921!

Can you try the current version from 0.6-dev branch? I think we've found and fixed the problem.

lpc921 commented 4 years ago

Hi, @eao197

Thanks so much for the fast response. I can confirm this issue is fixed for me when sending a file to the client.

I still need to catch and ignore SIGPIPE. I guess that's the correct / safe way to handle sendfile with partially-read response?

eao197 commented 4 years ago

I still need to catch and ignore SIGPIPE. I guess that's the correct / safe way to handle sendfile with partially-read response?

I don't know how sendfile and sendfile64 OS-calls are implemented under the hood. So it seems that on Linux (and other flavors of Unixes) the behavior of sendfile looks like the behavior of write for a pipe so you have to deal with SIGPIPE.

eao197 commented 4 years ago

The fix for that issue is in v.0.6.4 released today. This version is available via Conan.