heroku / heroku-buildpack-ruby

Heroku's buildpack for Ruby applications.
MIT License
787 stars 1.87k forks source link

heroku-24 stack erroring with Ruby 3.3.x and Rails 7.2.1 #1494

Closed rstammer closed 1 month ago

rstammer commented 2 months ago

Hi there! We're using Rails v7.1.3 (edit: same problem with 7.2.1) running on C-Ruby v3.3.1 and do have issues deploying the application using the heroku-24 stack with the usual heroku Ruby buildpack.

What we've tried to fix it:

Here's the error log for the variant with Ruby 3.3.1πŸ‘‡ What made me suspicious is that in the logs some gems are loaded from /app/vendor/bundle/ruby/3.3.0 and some from /app/vendor/ruby-3.3.1/ which seems paradox at first but the Gemfile specifies 3.3.1 as well as the .ruby-version file.

With heroku-22 stack all is fine so far. Are we doing something wrong here or is this a buildpack problem πŸ€”

2024-09-20T13:57:46.616143+00:00 app[web.1]: [2] ! Unable to load application: ArgumentError: Expected password: to be a String, got NilClass
2024-09-20T13:57:46.616228+00:00 app[web.1]: bundler: failed to load command: puma (/app/vendor/bundle/ruby/3.3.0/bin/puma)
2024-09-20T13:57:46.947524+00:00 app[web.1]: /app/vendor/bundle/ruby/3.3.0/gems/actionpack-7.1.4/lib/action_controller/metal/http_authentication.rb:78:in `http_basic_authenticate_with': Expected password: to be a String, got NilClass (ArgumentError)
2024-09-20T13:57:46.947536+00:00 app[web.1]:
2024-09-20T13:57:46.947557+00:00 app[web.1]: raise ArgumentError, "Expected password: to be a String, got #{password.class}" unless password.is_a?(String)
2024-09-20T13:57:46.947558+00:00 app[web.1]: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-09-20T13:57:46.947559+00:00 app[web.1]: from /app/app/controllers/api/base_controller.rb:2:in `<class:BaseController>'
2024-09-20T13:57:46.947559+00:00 app[web.1]: from /app/app/controllers/api/base_controller.rb:1:in `<top (required)>'
2024-09-20T13:57:46.947559+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/bundled_gems.rb:74:in `require'
2024-09-20T13:57:46.947560+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/bundled_gems.rb:74:in `block (2 levels) in replace_require'
2024-09-20T13:57:46.947560+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/zeitwerk-2.6.17/lib/zeitwerk/kernel.rb:26:in `require'
2024-09-20T13:57:46.947560+00:00 app[web.1]: from /app/app/controllers/api/accounts_controller.rb:1:in `<top (required)>'
2024-09-20T13:57:46.947560+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/bundled_gems.rb:74:in `require'
2024-09-20T13:57:46.947561+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/bundled_gems.rb:74:in `block (2 levels) in replace_require'
2024-09-20T13:57:46.947561+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/zeitwerk-2.6.17/lib/zeitwerk/kernel.rb:26:in `require'
2024-09-20T13:57:46.947562+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/zeitwerk-2.6.17/lib/zeitwerk/cref.rb:91:in `const_get'
2024-09-20T13:57:46.947562+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/zeitwerk-2.6.17/lib/zeitwerk/cref.rb:91:in `get'
2024-09-20T13:57:46.947563+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/zeitwerk-2.6.17/lib/zeitwerk/loader/eager_load.rb:173:in `block in actual_
eager_load_dir'
2024-09-20T13:57:46.947563+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/zeitwerk-2.6.17/lib/zeitwerk/loader/helpers.rb:47:in `block in ls'
2024-09-20T13:57:46.947563+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/zeitwerk-2.6.17/lib/zeitwerk/loader/helpers.rb:25:in `each'
2024-09-20T13:57:46.947564+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/zeitwerk-2.6.17/lib/zeitwerk/loader/helpers.rb:25:in `ls'
2024-09-20T13:57:46.947564+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/zeitwerk-2.6.17/lib/zeitwerk/loader/eager_load.rb:168:in `actual_eager_load_dir'
2024-09-20T13:57:46.947564+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/zeitwerk-2.6.17/lib/zeitwerk/loader/eager_load.rb:17:in `block (2 levels) in eager_load'
2024-09-20T13:57:46.947564+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/zeitwerk-2.6.17/lib/zeitwerk/loader/eager_load.rb:16:in `each'
2024-09-20T13:57:46.947564+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/zeitwerk-2.6.17/lib/zeitwerk/loader/eager_load.rb:16:in `block in eager_load'
2024-09-20T13:57:46.947564+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/zeitwerk-2.6.17/lib/zeitwerk/loader/eager_load.rb:10:in `synchronize'
2024-09-20T13:57:46.947564+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/zeitwerk-2.6.17/lib/zeitwerk/loader/eager_load.rb:10:in `eager_load'
2024-09-20T13:57:46.947565+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/zeitwerk-2.6.17/lib/zeitwerk/loader.rb:413:in `block in eager_load_all'
2024-09-20T13:57:46.947565+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/zeitwerk-2.6.17/lib/zeitwerk/loader.rb:411:in `each'
2024-09-20T13:57:46.947565+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/zeitwerk-2.6.17/lib/zeitwerk/loader.rb:411:in `eager_load_all'
2024-09-20T13:57:46.947565+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/railties-7.1.4/lib/rails/application/finisher.rb:80:in `block in <module:Finisher>'
2024-09-20T13:57:46.947565+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/railties-7.1.4/lib/rails/initializable.rb:32:in `instance_exec'
2024-09-20T13:57:46.947565+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/railties-7.1.4/lib/rails/initializable.rb:32:in `run'
2024-09-20T13:57:46.947565+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/railties-7.1.4/lib/rails/initializable.rb:61:in `block in run_initializers'
2024-09-20T13:57:46.947565+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/tsort.rb:231:in `block in tsort_each'
2024-09-20T13:57:46.947566+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/tsort.rb:353:in `block (2 levels) in each_strongly_connected_component'
2024-09-20T13:57:46.947566+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/tsort.rb:434:in `each_strongly_connected_component_from'
2024-09-20T13:57:46.947566+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/tsort.rb:352:in `block in each_strongly_connected_component'
2024-09-20T13:57:46.947566+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/tsort.rb:350:in `each'
2024-09-20T13:57:46.947566+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/tsort.rb:350:in `call'
2024-09-20T13:57:46.947566+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/tsort.rb:350:in `each_strongly_connected_component'
2024-09-20T13:57:46.947566+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/tsort.rb:229:in `tsort_each'
2024-09-20T13:57:46.947567+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/tsort.rb:208:in `tsort_each'
2024-09-20T13:57:46.947570+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/railties-7.1.4/lib/rails/initializable.rb:60:in `run_initializers'
2024-09-20T13:57:46.947570+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/railties-7.1.4/lib/rails/application.rb:426:in `initialize!'
2024-09-20T13:57:46.947571+00:00 app[web.1]: from /app/config/environment.rb:5:in `<top (required)>'
2024-09-20T13:57:46.947571+00:00 app[web.1]: from config.ru:3:in `require_relative'
2024-09-20T13:57:46.947571+00:00 app[web.1]: from config.ru:3:in `block (2 levels) in <top (required)>'
2024-09-20T13:57:46.947571+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/rack-3.1.7/lib/rack/builder.rb:108:in `eval'
2024-09-20T13:57:46.947572+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/rack-3.1.7/lib/rack/builder.rb:108:in `new_from_string'
2024-09-20T13:57:46.947572+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/rack-3.1.7/lib/rack/builder.rb:97:in 
`load_file'
2024-09-20T13:57:46.947572+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/rack-3.1.7/lib/rack/builder.rb:67:in `parse_file'
2024-09-20T13:57:46.947572+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/puma-6.4.2/lib/puma/configuration.rb:368:in `load_rackup'
2024-09-20T13:57:46.947572+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/puma-6.4.2/lib/puma/configuration.rb:290:in `app'
2024-09-20T13:57:46.947572+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/puma-6.4.2/lib/puma/runner.rb:162:in `load_and_bind'
2024-09-20T13:57:46.947572+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/puma-6.4.2/lib/puma/cluster.rb:371:in `run'
2024-09-20T13:57:46.947572+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/puma-6.4.2/lib/puma/launcher.rb:194:in `run'
2024-09-20T13:57:46.947572+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/puma-6.4.2/lib/puma/cli.rb:75:in `run'
2024-09-20T13:57:46.947573+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/gems/puma-6.4.2/bin/puma:10:in `<top (required)>'
2024-09-20T13:57:46.947573+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/bin/puma:25:in `load'
2024-09-20T13:57:46.947573+00:00 app[web.1]: from /app/vendor/bundle/ruby/3.3.0/bin/puma:25:in `<top (required)>'
2024-09-20T13:57:46.947573+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/bundler/cli/exec.rb:58:in `load'
2024-09-20T13:57:46.947575+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/bundler/cli/exec.rb:58:in `kernel_load'
2024-09-20T13:57:46.947575+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/bundler/cli/exec.rb:23:in `run'
2024-09-20T13:57:46.947575+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/bundler/cli.rb:451:in `exec'
2024-09-20T13:57:46.947576+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/bundler/vendor/thor/lib/thor/command.rb:28:in `run'
2024-09-20T13:57:46.947576+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
2024-09-20T13:57:46.947576+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/bundler/vendor/thor/lib/thor.rb:527:in `dispatch'
2024-09-20T13:57:46.947576+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/bundler/cli.rb:34:in `dispatch'
2024-09-20T13:57:46.947576+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/bundler/vendor/thor/lib/thor/base.rb:584:in `start'
2024-09-20T13:57:46.947576+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/bundler/cli.rb:28:in `start'
2024-09-20T13:57:46.947576+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/gems/3.3.0/gems/bundler-2.5.9/exe/bundle:28:in `block in <top (required)>'
2024-09-20T13:57:46.947576+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/3.3.0/bundler/friendly_errors.rb:117:in `with_friendly_errors'
2024-09-20T13:57:46.947577+00:00 app[web.1]: from /app/vendor/ruby-3.3.1/lib/ruby/gems/3.3.0/gems/bundler-2.5.9/exe/bundle:20:in `<top (required)>'
2024-09-20T13:57:46.947577+00:00 app[web.1]: from /app/bin/bundle:108:in `load'
2024-09-20T13:57:46.947577+00:00 app[web.1]: from /app/bin/bundle:108:in `<main>
rstammer commented 2 months ago

Little update: For some reason this only occurs when I add Rails' HTTP basic authentication mechanics, i.e.

class ApplicationController < ActionController::Base
  http_basic_authenticate_with name: "something", password: "password"
end

… adding this will result in the error described above, leaving out does not.

Edit: This error persists even after upgrading to Rails 7.2.1 and Ruby 3.3.5.

rstammer commented 1 month ago

Interestingly, the error messages were completely misleading here and the HTTP Basic auth was not the problem.

Instead, an invocation of git was causing the problems as git is no longer available by default for heroku-24 during app runtime. Removing the invocation of git fixed the build and we're successfully running on heroku-24 now.

Thx to @dansch from @dotruby for spotting the problem and providing the deciding hint πŸ™Œ

edmorley commented 1 month ago

@rstammer Ah interesting, thank you for the update. Yeah Git is no longer available at run time as documented on the Heroku-24 page.

I'm curious where the Git usage was that could lead to that error message? Was it in a dependency or app code? Do you know why the failure to find Git didn't raise an error at the point of usage?

rstammer commented 1 month ago

Unfortunately the reason why we did not observe a direct error popping up from using git is completely mysterious to me and I cannot explain from my current information.

It was part of the application code in the config/config.yml of the Rails app. The corresponding line sets some convenient default for development purposes where it tries to guess the local user's email address by employing git this way:

development:
  default_recipient: <%= `git config user.email`.presence || "somebody@example.com" %>

Removing this fixed the build for me, that's all I can see so far. Adding it will cause the weird error message as described above. I'd be also interested in learning where the connection is located πŸ˜…

edmorley commented 1 month ago

Ah I believe this may be due to the way Ruby's backticks work: https://ruby-doc.org/3.3.5/Kernel.html#method-i-60

On Heroku the command would have previously been exiting 1 (since there is no global Git config with a user set). eg:

$ docker run --rm -it heroku/heroku:22 bash -c 'git config user.email; echo $?'
1

However, Ruby backticks require explicitly checking the exit code:

$ docker run --rm -it ruby
irb(main):001> `git config user.email`
=> ""
irb(main):002> $?
=> #<Process::Status: pid 8 exit 1>

...so with older stacks this would previously have been silently failing on Heroku.

But backticks do raise when the command isn't found (so will raise if Git isn't found):

$ docker run --rm -it ruby
irb(main):001> `nonexistent-command`
(irb):1:in ``': No such file or directory - nonexistent-command (Errno::ENOENT)
    from (irb):1:in `<main>'
    from <internal:kernel>:187:in `loop'
    from /usr/local/lib/ruby/gems/3.3.0/gems/irb-1.13.1/exe/irb:9:in `<top (required)>'
    from /usr/local/bin/irb:25:in `load'
    from /usr/local/bin/irb:25:in `<main>'

I'm presuming this interacted badly with the templating in config/config.yml?

Perhaps @schneems knows more? :-)

schneems commented 1 month ago

But backticks do raise when the command isn't found (so will raise if Git isn't found):

TIL. I didn't know it would do that. I guard all shell-ing out because I've been bit by this problem so many times. I usually write a run!() method for example https://github.com/ruby/syntax_suggest/blob/67ce884935aaa71c07706b6e159dbee658c30c1a/spec/spec_helper.rb#L85-L89.

My best guess is that there's something that added a git executable to the path such as another buildpack or a bin/git binstub that would fail if the system git doesn't exist but which git would return success. The Ruby community is very keen to add aliases and binstubs.

Alternatively, if a templating library was catching and ignoring a raised exception it could cause something like that. It's hard to say without more information or context.

@rstammer I generally recommend support tickets for application specific problems. It's much easier for me to debug when I have access to the whole app and it's associated configuration. I tend to reserve issues for buildpack specific problems such as regressions "It used to work, but now it doesn't." In this case, the issue was found and resolved so I don't think that's strictly required.

At this stage, debugging would be to find out the root cause. If it happens to be 3rd party buildpack then it could help us save future customers from the same confusing problem. If that's where the issue came from, and we can address the problem in that location. Could you list out the buildpacks the app is using?

For example:

$ heroku buildpacks
=== arcane-beach-22672 Buildpack URL

heroku/ruby
rstammer commented 1 month ago

Thanks a lot for diving in and sharing your insights, @schneems & @edmorley πŸ‘ That is very valuable for us!

Your suggestion makes totally sense! I already have filed a suppport ticket some days before I created the issue here but decided to open an issue here anyway as my naive reasoning concluded that the buildpack logic may in the culprit and others may experience a similar issue because our general application setup is pretty default and not too crazy.

To anyone reading this later on: The error was raised in loading the config, but the error got "swallowed" by a rescue block that was adversely wrapping loading the YAML file. That's why we did not observe the initial error. Many thanks to the detective work by the heroku team figuring this out and we surely have to re-think that rescue-ingπŸ•΅οΈ

Thanks everybody for engagement and a good weekend!