flush() doesn't actually flush

[i-am-justin-dick]

I am using the test program below and restinio v. 0.6.13. When calling flush on a chunked response builder, and using curl -N as a test client, only the first flush() is honored. The rest of the data isn't actually sent until done() is called. This seems to defeat the purpose of a chunked response. Furthermore, the data sent as part of the final write is garbage, because the original object is out of scope.

The problem seems to be that although the first chunk is sent when flush() is called, restinio is not properly notified that this has completed and continues to believe it is in the middle of a write. That is, m_write_output_ctx.transmitting() is always true even when the data has been sent. You can see this behavior in that curl reports the data was received right after the flush(), but the log line [2021-06-15 09:25:19.661] TRACE: [connection:1] outgoing data was sent: 185 bytes isn't printed until after done() is called.

#pragma GCC diagnostic push
#pragma GCC diagnostic ignored "-Wconversion"
#pragma GCC diagnostic ignored "-Wsign-conversion"
#include <restinio/all.hpp>
#pragma GCC diagnostic pop

#include <iostream>
using namespace std::literals;

int main()
{
   try
   {
      using router_t = restinio::router::express_router_t<>;
      using traits_t = restinio::traits_t<
         restinio::asio_timer_manager_t,
         restinio::single_threaded_ostream_logger_t,
         router_t>;

      auto router = std::make_unique<router_t>();

      router->http_get(R"(/stream/:ID(\d+))", [&] (auto request, [[ maybe_unused ]] const auto & params) {
         auto response = request->template create_response<restinio::chunked_output_t>();
         response
            .append_header( "Server", "test" )
            .append_header_date_field()
            .append_header( restinio::http_field::content_type, "text/plain; charset=utf-8" );

         for (int i = 0; i < 5; i++) {
            std::string data(16, 'j' + i);
            response.append_chunk(restinio::const_buffer(data.data(), data.size()));
            response.flush([] (auto ec) {
               std::cout << "Data sent, per the callback.  Error code = " << ec << std::endl;
            });
            std::this_thread::sleep_for(1s);
         }
         response.done();

         return restinio::request_handling_status_t::accepted;
      });

      restinio::run(
         restinio::on_thread_pool<traits_t>(4)
            .port(8080)
            .address("localhost")
            .request_handler(std::move(router))
      );
   }
   catch (const std::exception & e)
   {
      std::cout << "Exception caught in Restinio main loop: " << e.what() << std::endl;
   }

   return 0;
}

Logs:

[2021-06-15 09:25:11.164] TRACE: starting server on 127.0.0.1:8080
[2021-06-15 09:25:11.165]  INFO: init accept #0
[2021-06-15 09:25:11.165]  INFO: server started on 127.0.0.1:8080
[2021-06-15 09:25:14.646] TRACE: accept connection from 127.0.0.1:51461 on socket #0
[2021-06-15 09:25:14.646] TRACE: [connection:1] start connection with 127.0.0.1:51461
[2021-06-15 09:25:14.646] TRACE: [connection:1] start waiting for request
[2021-06-15 09:25:14.646] TRACE: [connection:1] continue reading request
[2021-06-15 09:25:14.646] TRACE: [connection:1] received 88 bytes
[2021-06-15 09:25:14.646] TRACE: [connection:1] request received (#0): GET /stream/123
[2021-06-15 09:25:14.646] TRACE: [connection:1] append response (#0), flags: { not_final_parts, connection_keepalive }, write group size: 4
[2021-06-15 09:25:14.646] TRACE: [connection:1] start next write group for response (#0), size: 4
[2021-06-15 09:25:14.646] TRACE: [connection:1] start response (#0): HTTP/1.1 200 OK
[2021-06-15 09:25:14.646] TRACE: [connection:1] sending resp data, buf count: 4, total size: 185
[2021-06-15 09:25:15.650] TRACE: [connection:1] append response (#0), flags: { not_final_parts, connection_keepalive }, write group size: 3
[2021-06-15 09:25:16.653] TRACE: [connection:1] append response (#0), flags: { not_final_parts, connection_keepalive }, write group size: 3
[2021-06-15 09:25:17.656] TRACE: [connection:1] append response (#0), flags: { not_final_parts, connection_keepalive }, write group size: 3
[2021-06-15 09:25:18.656] TRACE: [connection:1] append response (#0), flags: { not_final_parts, connection_keepalive }, write group size: 3
[2021-06-15 09:25:19.660] TRACE: [connection:1] append response (#0), flags: { final_parts, connection_keepalive }, write group size: 1
[2021-06-15 09:25:19.661] TRACE: [connection:1] outgoing data was sent: 185 bytes
[2021-06-15 09:25:19.661] TRACE: [connection:1] finishing current write group
Data sent, per the callback.  Error code = system:0
[2021-06-15 09:25:19.661] TRACE: [connection:1] should keep alive
[2021-06-15 09:25:19.661] TRACE: [connection:1] start next write group for response (#0), size: 3
[2021-06-15 09:25:19.661] TRACE: [connection:1] sending resp data, buf count: 3, total size: 22
[2021-06-15 09:25:19.661] TRACE: [connection:1] outgoing data was sent: 22 bytes
[2021-06-15 09:25:19.661] TRACE: [connection:1] finishing current write group
Data sent, per the callback.  Error code = system:0
[2021-06-15 09:25:19.661] TRACE: [connection:1] should keep alive
[2021-06-15 09:25:19.661] TRACE: [connection:1] start next write group for response (#0), size: 3
[2021-06-15 09:25:19.661] TRACE: [connection:1] sending resp data, buf count: 3, total size: 22
[2021-06-15 09:25:19.661] TRACE: [connection:1] outgoing data was sent: 22 bytes
[2021-06-15 09:25:19.661] TRACE: [connection:1] finishing current write group
Data sent, per the callback.  Error code = system:0
[2021-06-15 09:25:19.661] TRACE: [connection:1] should keep alive
[2021-06-15 09:25:19.661] TRACE: [connection:1] start next write group for response (#0), size: 3
[2021-06-15 09:25:19.661] TRACE: [connection:1] sending resp data, buf count: 3, total size: 22
[2021-06-15 09:25:19.661] TRACE: [connection:1] outgoing data was sent: 22 bytes
[2021-06-15 09:25:19.661] TRACE: [connection:1] finishing current write group
Data sent, per the callback.  Error code = system:0
[2021-06-15 09:25:19.661] TRACE: [connection:1] should keep alive
[2021-06-15 09:25:19.661] TRACE: [connection:1] start next write group for response (#0), size: 3
[2021-06-15 09:25:19.661] TRACE: [connection:1] sending resp data, buf count: 3, total size: 22
[2021-06-15 09:25:19.661] TRACE: [connection:1] outgoing data was sent: 22 bytes
[2021-06-15 09:25:19.661] TRACE: [connection:1] finishing current write group
Data sent, per the callback.  Error code = system:0
[2021-06-15 09:25:19.661] TRACE: [connection:1] should keep alive
[2021-06-15 09:25:19.661] TRACE: [connection:1] start next write group for response (#0), size: 1
[2021-06-15 09:25:19.661] TRACE: [connection:1] sending resp data, buf count: 1, total size: 5
[2021-06-15 09:25:19.662] TRACE: [connection:1] outgoing data was sent: 5 bytes
[2021-06-15 09:25:19.662] TRACE: [connection:1] finishing current write group
[2021-06-15 09:25:19.662] TRACE: [connection:1] should keep alive
[2021-06-15 09:25:19.662] TRACE: [connection:1] start waiting for request
[2021-06-15 09:25:19.662] TRACE: [connection:1] continue reading request
[2021-06-15 09:25:19.662] TRACE: [connection:1] EOF and no request, close connection
[2021-06-15 09:25:19.662] TRACE: [connection:1] close
[2021-06-15 09:25:19.662] TRACE: [connection:1] close: close socket
[2021-06-15 09:25:19.662] TRACE: [connection:1] close: timer canceled
[2021-06-15 09:25:19.662] TRACE: [connection:1] close: reset responses data
[2021-06-15 09:25:19.662] TRACE: [connection:1] destructor called

CURL Client command:

curl -N localhost:8080/stream/123 | od -t x1

[eao197]

Hi!

I don't see anything wrong with RESTinio's behavior. When you call sleep_for you block the thread that is using for serving I/O operations related to the request. So RESTinio actually performs write operations only when you return the control by exiting your request handler. More about RESTinio's threading model could be found here.

An example of using RESTinio's chunked_output and timer can be found here.

[i-am-justin-dick]

Ah, thank you for the info. I had looked at the function make_resp_for_large_count() in the compression example which was using chunked output and it seemed to indicate you could alternate append_chunk() and flush() calls. Which I suppose technically you can - the chunks just won't be sent until the end. :)

Anyway, thanks for the clarification and docs. I'll switch to a dispatch model of some kind. Thanks for your great work on this open source project!!!