Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

How to properly close HTTP Chunked Encoding stream? #5020

Closed
vladfaust opened this issue Sep 22, 2017 · 6 comments
Closed

How to properly close HTTP Chunked Encoding stream? #5020

vladfaust opened this issue Sep 22, 2017 · 6 comments

Comments

@vladfaust
Copy link
Contributor

vladfaust commented Sep 22, 2017

I want to implement a HTTP Chunked Encoding client reconnecting to a server every 3 seconds. Despite of rescuing everywhere, it still throws Broken pipe (Errno) errors. What is the proper way to close an infinite stream so a server knows it and reconnect to the server afterwards?

My usecase is streaming from Twitter Stream API.

Related to #4991.

Try it yourself:

require "http/server"

port = 5000

server = HTTP::Server.new(port) do |context|
  puts "Server: got request"
  begin
    loop do
      puts "Server: writing response"
      context.response.puts "foobar\n"
      context.response.flush
      sleep 1
    end
  rescue ex
    puts "Server rescued from #{ex}"
  end
end

spawn do
  loop do
    begin
      puts "Server: listening on #{port}"
      server.listen
    rescue ex
      puts "Server: .listen rescued from #{ex}"
    end
  end
end

require "http/client"

client = HTTP::Client.new("localhost", port)

spawn do
  loop do
    begin
      puts "Client: connecting to the server"
      client.get("/") do |response|
        puts "Client: begin streaming"
        loop do
          puts "Client: got response \"" + response.body_io.gets.not_nil! + "\""
        end
      end
    rescue ex
      puts "Client: .get rescued from #{ex}"
    end
  end
end

loop do
  sleep 3
  begin
    puts "Client: time to close"
    client.close
  rescue ex
    puts "Client: .close rescued from #{ex}"
  end
end

Logs:

Server: listening on 5000
Client: connecting to the server
Server: got request
Server: writing response
Client: begin streaming
Client: got response "foobar"
Server: writing response
Client: got response "foobar"
Server: writing response
Client: got response "foobar"
Client: time to close
Client: .get rescued from Error reading file: Bad file descriptor
Client: connecting to the server
Server: writing response # What? I said close! No more responses!
Server: got request
Server: writing response
Client: begin streaming
Client: got response "foobar"
Server: writing response
Server rescued from Error writing file: Broken pipe # Huh, now you see it's closed
Unhandled exception in spawn:
Error writing file: Broken pipe (Errno)
0x4aedd7: *CallStack::unwind:Array(Pointer(Void)) at ??
0x59ff7b: unbuffered_write at /opt/crystal/src/io/file_descriptor.cr 276:11
0x59fbb8: flush at /opt/crystal/src/io/buffered.cr 186:5
0x5a034d: close at /opt/crystal/src/io/buffered.cr 194:5
0x59ad24: process at /opt/crystal/src/http/server/request_processor.cr 65:7
0x5925a9: process at /opt/crystal/src/http/server/request_processor.cr 16:3
0x5924c0: handle_client at /opt/crystal/src/http/server.cr 191:5
0x4c5ebe: run at /opt/crystal/src/fiber.cr 255:3
0x499926: ~proc2Proc(Fiber, (IO::FileDescriptor | Nil)) at /opt/crystal/src/concurrent.cr 61:3
0x0: ??? at ??
Server: writing response # It's the second connection, I suppose
Client: got response "foobar"
Server: writing response
Client: got response "foobar"
Client: time to close
Client: .get rescued from Error reading file: Bad file descriptor
Client: connecting to the server
Server: got request
Server: writing response
Client: begin streaming
Client: got response "foobar"
Server: writing response
Server: writing response # Missing?
Client: got response "foobar"
Server: writing response
Server rescued from Error writing file: Broken pipe # WTF
Unhandled exception in spawn:
Error writing file: Broken pipe (Errno)
0x59ff7b: unbuffered_write at /opt/crystal/src/io/file_descriptor.cr 276:11
0x59fbb8: flush at /opt/crystal/src/io/buffered.cr 186:5
0x5a034d: close at /opt/crystal/src/io/buffered.cr 194:5
0x59ad24: process at /opt/crystal/src/http/server/request_processor.cr 65:7
0x5925a9: process at /opt/crystal/src/http/server/request_processor.cr 16:3
0x5924c0: handle_client at /opt/crystal/src/http/server.cr 191:5
0x4c5ebe: run at /opt/crystal/src/fiber.cr 255:3
0x499926: ~proc2Proc(Fiber, (IO::FileDescriptor | Nil)) at /opt/crystal/src/concurrent.cr 61:3
0x0: ??? at ??
Server: writing response
Client: got response "foobar"
...
@petoem
Copy link
Contributor

petoem commented Sep 25, 2017

@vladfaust I modified your example to see, to what client the server wants to send a response to.
The first client connects on 00:19:18, after 3 seconds the client disconnects and a another client connects. Because the loop from the first client still runs, it resumes after sleep and tries to write a response to a not connected client. Which should raise and be rescued, but nothing happens and the loop continues. At the second iteration it tries again and throws.
It is weird that it only fails at the second attempt.

Another thing is that I haven't found any method which could be used to check whether a client is still connected. I tried context.response.closed? but it always returns false (because the including class doesn't seem to use it).

server = HTTP::Server.new(port) do |context|
  req_time = Time.now
  puts "Server: got request #{req_time}"
  begin
    loop do
      puts "Server: writing response # #{req_time}"
      context.response.puts "foobar\n"
      context.response.flush
      sleep 1
    end
  rescue ex
    puts "Server rescued from #{ex}"
  end
end

Output:

Server: listening on 5000
Client: connecting to the server
Server: got request 2017-09-26 00:19:18 +0200
Server: writing response # 2017-09-26 00:19:18 +0200
Client: begin streaming
Client: got response "foobar"
Server: writing response # 2017-09-26 00:19:18 +0200
Client: got response "foobar"
Server: writing response # 2017-09-26 00:19:18 +0200
Client: got response "foobar"
Client: time to close
Client: .get rescued from Error reading file: Bad file descriptor
Client: connecting to the server
Server: got request 2017-09-26 00:19:21 +0200
Server: writing response # 2017-09-26 00:19:21 +0200
Client: begin streaming
Client: got response "foobar"
Server: writing response # 2017-09-26 00:19:18 +0200
Server: writing response # 2017-09-26 00:19:21 +0200
Client: got response "foobar"
Server: writing response # 2017-09-26 00:19:18 +0200
Server rescued from Error writing file: Broken pipe
Unhandled exception in spawn:
Error writing file: Broken pipe (Errno)
0x4d02ebaca33: unbuffered_write at /usr/lib/crystal/io/file_descriptor.cr 276:11
0x4d02ebac678: flush at /usr/lib/crystal/io/buffered.cr 186:5
0x4d02ebace0d: close at /usr/lib/crystal/io/buffered.cr 194:5
0x4d02eba77d4: process at /usr/lib/crystal/http/server/request_processor.cr 65:7
0x4d02eb9f059: process at /usr/lib/crystal/http/server/request_processor.cr 16:3
0x4d02eb9ef70: handle_client at /usr/lib/crystal/http/server.cr 191:5
0x4d02ead2a1e: run at /usr/lib/crystal/fiber.cr 255:3
0x4d02eaa6206: ~proc2Proc(Fiber, (IO::FileDescriptor | Nil)) at /usr/lib/crystal/concurrent.cr 61:3
0x0: ??? at ??
Server: writing response # 2017-09-26 00:19:21 +0200
Client: got response "foobar"
Client: time to close
Client: .get rescued from Error reading file: Bad file descriptor
Client: connecting to the server
Server: got request 2017-09-26 00:19:24 +0200
Server: writing response # 2017-09-26 00:19:24 +0200
Client: begin streaming
Client: got response "foobar"
Server: writing response # 2017-09-26 00:19:21 +0200
Server: writing response # 2017-09-26 00:19:24 +0200
Client: got response "foobar"
Server: writing response # 2017-09-26 00:19:21 +0200
Server rescued from Error writing file: Broken pipe
Unhandled exception in spawn:
Error writing file: Broken pipe (Errno)
0x4d02ebaca33: unbuffered_write at /usr/lib/crystal/io/file_descriptor.cr 276:11
0x4d02ebac678: flush at /usr/lib/crystal/io/buffered.cr 186:5
0x4d02ebace0d: close at /usr/lib/crystal/io/buffered.cr 194:5
0x4d02eba77d4: process at /usr/lib/crystal/http/server/request_processor.cr 65:7
0x4d02eb9f059: process at /usr/lib/crystal/http/server/request_processor.cr 16:3
0x4d02eb9ef70: handle_client at /usr/lib/crystal/http/server.cr 191:5
0x4d02ead2a1e: run at /usr/lib/crystal/fiber.cr 255:3
0x4d02eaa6206: ~proc2Proc(Fiber, (IO::FileDescriptor | Nil)) at /usr/lib/crystal/concurrent.cr 61:3
0x0: ??? at ??
Server: writing response # 2017-09-26 00:19:24 +0200
Client: got response "foobar"
Client: time to close
Client: .get rescued from Error reading file: Bad file descriptor
Client: connecting to the server
Server: got request 2017-09-26 00:19:27 +0200
Server: writing response # 2017-09-26 00:19:27 +0200
Client: begin streaming
Client: got response "foobar"
...

@vladfaust
Copy link
Contributor Author

vladfaust commented Sep 25, 2017

@petoem thank you for your investigation.

It is weird that it only fails at the second attempt.

I agree with you, it is.

However, the biggest issue for me is properly quitting a current client response, because on a sudden stop it occasionally throws SSL error (see #4991).

@asterite
Copy link
Member

This can be fixed, but someone will need to send a PR. I'm sure we are missing a few rescues in both HTTP::Client and HTTP::Server.

@n7olkachev
Copy link
Contributor

While digging that issue I found that there is fix for it on HTTP::Server side in #4768.
Also, there are affecting changes on socket level, so it may be fixed on HTTP::Client side also.

@straight-shoota
Copy link
Member

The example no longer reproduces.

Server: listening on 5000
Client: connecting to the server
Server: got request
Server: writing response
Client: begin streaming
Client: got response "foobar"
Server: writing response
Client: got response "foobar"
Server: writing response
Client: got response "foobar"
Client: time to close
Client: .get rescued from Error reading socket: Bad file descriptor
Client: connecting to the server
Server: got request
Server: writing response
Client: begin streaming
Client: got response "foobar"
Server: writing response
Server: writing response
Client: got response "foobar"
Server: writing response
Server: writing response
Client: got response "foobar"
Server: writing response
Server rescued from Error writing to socket: Broken pipe
Client: time to close
Client: .get rescued from Error reading socket: Bad file descriptor
Client: connecting to the server
Server: got request
Server: writing response
Client: begin streaming
Client: got response "foobar"
Server: writing response
Server: writing response
Client: got response "foobar"
Server: writing response
Server: writing response
Client: got response "foobar"
Server: writing response

...

It continues looping forever.

It was probably fixed by #4768

@vladfaust
Copy link
Contributor Author

Closing then! Thanks ❤️

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants