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.

Sign up for GitHub

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

Jump to bottom

Always send lowlevel_error response to client #2731

Merged
merged 8 commits into from Nov 2, 2021
Merged

Always send lowlevel_error response to client #2731

Show file tree
Hide file tree
Changes from 7 commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
9e8eaac
Always send lowlevel_error response to client
baelter Oct 27, 2021
a5d83c3
Add spec for lowlever error handler
baelter Oct 28, 2021
def464a
Make sure we have a clean buffer when starting response
baelter Oct 28, 2021
7d53fef
Simplify test
baelter Oct 28, 2021
9a96822
Rename spec
baelter Oct 28, 2021
9020b01
Add method docs
baelter Oct 28, 2021
40c72f9
Tweak the test
dentarg Oct 28, 2021
3bb0ace
Return 500 from lowlevel_error_handler in test
baelter Nov 2, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
76 changes: 47 additions & 29 deletions lib/puma/request.rb
View file
Open in desktop
Expand Up @@ -46,11 +46,7 @@ def handle_request(client, lines, requests)
env[HIJACK_P] = true
env[HIJACK] = client

body = client.body

head = env[REQUEST_METHOD] == HEAD

env[RACK_INPUT] = body
env[RACK_INPUT] = client.body
env[RACK_URL_SCHEME] ||= default_server_port(env) == PORT_443 ? HTTPS : HTTP

if @early_hints
Expand All @@ -69,36 +65,58 @@ def handle_request(client, lines, requests)
# A rack extension. If the app writes #call'ables to this
# array, we will invoke them when the request is done.
#
after_reply = env[RACK_AFTER_REPLY] = []
env[RACK_AFTER_REPLY] = []

begin
begin
status, headers, res_body = @thread_pool.with_force_shutdown do
@app.call(env)
status, headers, res_body = @thread_pool.with_force_shutdown do
@app.call(env)
end

return :async if client.hijacked

status = status.to_i

if status == -1
unless headers.empty? and res_body == []
raise "async response must have empty headers and body"
end

return :async if client.hijacked
return :async
end
rescue ThreadPool::ForceShutdown => e
@events.unknown_error e, client, "Rack app"
@events.log "Detected force shutdown of a thread"

status = status.to_i
status, headers, res_body = lowlevel_error(e, env, 503)
rescue Exception => e
@events.unknown_error e, client, "Rack app"

if status == -1
unless headers.empty? and res_body == []
raise "async response must have empty headers and body"
end
status, headers, res_body = lowlevel_error(e, env, 500)
end

return :async
end
rescue ThreadPool::ForceShutdown => e
@events.unknown_error e, client, "Rack app"
@events.log "Detected force shutdown of a thread"
write_response(status, headers, res_body, lines, requests, client)
end

status, headers, res_body = lowlevel_error(e, env, 503)
rescue Exception => e
@events.unknown_error e, client, "Rack app"
# Does the actual response writing for Request#handle_request and Server#client_error
#
# @param status [Integer] the status returned by the Rack application
# @param headers [Hash] the headers returned by the Rack application
# @param res_body [Array] the body returned by the Rack application
# @param lines [Puma::IOBuffer] modified in place
# @param requests [Integer] number of inline requests handled
# @param client [Puma::Client]
# @return [Boolean,:async]
def write_response(status, headers, res_body, lines, requests, client)
env = client.env
io = client.io

status, headers, res_body = lowlevel_error(e, env, 500)
end
return false if closed_socket?(io)
lines.clear

head = env[REQUEST_METHOD] == HEAD
after_reply = env[RACK_AFTER_REPLY] || []

begin
res_info = {}
res_info[:content_length] = nil
res_info[:no_body] = head
Expand Down Expand Up @@ -149,9 +167,9 @@ def handle_request(client, lines, requests)
res_body.each do |part|
next if part.bytesize.zero?
if chunked
fast_write io, (part.bytesize.to_s(16) << line_ending)
fast_write io, part # part may have different encoding
fast_write io, line_ending
fast_write io, (part.bytesize.to_s(16) << line_ending)
fast_write io, part # part may have different encoding
fast_write io, line_ending
else
fast_write io, part
end
Expand All @@ -169,7 +187,7 @@ def handle_request(client, lines, requests)
ensure
uncork_socket io

body.close
client.body.close if client.body
client.tempfile.unlink if client.tempfile
res_body.close if res_body.respond_to? :close

Expand Down
20 changes: 11 additions & 9 deletions lib/puma/server.rb
View file
Open in desktop
Expand Up @@ -482,7 +482,7 @@ def process_client(client, buffer)
end
true
rescue StandardError => e
client_error(e, client)
client_error(e, client, buffer, requests)
# The ensure tries to close +client+ down
requests > 0
ensure
Expand Down Expand Up @@ -510,34 +510,36 @@ def with_force_shutdown(client, &block)
# :nocov:

# Handle various error types thrown by Client I/O operations.
def client_error(e, client)
def client_error(e, client, buffer = ::Puma::IOBuffer.new, requests = 1)
# Swallow, do not log
return if [ConnectionError, EOFError].include?(e.class)

lowlevel_error(e, client.env)
case e
when MiniSSL::SSLError
@events.ssl_error e, client.io
when HttpParserError
client.write_error(400)
status, headers, res_body = lowlevel_error(e, client.env, 400)
write_response(status, headers, res_body, buffer, requests, client)
@events.parse_error e, client
else
client.write_error(500)
status, headers, res_body = lowlevel_error(e, client.env)
write_response(status, headers, res_body, buffer, requests, client)
@events.unknown_error e, nil, "Read"
end
end

# A fallback rack response if +@app+ raises as exception.
#
def lowlevel_error(e, env, status=500)
def lowlevel_error(e, env, status = 500)
if handler = @options[:lowlevel_error_handler]
if handler.arity == 1
return handler.call(e)
handler_status, headers, res_body = handler.call(e)
elsif handler.arity == 2
return handler.call(e, env)
handler_status, headers, res_body = handler.call(e, env)
else
return handler.call(e, env, status)
handler_status, headers, res_body = handler.call(e, env, status)
end
return [handler_status || status, headers || {}, res_body || []]
end

if @leak_stack_on_error
Expand Down
11 changes: 11 additions & 0 deletions test/test_puma_server.rb
View file
Open in desktop
Expand Up @@ -363,6 +363,17 @@ def test_lowlevel_error_message
assert (data.size > 0), "Expected response message to be not empty"
end

def test_lowlevel_error_handler_custom_response
options = { lowlevel_error_handler: ->(_err) { [200, {}, ["error page"]] } }
baelter marked this conversation as resolved.
Show resolved Hide resolved
# setting the headers argument to nil will trigger exception inside Puma
broken_app = ->(_env) { [200, nil, []] }
server_run(**options, &broken_app)

data = send_http_and_read "GET / HTTP/1.0\r\n\r\n"

assert_match %r{HTTP/1.0 200 OK\r\nContent-Length: 10\r\n\r\nerror page}, data
end

def test_force_shutdown_error_default
server_run(force_shutdown_after: 2) do
@server.stop
Expand Down
4 changes: 2 additions & 2 deletions test/test_response_header.rb
View file
Open in desktop
Expand Up @@ -45,15 +45,15 @@ def test_integer_key
server_run app: ->(env) { [200, { 1 => 'Boo'}, []] }
data = send_http_and_read "GET / HTTP/1.0\r\n\r\n"

assert_match(/HTTP\/1.1 500 Internal Server Error/, data)
assert_match(/HTTP\/1.0 500 Internal Server Error/, data)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why did this have to change? Looks like something isn't working now? This is the failure without this change:

Errors & Failures:

  1) Failure:
TestResponseHeader#test_integer_key [test/test_response_header.rb:48]:
Expected /HTTP\/1.1 500 Internal Server Error/ to match # encoding: ASCII-8BIT
#    valid: true
"HTTP/1.0 200 OK\r\nHTTP/1.0 500 Internal Server Error\r\nContent-Length: 559\r\n\r\nPuma caught this error: undefined method `downcase' for 1:Integer (NoMethodError)\n/Users/dentarg/src/puma/lib/puma/request.rb:437:in `block in str_headers'\n/Users/dentarg/src/puma/lib/puma/request.rb:434:in `each'\n/Users/dentarg/src/puma/lib/puma/request.rb:434:in `str_headers'\n/Users/dentarg/src/puma/lib/puma/request.rb:122:in `write_response'\n/Users/dentarg/src/puma/lib/puma/request.rb:97:in `handle_request'\n/Users/dentarg/src/puma/lib/puma/server.rb:447:in `process_client'\n/Users/dentarg/src/puma/lib/puma/thread_pool.rb:147:in `block in spawn_thread'".

If I make the assert fail on master it looks like

Run options: --verbose --name /test_integer_key/ --seed 19438

# Running:

TestResponseHeader#test_integer_key = 0.02 s = F

Fabulous run in 0.024515s, 40.7914 runs/s, 81.5827 assertions/s.
Errors & Failures:

  1) Failure:
TestResponseHeader#test_integer_key [test/test_response_header.rb:48]:
Expected /aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa/ to match # encoding: ASCII-8BIT
#    valid: true
"HTTP/1.1 500 Internal Server Error\r\n\r\n".

1 runs, 2 assertions, 1 failures, 0 errors, 0 skips

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I guess it is coming from this code and the fact that @leak_stack_on_error is true in test and development

puma/lib/puma/server.rb

Lines 543 to 548 in 7812f1b

if @leak_stack_on_error
backtrace = e.backtrace.nil? ? '<no backtrace available>' : e.backtrace.join("\n")
[status, {}, ["Puma caught this error: #{e.message} (#{e.class})\n#{backtrace}"]]
else
[status, {}, ["An unhandled lowlevel error occurred. The application logs may have details.\n"]]
end

Maybe it has "always" been like this... but the start with HTTP/1.0 200 OK\r\n looks strange?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not entirely sure, but the spec send a HTTP 1.0 request so I think it makes sense it gets a HTTP 1.0 response back. Maybe something was off before :) ?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, it was hard coded before: https://github.com/baelter/puma/blob/a2bcda414377ee3f5855a66ed83aa41ce6f0a29d/lib/puma/const.rb#L139

But now we use the correct version.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There's been a change though, this tests triggers an exception in str_headers and if we look at str_headers it has already populated the buffer with a 200 response, that is also included when we try write the error response with write_response.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, nice catch

end

# The header must respond to each
def test_nil_header
server_run app: ->(env) { [200, nil, []] }
data = send_http_and_read "GET / HTTP/1.0\r\n\r\n"

assert_match(/HTTP\/1.1 500 Internal Server Error/, data)
assert_match(/HTTP\/1.0 500 Internal Server Error/, data)
end

# The values of the header must be Strings
Expand Down