0

I've only updated my application's gems and moved to Rails 6.1.0.rc1 and am now unable to run puma. I see a number of messages that say [7XXXX] Early termination of worker.

I can replicate this locally by running bundle exec puma -p 3000 -e production but I do not see any other output in log/production.log or any of the other environments' logs.

At this point besides waiting for a new Rails rc I'm not sure how I can find the root of the issue. There is also no problem if I run bundle exec puma -C config/puma.rb -p 3000 or bundle exec rails s.

Additional Details

In Gemfile

gem 'puma', '~> 4.1'

and in Gemfile.lock

puma (4.3.6)

I updated to Puma 5.0.4 so I could use the thread-backtraces method on the Control/Status Server Puma can run. It was able to give me the following output which I'll dive into later but it didn't seem to provide a smoking gun.

[
    {
        "backtrace": [
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/cluster.rb:412:in `select'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/cluster.rb:412:in `run'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/launcher.rb:171:in `run'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/cli.rb:80:in `run'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/bin/puma:10:in `<top (required)>'",
            "~/.rvm/gems/ruby-2.7.2/bin/puma:23:in `load'",
            "~/.rvm/gems/ruby-2.7.2/bin/puma:23:in `<main>'",
            "~/.rvm/gems/ruby-2.7.2/bin/ruby_executable_hooks:24:in `eval'",
            "~/.rvm/gems/ruby-2.7.2/bin/ruby_executable_hooks:24:in `<main>'"
        ],
        "name": "Thread: TID-5ic"
    },
    {
        "backtrace": [
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/plugin/tmp_restart.rb:21:in `sleep'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/plugin/tmp_restart.rb:21:in `block in start'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/plugin.rb:68:in `block (2 levels) in fire_background'"
        ],
        "name": "Thread: TID-5iw puma plugin background 0"
    },
    {
        "backtrace": [
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/reactor.rb:70:in `select'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/reactor.rb:70:in `select_loop'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/reactor.rb:34:in `block in run'"
        ],
        "name": "Thread: TID-5jg puma reactor"
    },
    {
        "backtrace": [
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/thread_pool.rb:308:in `sleep'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/thread_pool.rb:308:in `block in start!'"
        ],
        "name": "Thread: TID-5k0 puma threadpool reaper"
    },
    {
        "backtrace": [
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/thread_pool.rb:308:in `sleep'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/thread_pool.rb:308:in `block in start!'"
        ],
        "name": "Thread: TID-5kk puma threadpool trimmer"
    },
    {
        "backtrace": [
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/server.rb:323:in `select'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/server.rb:323:in `handle_servers'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/server.rb:258:in `block in run'"
        ],
        "name": "Thread: TID-5l4 puma server"
    },
    {
        "backtrace": [
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/launcher.rb:219:in `backtrace'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/launcher.rb:219:in `block in thread_status'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/launcher.rb:215:in `each'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/launcher.rb:215:in `thread_status'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/app/status.rb:59:in `call'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/request.rb:76:in `block in handle_request'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/thread_pool.rb:337:in `with_force_shutdown'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/request.rb:75:in `handle_request'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/server.rb:430:in `process_client'",
            "~/.rvm/gems/ruby-2.7.2/gems/puma-5.0.4/lib/puma/thread_pool.rb:145:in `block in spawn_thread'"
        ],
        "name": "Thread: TID-5og puma threadpool 001"
    }
]
Aaron
  • 13,349
  • 11
  • 66
  • 105
  • Can you please add some logs? Also please check this out https://stackoverflow.com/a/62079968 . it might help you – Vishal Nov 09 '20 at 05:48
  • 1
    Thanks @Vishal. I read that post before posting myself but I'm having the problem locally. I'll update my post to include the versioning info as well. The primary problem is that I cannot find any logs to read through or post for better minds than mine! There's nothing added to `log/production.log` and the only STDOUT is the early termination message. – Aaron Nov 09 '20 at 15:03

1 Answers1

0

Unexpected!

pumactl and having a control-url helped but a friend of mine suggested the best idea that I only wish was more obvious,

are you throwing the error on a different server?

I ran gem install thin and RAILS_ENV=production thin start finally showed me the error I was looking for!

As it turns out, I should not have been using non-public methods like add_template_helper as ActionMailer::Base may not always get all the methods of ActionController::Base. I didn't see this error in development because Rails does not eagerly load all of your classes.

Aaron
  • 13,349
  • 11
  • 66
  • 105
  • great.. !! Maybe this answer will help many people in the future. – Vishal Nov 10 '20 at 09:22
  • I hope it will. If I scrape together the time I'd like to find out why I could not get this information easily from puma. However, my friend's epiphany of using another server is the major takeaway as that will come in handy again later I'm sure. – Aaron Nov 10 '20 at 14:13
  • Indeed, a friend always take out us from problem :) – Vishal Nov 10 '20 at 16:01
  • Wow nice one! Thin did print the full stack and error! <3 – Frexuz Jan 02 '22 at 04:44