Passenger AppPreloader reports existing ruby executables as non existing when BUNDLED WITH in Gemfile.lock differs from pre-installed

[bb]

Rails Apps based on this image are not starting up showing "We're sorry, but something went wrong".

/var/log/nginx/error.log shows:

App 1977 output: /usr/local/rvm/rubies/ruby-3.1.5/bin/ruby: No such file or directory -- Passenger AppPreloader: /home/app/webapp (LoadError)
[ E 2024-06-18 00:20:11.9001 77/T29 age/Cor/App/Implementation.cpp:221 ]: Could not spawn process for application /home/app/webapp: The application process exited prematurely.
  Error ID: 4b6cb0aa
  Error details saved to: /tmp/passenger-error-O6tEuV.html

[ E 2024-06-18 00:20:11.9014 77/Tr age/Cor/Con/CheckoutSession.cpp:281 ]: [Client 10-1] Cannot checkout session because a spawning error occurred. The identifier of the error is 4b6cb0aa. Please see earlier logs for details about the error.

but the file actually exists:

root@05b1edfe5a34:/home/app/webapp# ls -la /usr/local/rvm/rubies/ruby-3.1.5/bin/ruby
-rwxrwxr-x 1 root root 215920 May 17 10:24 /usr/local/rvm/rubies/ruby-3.1.5/bin/ruby

and is really executable:

root@05b1edfe5a34:/home/app/webapp# /usr/local/rvm/rubies/ruby-3.1.5/bin/ruby --version
ruby 3.1.5p252 (2024-04-23 revision 1945f8dc0e) [x86_64-linux]

This happens for images based on

• phusion/passenger-ruby31:3.0.4
• phusion/passenger-ruby31:3.0.5
• phusion/passenger-ruby31:3.0.6 / latest, both when using already-installed 3.1.5 and also when installing ruby-3.1.4 via rvm
• phusion/passenger-ruby32 (latest) when using ruby 3.2.2 (i.e. NOT the one which comes with the image but installing it via rvm during docker build.) and also with ruby 3.2.4 (the one which comes with the image)

There's no issue with the latest docker/passenger-ruby33 image when using the ruby which comes with the image. I didn't try installing a different version via rvm.

I first noticed this last Friday's nightly CI run (i.e. since 3.0.6 has been released).

It also happens for images built before which worked before but where container is recreated, i.e. already existing images stop working.

Nginx config sets passenger_ruby /usr/bin/ruby; but this is just a wrapper forwarding to /usr/local/rvm/wrappers/default/ruby which then references /usr/local/rvm/gems/ruby-3.1.5/environment which contains:

export PATH="/usr/local/rvm/gems/ruby-3.1.5/bin:/usr/local/rvm/gems/ruby-3.1.5@global/bin:/usr/local/rvm/rubies/ruby-3.1.5/bin:$PATH"
export GEM_HOME='/usr/local/rvm/gems/ruby-3.1.5'
export GEM_PATH='/usr/local/rvm/gems/ruby-3.1.5:/usr/local/rvm/gems/ruby-3.1.5@global'
export MY_RUBY_HOME='/usr/local/rvm/rubies/ruby-3.1.5'
export IRBRC='/usr/local/rvm/rubies/ruby-3.1.5/.irbrc'
unset MAGLEV_HOME
unset RBXOPT
export RUBY_VERSION='ruby-3.1.5'

It still doesn't work when setting passenger_ruby /usr/local/rvm/rubies/ruby-3.1.5/bin/ruby;

Even though I tested quite a few different combinations of image versions and ruby versions, I still don't know where the issue comes from. Newly created containers from images built FROM phusion/passenger-ruby31 before last Thursday were working before but are now also broken once recreated.

[CamJN]

it's saying /home/app/webapp doesn't exist not that the ruby executable doesn't exist.

[bb]

Thanks for clarifying. However, this also exists. Including a config.ru and whatever... see:

root@80fae41725db:/home/app/webapp# ls -lad `pwd`
drwxr-xr-x 1 app app 4096 Jun 14 23:43 /home/app/webapp
root@80fae41725db:/home/app/webapp# bin/rails c
Loading production environment (Rails 6.1.7.8)
3.1.5 :001 >
root@80fae41725db:/home/app/webapp# bin/rails s
=> Booting Puma
=> Rails 6.1.7.8 application starting in production
=> Run `bin/rails server --help` for more startup options
Puma starting in single mode...
* Puma version: 5.6.8 (ruby 3.1.5-p252) ("Birdie's Version")
*  Min threads: 20
*  Max threads: 20
*  Environment: production
*          PID: 18337
* Listening on http://0.0.0.0:3000
Use Ctrl-C to stop
^C- Gracefully stopping, waiting for requests to finish
=== puma shutdown: 2024-06-18 21:09:36 +0200 ===
- Goodbye!
Exiting

To emphasize what I said before: An image which was working fine a week ago and the very same image with exactly same configuration (env, volumes, ...) does no longer work after recreating the container (not the image).

[CamJN]

If you recreate the container from the same image with no changes to how you run it then I don't see how anything we did can have affected it, it's not like we changed the image on you. Have you looked at the error message in the /tmp/passenger-error-*.html file that gets created?

[bb]

If you recreate the container from the same image with no changes to how you run it then I don't see how anything we did can have affected it, it's not like we changed the image on you.

I was suspecting passenger updating itself with the security update check.
BUT: I was wrong about old images no longer working. I tagged the first bad image instead of the last good.

So, the image built on 2024-06-13T02:39:19+00:00 worked and still works, also when recreating containers. The ones built 24 hours later no longer worked.

[bb]

I finally managed to find out when it breaks and how to fix it.

If the Bundler version at the end of the Gemfile.lock is specifies the system-wide Bundler version, it works. If they differ, passenger claims the directory was not found.

e.g. Ruby 3.1.6 comes with Bundler 2.3.27. When the Gemfile.lock contains

RUBY VERSION
   ruby 3.1.6p260

BUNDLED WITH
   2.3.27

it works. When it contains e.g. BUNDLED WITH 2.3.26 or BUNDLED WITH 2.5.13 passenger breaks.

When doing gem update --system which (currently) installs Bundler 2.5.13, then it works only with this Gemfile.lock:

RUBY VERSION
   ruby 3.1.6p260

BUNDLED WITH
   2.5.13

but not with 2.5.12 or 2.3.26 etc.

As mentioned before, the problem occurs only with Passenger (both standalone and in nginx), but not with Puma, Rails Console, good_job etc. -- all of them handle bundler switching itself to the directory-local version well.

I think (but didn't bother verifying) that having different global and local bundler versions was not a problem for Passenger before.

The problem is fully reproducible in the container, but I never saw the issue when running passenger start on my development mac, even when the Bundler versions mismatched.

[AvaelKross]

@bb oh my friend, you're a life saver. That's weird that we came across the same issue within one week, while it's difficult to find anything related in google, like it's a new issue or something. I wish Passenger improve their errors log to include some really useful information instead of "No such file or directory", especially since both ruby path and app path are in place..

[mech]

Just encounter this today. My Gemfile.lock has v2.5.14 and is working fine with passenger 3.0.6 last week. Today, I deploy it to AWS EC2 and thought all will be fine, but hit with this error:

App 21202 output: /usr/local/rvm/rubies/ruby-3.3.3/bin/ruby: No such file or directory -- Passenger AppPreloader: /home/app/mail_log (LoadError)

[ E 2024-07-13 15:26:56.4513 41/T29 age/Cor/App/Implementation.cpp:221 ]: Could not spawn process for application /home/app/mail_log: The application process exited prematurely.

As pointed out by @bb it is a Bundler version mismatch issues. I go to my local development and upgrade my bundler to the latest v2.5.15 and because the Dockerfile also do RUN gem update --system, so both local development and Docker bundler version matched and the application can run.

I don't remember Passenger to be so picky on bundler version in the past though 🤔

[bb]

I created a repository for reproducing the issue: https://github.com/bb/passenger-not-found-minimal

The main branch contains a failing setup using Ruby 3.1.6 and Rails 6.1.
The branch https://github.com/bb/passenger-not-found-minimal/tree/ruby-33 contains a failing Ruby 3.3.3 with Rails 7.1.
The branch https://github.com/bb/passenger-not-found-minimal/tree/ruby-32 contains a failing Ruby 3.2.4 with Rails 7.1.

All can be fixed by changing Gemfile.lock to contain BUNDLED WITH 2.5.15 (currently 2.5.14 for the ruby-33 and the ruby-32 branch, 2.5.12 in the main branch).

[tanmayj28]

@bb Thanks for raising this. I faced the same issue few days ago and since bundler released another update it started breaking again.

I was able to fix this by adding below line in my Dockerfile instead of updating the Gemfile.lock after every release:

RUN gem install bundler --force -N -v "$(tail -n 1 Gemfile.lock | tr -d '[:blank:]\n')" && bundle --version

I have raised a PR against your failing ruby33 branch and the fix seems to be working fine.

[bb]

@tanmayj28 thanks for your PR.
I can confirm that your PR fixes the issue.

So anybody looking for an intermediate fix, use @tanmayj28's solution above.

While it's no longer urgent for me, I still hope @CamJN will give it a look someday and fix the root cause which I suspect being somewhere in passenger.

[niggalodon]

I created a repository for reproducing the issue: https://github.com/bb/passenger-not-found-minimal

The main branch contains a failing setup using Ruby 3.1.6 and Rails 6.1. The branch https://github.com/bb/passenger-not-found-minimal/tree/ruby-33 contains a failing Ruby 3.3.3 with Rails 7.1. The branch https://github.com/bb/passenger-not-found-minimal/tree/ruby-32 contains a failing Ruby 3.2.4 with Rails 7.1.

All can be fixed by changing Gemfile.lock to contain BUNDLED WITH 2.5.15 (currently 2.5.14 for the ruby-33 and the ruby-32 branch, 2.5.12 in the main branch).

@bb, I wanted to say THANK YOU!

This error had messed me up, and I invested hours into trying to find a solution.

You are truly a lifesaver, as @AvaelKross said.

[brettwgreen]

This issue has been plaguing us for 6-8 weeks... it seems to me it only happens if you are updating bundler within your Dockerfile. Following assumes running on default ruby version... I'm on version 3.0.6 which is ruby 3.3.4 by default.

• If you just take what's pre-installed it works (with version 3.0.6, the preinstalled version of bundler is 2.5.11 for ruby 3.3.4).
• If you update it, if you lock the update to 2.5.11 (gem install -N bundler -v 2.5.11), it works... but accomplishes little since that's already installed
• If you update it and match the bundler version to your Gemfile.lock, it works

I'm inclined to just take what the base image gives me for bundler. In odd cases where you want the latest/greatest bundler for whatever reason, then you need to keep the versions in sync (in lieu of some kind of fix I guess)

First bullet seems to contradict a bit what @bb had reported, but seems to work for me regardless of what's in lock file if I don't try and update bundler and just take what's pre-installed.

Anything else gets this error.

UPDATE:
I just want to add that, if you are manually upgrading rubygems and bundler in your Dockerfile, that maybe that's not good practice anymore. Since Bundler 2.3, bundler handles this itself by looking at your lockfile and installing the version it needs.

https://bundler.io/blog/2022/01/23/bundler-v2-3.html

[CamJN]

I have a theory this problem might be related to this change: passenger#4586623d

Nevermind, 3.0.6 had Passenger 6.0.22 which didn't include that change.

Actually 3.0.5 and 3.0.6 both have Passenger 6.0.22 so passenger didn't change.
Both 3.0.5 and 3.0.6 have rvm 1.29.12 so that didn't change.

Here's the changes between 3.0.5 and 3.0.6: phusion/passenger-docker@rel-3.0.5...rel-3.0.6 aside from time-dependent things, however the big ones (rvm and passenger) didn't change.

[brettwgreen]

I have a theory this problem might be related to this change: passenger#4586623d

Nevermind, 3.0.6 had Passenger 6.0.22 which didn't include that change.

Actually 3.0.5 and 3.0.6 both have Passenger 6.0.22 so passenger didn't change. Both 3.0.5 and 3.0.6 have rvm 1.29.12 so that didn't change.

Here's the changes between 3.0.5 and 3.0.6: rel-3.0.5...rel-3.0.6 aside from time-dependent things, however the big ones (rvm and passenger) didn't change.

I have suspected the issue isn't really because of a change in passenger itself, but because of a change in bundler.... the problem started to hit with us when bundler 2.5.12 dropped (and our dockerfile was set to always update to latest bundler). I find it curious that 2.5.11 remains the default in even latest versions of ruby (https://stdgems.org/). Something about 2.5.12 and up causes problems somehow.

That being said, if you just let bundler update itself using the version in the lock file, it seems to handle it just fine even upgrading past that version. In my case, I removed my manual gem update bundler lines from Dockerfile, and then bundler just does the following, and passenger starts up just fine.

Bundler 2.5.11 is running, but your lockfile was generated with 2.5.16. Installing Bundler 2.5.16 and restarting using that version.
Fetching gem metadata from https://rubygems.org/.
Fetching bundler 2.5.16
Installing bundler 2.5.16

[CamJN]

There are quite a few changes in bundler 2.5.11 → 2.5.12 including some that seem like they could be related rubygems/rubygems@bundler-v2.5.11...bundler-v2.5.12

Since our images include bundler 2.3.27 not 2.5.12 I guess my advice would be to not upgrade to a broken version of bundler?

[brettwgreen]

Or, oddly enough, if you let bundler itself do the updating it seems to do it in a way that does not break passenger start up. Bundler will look at your lock file BUNDLED WITH and just install the correct version and that worked for me.

[syntruth]

Thank you all, since this was causing me much pain. We're running on bare metal in Nginx, so I'll have to come up with another solution, other than manually remembering to install the correct version of Bundler if it changes in our apps.

Of course this was not an issue in dev/qa, because those run in local thin servers and not passenger. (At least for now, this makes me think that needs to change.)

I'm not sure where the change needs to happen, but after reading over the Bundler blogs, this new system is probably not going to change. Eventually they want to get to just including Bundler in the Gemfile just like any other gem. I guess that makes sense, but the version mismatch was definitely causing problems, and changing the lock file version by hand allowed us to get our apps into production. (We had already rolled-back once, and were reluctant to do so again.

[huangdengpan]

I created a repository for reproducing the issue: https://github.com/bb/passenger-not-found-minimal

The main branch contains a failing setup using Ruby 3.1.6 and Rails 6.1. The branch https://github.com/bb/passenger-not-found-minimal/tree/ruby-33 contains a failing Ruby 3.3.3 with Rails 7.1. The branch https://github.com/bb/passenger-not-found-minimal/tree/ruby-32 contains a failing Ruby 3.2.4 with Rails 7.1.

All can be fixed by changing Gemfile.lock to contain BUNDLED WITH 2.5.15 (currently 2.5.14 for the ruby-33 and the ruby-32 branch, 2.5.12 in the main branch).

Very nice ! it fixed the problem.

[FooBarWidget]

@CamJN This issue is even more complicated than it seems so far. In addition to Bundler having changed its behavior, I've also found this:

• I cannot reproduce the problem using 'irb' where I first run gem "bundler" and then require "bundler/setup" (which is all that Passenger is supposed to do).
• Using the 'direct' spawning method makes the problem go away.
• The problem is triggered by the call activate_gem 'bundler', 'bundler/setup'. However, I'm not able to catch the exception and perform additional diagnosis in the exception handler. Even an ensure block does not work. It looks as if the whole process crashes outside of Ruby code.

I'm going to investigate this further.

[bb]

@FooBarWidget I got an e-mail about a comment where you mentioned me, which is now deleted. Please let me know if you still need help or add a rocket emoji, so I know I can delete this comment.

[FooBarWidget]

@bb I was able to reproduce it after all thanks to your repository! No help needed, thanks for providing the repo!

[FooBarWidget]

Okay I've identified the root cause of this problem. A recent Bundler version introduced a mechanism called "auto-restarting". It's triggered under a complex set of conditions. One condition is that the program was invoked using a Bundler version that's different from the Bundler version in Gemfile.lock.

It was designed for this typical CLI usage:

bundle exec rake --version

• Running bundle on the CLI runs the latest version of Bundler, let's say 2.5.23.
• Bundler 2.5.23 then sees your Gemfile.lock specifies a different version, let's say 2.5.14.
• Bundler then performs some environment modifications (presumably to activate 2.5.14), then re-executes the current process by calling its original invocation parameters, i.e., Kernel.exec("bundle", "exec", "rake", "--version").
  • This happens in Bundler::SelfManager#start_with.

It's this last step that blows up in combination with Passenger. Bundler determines the program invocation using various means, one of which is $PROGRAM_NAME (which in the above example is "rake"). However, Passenger sets $PROGRAM_NAME to "Passenger AppPreloader: /path-to-app" in order to change the process title to something friendly (so that users who use 'ps' can more easily identify Passenger processes). Thus, Bundler ends up calling:

Kernel.exec("/usr/local/rvm/rubies/ruby-3.2.4/bin/ruby", "Passenger AppPreloader: /home/app/webapp")

This explains:

• The weird error message "No such file or directory -- Passenger AppPreloader: /home/app/webapp".
• Why direct spawning does not trigger the problem. It's because we don't change $PROGRAM_NAME until after we've loaded Bundler.

---

What's the fix? In my tests, temporarily reverting $PROGRAM_NAME to its original value, right before loading Bundler, solves this problem. Bundler then success re-executes the preloader. It didn't think it would be this simple, because when Passenger loads a subprocess (whether that's a Ruby process or whatever), the subprocess communicates its progress to Passenger, and this communication protocol was not designed to be restartable. But so far it seems like there are no issues. I will do some more checks, and if all is well, then we can use this fix.

There is another potential fix strategy, namely by forcing Bundler not to restart Ruby. A CLI invocation like this does not trigger Bundler to restart the process...

ruby -rbundler/setup -e 'puts "hello"'

...because $PROGRAM_NAME is -e, which Bundler recognizes as "unrestartable". In this case, Bundler will just proceed with the latest Bundler version.

But for compatibility, I think it's best to let Bundler restart us, so I definitely prefer the first fix strategy.

[CamJN]

A cleaner way to force bundler to not restart for no good reason would be to set the BUNDLER_VERSION env var before loading bundler to a version that is installed: https://github.com/rubygems/rubygems/blob/a63e6c5f58c771f78b27603f46bc0702ef52a79c/bundler/lib/bundler/self_manager.rb#L108 That way we don't need to re-run the setup steps.

[CamJN]

@FooBarWidget Also can you provide a minimal example that triggers the problem without Passenger, I'm trying to let the bundler folks know that their logic for knowing if it's safe to re-exec bundler is broken.

The following script does not trigger the problem with a Gemfile.lock that doesn't match any installed bundler, but based on your description I would think it should:

#!/usr/bin/env ruby

$PROGRAM_NAME = 'pretty name here'

def activate_gem(gem_name, library_name = nil)
  if !defined?(::Gem)
    begin
      require 'rubygems'
    rescue LoadError
    end
  end
  if Kernel.respond_to?(:gem, true)
    begin
      gem(gem_name)
    rescue Gem::LoadError
    end
  end
  require(library_name || gem_name)
end

activate_gem 'bundler', 'bundler/setup'

[FooBarWidget]

I do not think that forcing Bundler not to restart, is a good idea. For maximum compatibility and least surprises, we should make Bundler restart work.

Regarding reproduction:

1. Use @bb's repository. I use the ruby32 branch. docker compose up

2. Open a shell in the container: docker compose exec web sudo -u app -H bash -l

3. In /home/app/webapp, create foo.rb:

   #!/usr/bin/env ruby
   $0 = "this is the program name"
   require 'bundler/setup'

4. Run ruby foo.rb:

   /usr/local/rvm/rubies/ruby-3.2.4/bin/ruby: No such file or directory -- this is the program name (LoadError)
   

Note that I cannot reproduce this on macOS, Ruby 3.2 installed via ASDF, RubyGems 3.5.3. Triggering this issue requires a specific environment, the details of which I've not fully explored.

In particular, one necessary factor (though it may not be the only necessary factor) is that calling require 'bundler' the first time must load the bundler.rb in the Ruby default library directory (which is what happens in bb's container), instead of immediately activating the Bundler gem version specified in Gemfile.lock (which is what happens on my macOS Ruby). I do not yet know where this difference in behavior comes from.

[tinco]

Is $PROGRAM_NAME an alias for $0? That is surprising to me, I feel modifying $0 is a significantly different from modifying $PROGRAM_NAME semantically. If they are really identical, then I am leaning a lot more in the direction that modifying $PROGRAM_NAME is a bad idea and find it a little more reasonable of bundler to be relying on $0 to hold the original executable name.

[CamJN]

@tinco $PROGRAM_NAME is an alias for $0. https://github.com/ruby/ruby/blob/5edf1c8febb105da077b8b690b5e1df9d99099a6/ext/extmk.rb#L30

However what bundler probably wants is Process.argv0 which seems to be unchanged when you modify $PROGRAM_NAME or $0: https://docs.ruby-lang.org/en/master/Process.html#method-c-argv0

[CamJN]

Yup, bundler doesn't have any problems if you swap $PROGRAM_NAME for Process.argv0.

[FooBarWidget]

Good find Camden. We should suggest that to the Bundler team.

[CamJN]

I've reduced the reproduction environment to the following:

Dockerfile:

FROM ruby:3.2.6

WORKDIR /root
COPY test.rb /root/test.rb
COPY Gemfile /root/Gemfile
COPY Gemfile.lock /root/Gemfile.lock

RUN gem update --system
RUN bundle config set --local deployment "true"
RUN bundle config set --local path vendor/ruby
RUN bundle install
RUN rm -rf /root/vendor/ruby/ruby/3.2.0/gems/bundler-2.5.12

CMD ["ruby", "test.rb"]

Gemfile:

# frozen_string_literal: true

source "https://rubygems.org"

ruby '3.2.6'

Gemfile.lock:

GEM
  remote: https://rubygems.org/
  specs:

PLATFORMS
  arm64-darwin-23
  ruby

DEPENDENCIES

RUBY VERSION
   ruby 3.2.6p234

BUNDLED WITH
   2.5.12

test.rb

#!/usr/bin/env ruby
$0 = "this is the program name"
require 'bundler/setup'