Issues after 5.5.0 upgrade

Issues after 5.5.0 upgrade

[Stan Pitucha]

Hi, I'm running into two issues after an upgrade from 5.4.1 (a few
previous versions worked just fine as well). I've got a rails 5.2 app
started via:

bin/unicorn_rails -E development -c config/unicorn.rb

With the minimal config.ru in place (require environment, run app), I get:

I, [2019-03-06T12:28:44.393406 #43714]  INFO -- : Refreshing Gem list
ArgumentError: wrong number of arguments (given 0, expected 2)
  /Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/lib/unicorn.rb:49:in
`block in builder'
  /Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/bin/unicorn_rails:139:in
`block in rails_builder'
  /Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:794:in
`build_app!'
  /Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:141:in
`start'
  /Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/bin/unicorn_rails:209:in
`<top (required)>'
  bin/unicorn_rails:17:in `load'
  bin/unicorn_rails:17:in `<top (required)>'

Any ideas how to debug this further? (I made an attempt at bisecting
last release, but ended up with yet another issue there when building
native extensions when installing 5.4.1 over another version of 5.4.1,
so gave up for now - let me know if that's the only way)

-- 

Stan Pitucha

Site Reliability Engineer at Envato
http://envato.com

Re: Issues after 5.5.0 upgrade

[Eric Wong]

Stan Pitucha <stan.pitucha@envato.com> wrote:
> Hi, I'm running into two issues after an upgrade from 5.4.1 (a few

I only saw one issue (proposed fix below).
Did you forget to write about the other?

> previous versions worked just fine as well). I've got a rails 5.2 app
> started via:
> 
> bin/unicorn_rails -E development -c config/unicorn.rb
 
> With the minimal config.ru in place (require environment, run app), I get:
> 
> I, [2019-03-06T12:28:44.393406 #43714]  INFO -- : Refreshing Gem list
> ArgumentError: wrong number of arguments (given 0, expected 2)

It looks like the breakage was introduced in
commit 5985dd50a9bd72388dd5ca4886d6dffc083f87d4
("Support default_middleware configuration option")

Does this trivial change to unicorn_rails fix it for you?

diff --git a/bin/unicorn_rails b/bin/unicorn_rails
index ea4f822..558dd0b 100755
--- a/bin/unicorn_rails
+++ b/bin/unicorn_rails
@@ -136,7 +136,7 @@ def rails_builder(ru, op, daemonize)
     # Rails 3 includes a config.ru, use it if we find it after
     # working_directory is bound.
     ::File.exist?('config.ru') and
-      return Unicorn.builder('config.ru', op).call
+      return Unicorn.builder('config.ru', op)
 
     # Load Rails and (possibly) the private version of Rack it bundles.
     begin

If it's local, you can just edit
/Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/bin/unicorn_rails
No need to bother with building a gem.


Fwiw, "unicorn_rails" was only intended for Rails 1.x and 2.x.
Rails >= 3.x can use "unicorn" directly.  But "unicorn_rails"
still needs to be fixed on our end because I can't tolerate
breaking changes to existing deployment scripts.

Re: Issues after 5.5.0 upgrade

[Stan Pitucha]

> I only saw one issue (proposed fix below).
Sorry, I solved the other one while writing the email but forgot to
update the intro.

So the fix worked for the issue I mentioned, thanks! Also, running
unicorn directly works just fine now.

I ran into another regression with unicorn_rails though. We're doing
some work in `after_fork` which relies on a class found in
`lib/logger_switcher.rb`. Unfortunately it looks like the scope
changed and now I get workers respawning in a loop:

E, [2019-03-06T15:03:04.990789 #46680] ERROR -- : uninitialized
constant #<Class:#<Unicorn::Configurator:0x00007fc3d113d098>>::LoggerSwitcher
(NameError)
config/unicorn.rb:97:in `block in reload'
/Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:653:in
`init_worker_process'
/Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:681:in
`worker_loop'
/Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:548:in
`spawn_missing_workers'
/Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:562:in
`maintain_worker_count'
/Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:295:in
`join'
/Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/bin/unicorn_rails:209:in
`<top (required)>'
bin/unicorn_rails:17:in `load'
bin/unicorn_rails:17:in `<main>'
E, [2019-03-06T15:03:04.992143 #46194] ERROR -- : reaped
#<Process::Status: pid 46680 exit 1> worker=1

The LoggerSwitcher was previously resolved by rails automatically.

Re: Issues after 5.5.0 upgrade

[Eric Wong]

Stan Pitucha <stan.pitucha@envato.com> wrote:
> > I only saw one issue (proposed fix below).
> Sorry, I solved the other one while writing the email but forgot to
> update the intro.
>
> So the fix worked for the issue I mentioned, thanks! Also, running
> unicorn directly works just fine now.

You're welcome and thanks for following up!

> I ran into another regression with unicorn_rails though. We're doing
> some work in `after_fork` which relies on a class found in
> `lib/logger_switcher.rb`. Unfortunately it looks like the scope
> changed and now I get workers respawning in a loop:
> 
> E, [2019-03-06T15:03:04.990789 #46680] ERROR -- : uninitialized
> constant #<Class:#<Unicorn::Configurator:0x00007fc3d113d098>>::LoggerSwitcher
> (NameError)

Is this with `preload_app true`?  I'm not too up-to-date
with scoping and namespace behavior stuff, actually.

I'm too tired at the moment, maybe Jeremy can help figure this out.

> config/unicorn.rb:97:in `block in reload'
> /Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:653:in
> `init_worker_process'
> /Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:681:in
> `worker_loop'
> /Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:548:in
> `spawn_missing_workers'
> /Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:562:in
> `maintain_worker_count'
> /Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:295:in
> `join'
> /Users/viraptor/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/unicorn-5.5.0/bin/unicorn_rails:209:in
> `<top (required)>'
> bin/unicorn_rails:17:in `load'
> bin/unicorn_rails:17:in `<main>'
> E, [2019-03-06T15:03:04.992143 #46194] ERROR -- : reaped
> #<Process::Status: pid 46680 exit 1> worker=1
> 
> The LoggerSwitcher was previously resolved by rails automatically.

Re: Issues after 5.5.0 upgrade

[Jeremy Evans]

On 03/06 04:44, Eric Wong wrote:
> Stan Pitucha <stan.pitucha@envato.com> wrote:
> > > I only saw one issue (proposed fix below).
> > Sorry, I solved the other one while writing the email but forgot to
> > update the intro.
> >
> > So the fix worked for the issue I mentioned, thanks! Also, running
> > unicorn directly works just fine now.
> 
> You're welcome and thanks for following up!
> 
> > I ran into another regression with unicorn_rails though. We're doing
> > some work in `after_fork` which relies on a class found in
> > `lib/logger_switcher.rb`. Unfortunately it looks like the scope
> > changed and now I get workers respawning in a loop:
> > 
> > E, [2019-03-06T15:03:04.990789 #46680] ERROR -- : uninitialized
> > constant #<Class:#<Unicorn::Configurator:0x00007fc3d113d098>>::LoggerSwitcher
> > (NameError)
> 
> Is this with `preload_app true`?  I'm not too up-to-date
> with scoping and namespace behavior stuff, actually.

This is just a guess, but we probably want to call the Unicorn.builder
lambda with the same arguments as the rails_builder lambda.

diff --git a/bin/unicorn_rails b/bin/unicorn_rails
index ea4f822..354c1df 100755
--- a/bin/unicorn_rails
+++ b/bin/unicorn_rails
@@ -132,11 +132,11 @@ def rails_builder(ru, op, daemonize)
 
   # this lambda won't run until after forking if preload_app is false
   # this runs after config file reloading
-  lambda do ||
+  lambda do |x, server|
     # Rails 3 includes a config.ru, use it if we find it after
     # working_directory is bound.
     ::File.exist?('config.ru') and
-      return Unicorn.builder('config.ru', op).call
+      return Unicorn.builder('config.ru', op).call(x, server)
 
     # Load Rails and (possibly) the private version of Rack it bundles.
     begin

If that doesn't fix it, keep reading.

If after_fork is referencing LoggerSwitcher, and preload_app is not set,
then I think the failure should be expected, as in that case after_fork
is called before build_app!.  That would not explain a regression,
though, as that behavior should have been true in 5.4.1.

Does the problem go away if you switch after_fork to after_worker_ready?
Is preload_app set to true?

Thanks,
Jeremy

Re: Issues after 5.5.0 upgrade

[Stan Pitucha]

That was indeed with `preload_app true`.

The patch you posted fixed the second issue and now both `unicorn` and
`unicorn_rails` start successfully.
Thank you.

[PATCH] unicorn_rails: fix regression with Rails >= 3.x in app build

[Eric Wong]

Stan Pitucha <stan.pitucha@envato.com> wrote:
> That was indeed with `preload_app true`.
> 
> The patch you posted fixed the second issue and now both `unicorn` and
> `unicorn_rails` start successfully.

Thanks both.  Pushed out a pre-release with Jeremy's patch:

	gem install --pre unicorn 5.5.0.1.g6836

commit 6836d0674efdb1a6b79953285f10d8edd7e20432

Will tag and release 5.5.1 final in a day or two assuming all
goes well.
------8<-------
From: Jeremy Evans <code@jeremyevans.net>
Subject: [PATCH] unicorn_rails: fix regression with Rails >= 3.x in app build

Note: `unicorn_rails' was only intended for Rails <= 2.x projects
in the old days.

Fixes: 5985dd50a9bd7238 ("Support default_middleware configuration option")

From: Jeremy Evans <code@jeremyevans.net>
  cf. https://bogomips.org/unicorn-public/20190306055734.GC61406@jeremyevans.local/
Signed-off-by: Eric Wong <e@80x24.org>
  [ew: commit message]
---
 bin/unicorn_rails | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/bin/unicorn_rails b/bin/unicorn_rails
index ea4f822..354c1df 100755
--- a/bin/unicorn_rails
+++ b/bin/unicorn_rails
@@ -132,11 +132,11 @@ def rails_builder(ru, op, daemonize)
 
   # this lambda won't run until after forking if preload_app is false
   # this runs after config file reloading
-  lambda do ||
+  lambda do |x, server|
     # Rails 3 includes a config.ru, use it if we find it after
     # working_directory is bound.
     ::File.exist?('config.ru') and
-      return Unicorn.builder('config.ru', op).call
+      return Unicorn.builder('config.ru', op).call(x, server)
 
     # Load Rails and (possibly) the private version of Rack it bundles.
     begin
-- 
EW