Puma 6.2 does not respond correctly when Rails app responds with empty body

[dmke]

Describe the bug

In one of my Rails 6.1 apps, I have code that boils down to:

class ThingsController < ApplicationController
  def show
    head :not_found
  end
end

With Puma 6.1.1 I get the following response:

curl

$ curl -i localhost:3000/thing
HTTP/1.1 404 Not Found
X-Frame-Options: SAMEORIGIN
X-XSS-Protection: 1; mode=block
X-Content-Type-Options: nosniff
X-Download-Options: noopen
X-Permitted-Cross-Domain-Policies: none
Referrer-Policy: strict-origin-when-cross-origin
Content-Type: text/html
Cache-Control: no-cache
X-Request-Id: 15463eac-5912-4c17-8044-5d884fde576b
X-Runtime: 0.003416
Transfer-Encoding: chunked

Rails log

=> Booting Puma
=> Rails 6.1.7.3 application starting in development 
=> Run `bin/rails server --help` for more startup options
Puma starting in single mode...
* Puma version: 6.1.1 (ruby 3.0.5-p211) ("The Way Up")
*  Min threads: 5
*  Max threads: 5
*  Environment: development
*          PID: 104668
* Listening on http://[::]:3000
Use Ctrl-C to stop
Started GET "/thing" for ::1 at 2023-03-30 16:39:55 +0200
Processing by ThingsController#show as */*
Completed 404 Not Found in 0ms (Allocations: 160)

After upgrading to Puma 6.2, this is the result:

curl

$ curl -i localhost:3000/thing
curl: (1) Received HTTP/0.9 when not allowed

Rails log

=> Booting Puma
=> Rails 6.1.7.3 application starting in development 
=> Run `bin/rails server --help` for more startup options
Puma starting in single mode...
* Puma version: 6.2.0 (ruby 3.0.5-p211) ("Speaking of Now")
*  Min threads: 5
*  Max threads: 5
*  Environment: development
*          PID: 105699
* Listening on http://[::]:3000
Use Ctrl-C to stop
Started GET "/thing" for ::1 at 2023-03-30 16:40:18 +0200
Processing by ThingsController#show as */*
Completed 404 Not Found in 0ms (Allocations: 231)

When pointing Firefox to http://localhost:3000/thing, the browser hangs for 20s, then prints a 0.

I've captured the network traffic: puma.pcap.gz

Puma config:

config/puma.rb

This is the unaltered config file generated by rails new:

# Puma can serve each request in a thread from an internal thread pool.
# The `threads` method setting takes two numbers: a minimum and maximum.
# Any libraries that use thread pools should be configured to match
# the maximum value specified for Puma. Default is set to 5 threads for minimum
# and maximum; this matches the default thread size of Active Record.
#
max_threads_count = ENV.fetch("RAILS_MAX_THREADS") { 5 }
min_threads_count = ENV.fetch("RAILS_MIN_THREADS") { max_threads_count }
threads min_threads_count, max_threads_count

# Specifies the `worker_timeout` threshold that Puma will use to wait before
# terminating a worker in development environments.
#
worker_timeout 3600 if ENV.fetch("RAILS_ENV", "development") == "development"

# Specifies the `port` that Puma will listen on to receive requests; default is 3000.
#
port ENV.fetch("PORT") { 3000 }

# Specifies the `environment` that Puma will run in.
#
environment ENV.fetch("RAILS_ENV") { "development" }

# Specifies the `pidfile` that Puma will use.
pidfile ENV.fetch("PIDFILE") { "tmp/pids/server.pid" }

# Specifies the number of `workers` to boot in clustered mode.
# Workers are forked web server processes. If using threads and workers together
# the concurrency of the application would be max `threads` * `workers`.
# Workers do not work on JRuby or Windows (both of which do not support
# processes).
#
# workers ENV.fetch("WEB_CONCURRENCY") { 2 }

# Use the `preload_app!` method when specifying a `workers` number.
# This directive tells Puma to first boot the application and load code
# before forking the application. This takes advantage of Copy On Write
# process behavior so workers use less memory.

#
# preload_app!

# Allow puma to be restarted by `rails restart` command.
plugin :tmp_restart

The Rails app is started with bundle exec rails server -b '::'.

To Reproduce

I've prepared a repro-repo. You'll need Ruby 3.0.5:

$ git clone https://github.com/dmke/puma-repro
$ cd puma-repro
$ git checkout puma-6.1.1
$ bundle install
$ bundle exec rails server -b '::'

To switch to Puma 6.2:

$ git checkout puma-6.2
$ bundle install
$ bundle exec rails server -b '::'

Expected behavior

head(:not_found) should work as expected.

Desktop (please complete the following information):

• OS: Debian Linux (11/bullseye)
• Puma Version: 6.2

[Thibaut]

I'm also experiencing this. I've narrowed it down to any response (regardless of status code) that returns an empty body. You can work around it by doing something like render(plain: "Not found", status: :not_found), but render(plain: "", status: :not_found) will trigger the issue in Puma. Reverting to 6.1.1 fixes it.

[MSP-Greg]

I'm looking at this, not sure if it's a bug in Rails. The Rack spec states:

---

The Body must respond to each or call. It may optionally respond to to_path or to_ary. A Body that responds to each is considered to be an Enumerable Body. A Body that responds to call is considered to be a Streaming Body.

A Body that responds to both each and call must be treated as an Enumerable Body, not a Streaming Body. If it responds to each, you must call each and not call. If the Body doesn’t respond to each, then you can assume it responds to call.

---

I'm trying to figure out what Rails is returning for the body...

[dmke]

I'm trying to figure out what Rails is returning for the body...

self.response_body is set to an empty string:

https://github.com/rails/rails/blob/f09dc7c4c2e8b9375345d443c230cb8d78ad6a18/actionpack/lib/action_controller/metal/head.rb#L21-L49

I'm not sure though, how and where a processed ActionController response is translated back into a Rack response.

[MSP-Greg]

@dmke

Thanks. I also got that far, but then interrupted. Can you test locally with a patch or a different branch?

I tried locally with a 'rackup' file with various bodies, and it seems to be working correctly, but Rails wraps the body with a bit of code, depending on the setup...

[dmke]

I can try.

I'm currently not at my workstation anymore though, so response times (heh...) might be sluggish.

[dmke]

In a Pry session, I've stepped up around two dozen caller frames to this point (the first/last Puma method):

From: RAILS_ROOT/.gems/gems/puma-6.2.0/lib/puma/request.rb:98 Puma::Request#handle_request:

     93:       env[RACK_AFTER_REPLY] ||= []
     94: 
     95:       begin
     96:         if SUPPORTED_HTTP_METHODS.include?(env[REQUEST_METHOD])
     97:           status, headers, app_body = @thread_pool.with_force_shutdown do
 =>  98:             @app.call(env)
     99:           end

Skipping #with_force_with_shutdown, the result from @all.call(env) is the following:

status
=> 404

headers
=> {"X-Frame-Options"=>"SAMEORIGIN",
 "X-XSS-Protection"=>"1; mode=block",
 "X-Content-Type-Options"=>"nosniff",
 "X-Download-Options"=>"noopen",
 "X-Permitted-Cross-Domain-Policies"=>"none",
 "Referrer-Policy"=>"strict-origin-when-cross-origin",
 "Content-Type"=>"text/html",
 "Cache-Control"=>"no-cache",
 "X-Request-Id"=>"3cdb7705-40ea-4ee0-8386-1738895900d5",
 "X-Runtime"=>"150.589500"}

app_body
=> #<Rack::BodyProxy:0x000055a1f6240f70
 @block=#<Proc:0x000055a1f6240ea8 RAILS_ROOT/.gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/executor.rb:15>,
 @body=
  #<Rack::BodyProxy:0x000055a1f6243ba8
   @block=#<Proc:0x000055a1f6243b08 RAILS_ROOT/.gems/gems/activesupport-6.1.7.3/lib/active_support/cache/strategy/local_cache_middleware.rb:30>,
   @body=
    #<Rack::BodyProxy:0x000055a1f61ef2b0
     @block=#<Proc:0x000055a1f61ef238 RAILS_ROOT/.gems/gems/railties-6.1.7.3/lib/rails/rack/logger.rb:38>,
     @body=
      #<Rack::BodyProxy:0x000055a1f5b54e28
       @block=#<Proc:0x000055a1f5b37f30 RAILS_ROOT/.gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/executor.rb:15>,
       @body=
        #<Rack::BodyProxy:0x000055a1f599d850
         @block=#<Proc:0x000055a1f599d738 RAILS_ROOT/.gems/gems/rack-2.2.6.4/lib/rack/tempfile_reaper.rb:16>,
         @body=
          #<ActionDispatch::Response::RackBody:0x000055a1f6356748
           @response=
            #<ActionDispatch::Response:0x000055a1f5a12808
             @cache_control={},
             @committed=true,
             @cv=#<MonitorMixin::ConditionVariable:0x000055a1f5a12600 @cond=#<Thread::ConditionVariable:0x000055a1f5a124e8>, @monitor=#<Monitor:0x000055a1f5a12768>>,
             @header=
              {"X-Frame-Options"=>"SAMEORIGIN",
               "X-XSS-Protection"=>"1; mode=block",
               "X-Content-Type-Options"=>"nosniff",
               "X-Download-Options"=>"noopen",
               "X-Permitted-Cross-Domain-Policies"=>"none",
               "Referrer-Policy"=>"strict-origin-when-cross-origin",
               "Content-Type"=>"text/html"},
             @mon_data=#<Monitor:0x000055a1f5a12768>,
             @mon_data_owner_object_id=7300,
             @request=#<ActionDispatch::Request GET "http://localhost:3000/thing" for ::1>,
             @sending=false,
             @sent=false,
             @status=404,
             @stream=#<ActionDispatch::Response::Buffer:0x00007f1a70074ea0 @buf=[""], @closed=false, @response=#<ActionDispatch::Response:0x000055a1f5a12808 ...>, @str_body=nil>>>,
         @closed=false>,
       @closed=false>,
     @closed=false>,
   @closed=false>,
 @closed=false>

Does this help?

[MSP-Greg]

@dmke

Thank you. Yes, that helps.

I was going to try a Rack::BodyProxy next, and check the Rails code, You may have noticed @str_body=nil, which may be the cause of the problem, not sure.

[MSP-Greg]

@dmke

Can you try replacing:

puma/lib/puma/request.rb

Line 183 in 52fa8f6

body = array_body

with:

body = array_body.compact

That fixes an issue if the body is [nil]...

[dmke]

That doesn't help, array_body itself is nil.

[dmke]

You may have noticed @str_body=nil, which may be the cause of the problem, not sure.

That seems to be the default value, @buf=[""] was set via self.response_body = "" (despite appearance, this is a ActionDispatch::Response::Buffer).

[collinsauve]

In case it helps, here's the view from telnet (shows exactly what the response looks like, unlike that weird curl error):

$ telnet 172.16.32.132 9292
Trying 172.16.32.132...
Connected to 172.16.32.132.
Escape character is '^]'.
GET /redacted HTTP/1.1

0

That 0 should be HTTP/1.1 ...status code...

[MSP-Greg]

Sorry, AFK for a bit

@dmke

That doesn't help, array_body itself is nil.

So, we have:

if res_body.respond_to?(:to_ary) && (array_body = res_body.to_ary) &&
    array_body.is_a?(Array)
  body = array_body.compact
  content_length = body.sum(&:bytesize)
elsif res_body.is_a?(File) && res_body.respond_to?(:size)
  body = res_body
  content_length = body.size
elsif res_body.respond_to?(:to_path) && File.readable?(fn = res_body.to_path)
  body = File.open fn, 'rb'
  content_length = body.size
  close_body = true
else
  body = res_body
end

If array_body is nil, the first conditional (the if statement) wouldn't be true because of array_body.is_a?(Array), so it jumps to the final else?

I've got to determine how this response body is traversing the logic...

[dmke]

Breakpoint just before the condition:

content_length
#=> nil
resp_info
#=> {:no_body=>nil, :allow_chunked=>true, :keep_alive=>true, :response_hijack=>nil}
res_body.respond_to?(:to_ary)
#=> true
array_body = res_body.to_ary
#=> nil
array_body.is_a?(Array)
#=> false

None of the conditionals match, and the else-branch is taken.

[dmke]

Um... ActionDispatch::Response::RackBody#to_ary returns nil by design:

https://github.com/rails/rails/blob/f09dc7c4c2e8b9375345d443c230cb8d78ad6a18/actionpack/lib/action_dispatch/http/response.rb#L518-L520

[MSP-Greg]

Thanks. I think it was removed in 7.0, but master currently has

def to_ary
  @buf.to_ary
end

Or, this can get really fun.

Regardless, I'm wading thru it. I don't have the code memorized, and without content-length, it's hard to determine whether the body needs to be chunked...

[dmke]

#3113 seems to fix this issue.

[collinsauve]

Copying desc from my PR here for visibility:

Root of the issue is that you can get into the if chunked branch when body.each has nothing in it, so the previously populated io_buffer is never written to the socket.

This used to be the case but was changed on #3072. I'm just moving this line back.

Probably needs a unit test, but I have yet to grok the test coverage that Puma has or how to write this one... will take me a while.

[MSP-Greg]

@collinsauve

will take me a while.

If you'd like to, but I've already got a test for it, or at least an app response for it. I'll post in your PR.

[collinsauve]

Definitely would appreciate help writing the test(s)!