Always send lowlevel_error response to client #2812

baelter · 2022-01-27T21:29:28Z

Description

Add back f8acac1 and closes #2808

Problematic lines where f8acac1#diff-b58a5aaef75ecf535b6fc4546c848b0f576f9cf27e37b27c59015251097d5736R113-R114 and 117
The former lead to incorrect control flow in cases.

Your checklist for this pull request

I have reviewed the guidelines for contributing to this repository.
I have added (or updated) appropriate tests if this PR fixes a bug or adds a feature.
My pull request is 100 lines added/removed or less so that it can be easily reviewed.
If this PR doesn't need tests (docs change), I added [ci skip] to the title of the PR.
If this closes any issues, I have added "Closes #issue" to the PR description or my commit messages.
I have updated the documentation accordingly.
All new and existing tests passed, including Rubocop.

)" (puma#2809)" This reverts commit 7008a61.

dentarg · 2022-01-27T22:10:41Z

I think we are going to need a regression test 😅 , any ideas?

dentarg · 2022-01-27T22:41:40Z

With this config.ru

class BrokenApp
  def initialize(app)
    @app = app
  end

  def call(env)
    [200, nil, []]
  end
end

use BrokenApp

map '/' do
  run lambda { |env| [200, {"Content-Type" => "text/plain"}, ["Hello World"]] }
end

and with Puma 5.6.1

$ curl -s -v http://127.0.0.1:9292
*   Trying 127.0.0.1:9292...
* Connected to 127.0.0.1 (127.0.0.1) port 9292 (#0)
> GET / HTTP/1.1
> Host: 127.0.0.1:9292
> User-Agent: curl/7.76.1
> Accept: */*
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 500 Internal Server Error
* no chunk, no close, no size. Assume close to signal end
<
* Closing connection 0

with this branch

$ cat Gemfile_PR
# frozen_string_literal: true

source "https://rubygems.org"

gem "puma", github: "https://github.com/puma/puma/pull/2812"

$ curl -s -v http://127.0.0.1:9292
*   Trying 127.0.0.1:9292...
* Connected to 127.0.0.1 (127.0.0.1) port 9292 (#0)
> GET / HTTP/1.1
> Host: 127.0.0.1:9292
> User-Agent: curl/7.76.1
> Accept: */*
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< HTTP/1.1 500 Internal Server Error
< Content-Length: 616
<
Puma caught this error: undefined method `each' for nil:NilClass (NoMethodError)
/Users/dentarg/.gem/ruby/3.0.2/bundler/gems/puma-df6512cfbf71/lib/puma/request.rb:441:in `str_headers'
/Users/dentarg/.gem/ruby/3.0.2/bundler/gems/puma-df6512cfbf71/lib/puma/request.rb:129:in `write_response'
/Users/dentarg/.gem/ruby/3.0.2/bundler/gems/puma-df6512cfbf71/lib/puma/request.rb:97:in `handle_request'
/Users/dentarg/.gem/ruby/3.0.2/bundler/gems/puma-df6512cfbf71/lib/puma/server.rb:441:in `process_client'
* Connection #0 to host 127.0.0.1 left intact
/Users/dentarg/.gem/ruby/3.0.2/bundler/gems/puma-df6512cfbf71/lib/puma/thread_pool.rb:147:in `block in spawn_thread'

I'm thinking about this, looks like two responses?

< HTTP/1.1 200 OK
< HTTP/1.1 500 Internal Server Error

MSP-Greg · 2022-01-28T02:30:31Z

Maybe we need a better example? Somewhere soon after where Request#handle_request calls @app.call, maybe something like the following could be added?

if headers.is_a? Hash
  raise 'headers from app cannot be frozen' if headers.frozen?
else
  raise "Improper headers (#{headers.class}) from app"
end

nateberkopec · 2022-01-28T16:48:47Z

Diff:

diff --git a/lib/puma/request.rb b/lib/puma/request.rb
index 8950cf28..6cde60de 100644
--- a/lib/puma/request.rb
+++ b/lib/puma/request.rb
@@ -110,11 +110,8 @@ module Puma
       env = client.env
       io  = client.io
 
-      return false if closed_socket?(io)
-      lines.clear
-
       head = env[REQUEST_METHOD] == HEAD
-      after_reply = env[RACK_AFTER_REPLY] || []
+      after_reply = env[RACK_AFTER_REPLY] ||= []
 
       begin
         res_info = {}

nateberkopec · 2022-01-28T16:51:05Z

Barrier for merge here is a test that fails on #2731 but passes on this branch.

MSP-Greg · 2022-01-29T04:48:43Z

@baelter

I had a look at this, and made some changes. See the last commit in my fork's branch:

https://github.com/MSP-Greg/puma/tree/pr2812-f1

A couple of style simplifications, and some begin/rescue/ensure rearranging, which, of course, makes the diff a mess.

Anyway, the issue @dentarg mentioned above is fixed with the lines.reset in write_response's ensure block, and I made a slight change to the test assert_match regex. Without the added lines.reset, the test fails.

I have not run the names.pn specs mentioned elsewhere.

HTH, Greg

baelter · 2022-01-31T19:40:02Z

@MSP-Greg Thanks! Your changes pass the name.pn specs. Cherry picked your commit into this PR.
Not sure how to resolve the conflicts against master though, maybe you are more equipped to do that?
Also no clue on how a regression tests would look like, any help there is also greatly appreciated.

MSP-Greg · 2022-01-31T21:26:02Z

@baelter

Your changes pass the name.pn specs

Thanks for checking. I fixed the conflict. Re a test, if the issue is the one @dentarg mentioned above, showing the response start as:

HTTP/1.1 200 OK
HTTP/1.1 500 Internal Server Error
Content-Length: 616

the issue was fixed in the fixup patch. Previously, the regex in the test was:

%r{HTTP/1.0 500 Internal Server Error\r\nContent-Length: 10\r\n\r\nerror page}

That regex matches the response that dentarg's config.ru generated, but that is an invalid response. The fixup anchored the regex with \A, so it would not pass without the fixup commit. Does that make sense?

Anyway, if that is the cause of the name.pn spec failures, then this is good to go.

nateberkopec · 2022-01-31T21:34:01Z

if that is the cause of the name.pn spec failures

@MSP-Greg I'm not sure it is the cause. Your test change passes on v5.6.0.

MSP-Greg · 2022-01-31T22:15:49Z

@nateberkopec You're right, sorry. I think this PR was clearing lines and if an error happened after the clear, lines wasn't reset for the next response. The fixup took care of that, but as you've found, we still don't have a test for what was wrong with #2731.

@baelter

Do you recall what specs were failing?

joeldrapper · 2022-02-03T20:37:34Z

I haven't been able to get a test to fail locally, but 5.6.0 seems to be leaking ActiveSupport::CurrentAttributes between requests on Rails 6. I can reproduce it in a staging environment but not development.

baelter · 2022-02-04T14:18:47Z

These specs sometimes fail:

    Signup and edit profile :: Delete a link :: And I click the edit button in the links box
    Signup and edit profile :: Delete an alternate name :: And I click the edit button in the variants box
    Signup and edit profile :: Change pronunciation of :: And I click the edit button in the pronunciation box

https://github.com/fishpercolator/name.pn/blob/main/features/signup_and_edit_profile.feature

These specs make a handful of requests each, other than that I don't see anything special. Maybe @pedantic-git can give some more details on what those spec do?

pedantic-git · 2022-02-04T16:46:40Z

Hi @baelter - those are just following links with Capybara. Turbolinks is enabled on the app so there is some work involved in the process of "following a link" but there's nothing special about those particular lines. In my limited testing experience with this issue I found it was more likely to be related to the (number of? specific?) tests that had been run ahead of the ones that failed. Maybe puma reaches some kind of limit or race condition?

MSP-Greg · 2022-02-04T17:06:06Z

I've got an idea about what's causing the problem, I hope to check it this weekend. As with most code, there are parts that might be considered 'brittle', and this has shown that we need more tests.

There has been mention of 'cookies'/session data. I assume that lines up with the logs of the failed tests?

pedantic-git · 2022-02-04T18:05:50Z

Whenever I saw tests fail in my own runs, the symptom was always an "unauthenticated" version of the page coming back when the previous request had been authenticated. I couldn't work out what was going wrong beyond that.

joeldrapper · 2022-02-04T19:02:20Z

@pedantic-git do you use CurrentAttributes in your app to track authentication variables? I don't think it's cookies, I think it's something to do with threads.

pedantic-git · 2022-02-04T19:12:27Z

@joeldrapper Afaik there's no CurrentAttributes in there - it's just the standard cookie session store used with Devise/Warden.

rainerborene · 2022-02-10T22:55:15Z

I haven't been able to get a test to fail locally, but 5.6.0 seems to be leaking ActiveSupport::CurrentAttributes between requests on Rails 6. I can reproduce it in a staging environment but not development.

@joeldrapper It leaks on Rails 7 as well. I've deployed 5.6.0 to production environment and it basically fucked up all the data of our customers because we're using ActiveSupport::CurrentAttributes. This release should be removed from Rubygems to say the least.

joeldrapper · 2022-02-10T23:13:19Z

@rainerborene I'm sorry to hear that! The consequences of CurrentAttributes not being contained to the request execution are really serious. It's literally designed to be relied on for authentication attributes.

My tests showed ActiveSupport.reset_all did work but somehow wasn't being called. For now, I've deployed a before_action that calls reset_all as an extra precaution, as well as updating to 5.6.1. I still can't get a local test to fail.

I don't know how, but this control flow change seems to cause the Rails app executor callbacks not to fire in some circumstances. It seems like a puma thread can get stuck in this state for a while. I haven't been able to reproduce the issue locally even using the same docker image that reproduced in staging.

nateberkopec · 2022-02-10T23:39:48Z

This release should be removed from Rubygems to say the least.

If we can figure out if we're actually causing an issue with CurrentAttributes, then we can do that, but I can't yank (which definitely breaks people's apps) for something that may or may not be broken.

dentarg · 2022-02-11T00:44:22Z

@nateberkopec I think 5.6.0 should be yanked. We know it is broken (somehow). Someone using 5.6.0 might not notice something is wrong and I think that is worse than having "bundle install" not work and having to fix that by upgrading to 5.6.1.

nateberkopec · 2022-02-11T21:25:37Z

The security issue here turned in to GHSA-rmj8-8hhh-gv5h

nateberkopec · 2022-02-11T21:30:11Z

We will not be yanking 5.6.0, as this issue existed in all versions of Puma and Rails. Users should upgrade Rails or Puma.

baelter · 2022-02-21T10:12:54Z

@nateberkopec Since you found and fixed the underlying issue, do you still need more proof in this PR?

nateberkopec · 2022-02-21T15:24:16Z

Yes, we need more proof - we never committed a test for that fix 😅

baelter added 2 commits January 27, 2022 22:10

Revert "Revert "Always send lowlevel_error response to client (puma#2731

cfde8a7

)" (puma#2809)" This reverts commit 7008a61.

Fixup write_response refactoring bug puma#2808

df6512c

nateberkopec added the feature label Jan 28, 2022

nateberkopec added the waiting-for-changes Waiting on changes from the requestor label Jan 30, 2022

Fixup 2812

d3fc0cf

Merge branch 'master' into fix-write-response-bug

d68a6b6

baelter closed this Dec 8, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Always send lowlevel_error response to client #2812

Always send lowlevel_error response to client #2812

baelter commented Jan 27, 2022 •

edited

Loading

dentarg commented Jan 27, 2022

dentarg commented Jan 27, 2022

MSP-Greg commented Jan 28, 2022

nateberkopec commented Jan 28, 2022 •

edited

Loading

nateberkopec commented Jan 28, 2022

MSP-Greg commented Jan 29, 2022

baelter commented Jan 31, 2022

MSP-Greg commented Jan 31, 2022

nateberkopec commented Jan 31, 2022

MSP-Greg commented Jan 31, 2022 •

edited

Loading

joeldrapper commented Feb 3, 2022 •

edited

Loading

baelter commented Feb 4, 2022

pedantic-git commented Feb 4, 2022

MSP-Greg commented Feb 4, 2022

pedantic-git commented Feb 4, 2022

joeldrapper commented Feb 4, 2022

pedantic-git commented Feb 4, 2022

rainerborene commented Feb 10, 2022

joeldrapper commented Feb 10, 2022 •

edited

Loading

nateberkopec commented Feb 10, 2022

dentarg commented Feb 11, 2022

nateberkopec commented Feb 11, 2022

nateberkopec commented Feb 11, 2022 •

edited

Loading

baelter commented Feb 21, 2022

nateberkopec commented Feb 21, 2022

Always send lowlevel_error response to client #2812

Always send lowlevel_error response to client #2812

Conversation

baelter commented Jan 27, 2022 • edited Loading

Description

Your checklist for this pull request

dentarg commented Jan 27, 2022

dentarg commented Jan 27, 2022

MSP-Greg commented Jan 28, 2022

nateberkopec commented Jan 28, 2022 • edited Loading

nateberkopec commented Jan 28, 2022

MSP-Greg commented Jan 29, 2022

baelter commented Jan 31, 2022

MSP-Greg commented Jan 31, 2022

nateberkopec commented Jan 31, 2022

MSP-Greg commented Jan 31, 2022 • edited Loading

joeldrapper commented Feb 3, 2022 • edited Loading

baelter commented Feb 4, 2022

pedantic-git commented Feb 4, 2022

MSP-Greg commented Feb 4, 2022

pedantic-git commented Feb 4, 2022

joeldrapper commented Feb 4, 2022

pedantic-git commented Feb 4, 2022

rainerborene commented Feb 10, 2022

joeldrapper commented Feb 10, 2022 • edited Loading

nateberkopec commented Feb 10, 2022

dentarg commented Feb 11, 2022

nateberkopec commented Feb 11, 2022

nateberkopec commented Feb 11, 2022 • edited Loading

baelter commented Feb 21, 2022

nateberkopec commented Feb 21, 2022

baelter commented Jan 27, 2022 •

edited

Loading

nateberkopec commented Jan 28, 2022 •

edited

Loading

MSP-Greg commented Jan 31, 2022 •

edited

Loading

joeldrapper commented Feb 3, 2022 •

edited

Loading

joeldrapper commented Feb 10, 2022 •

edited

Loading

nateberkopec commented Feb 11, 2022 •

edited

Loading