Hey, about a week ago my app started failing when starting after deploy. It used to work fine and I didn’t change any deployment related code in months.
2024-07-03T06:53:17.300 app[9185776dfd30e8] fra [info] foreman start --procfile=Procfile.fly
2024-07-03T06:53:17.435 app[9185776dfd30e8] fra [info] /usr/lib/ruby/vendor_ruby/rubygems.rb:265:in `find_spec_for_exe': can't find gem foreman (>= 0.a) with executable foreman (Gem::GemNotFoundException)
2024-07-03T06:53:17.435 app[9185776dfd30e8] fra [info] from /usr/lib/ruby/vendor_ruby/rubygems.rb:284:in `activate_bin_path'
2024-07-03T06:53:17.436 app[9185776dfd30e8] fra [info] from /usr/bin/foreman:25:in `<main>'
2024-07-03T06:53:17.442 app[9185776dfd30e8] fra [info] bin/rails aborted!
2024-07-03T06:53:17.444 app[9185776dfd30e8] fra [info] Command failed with status (1): [foreman start --procfile=Procfile.fly]
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/file_utils.rb:65:in `block in create_shell_runner'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/file_utils.rb:57:in `sh'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/lib/tasks/fly.rake:15:in `block (3 levels) in <main>'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/bundler-2.5.12/lib/bundler.rb:412:in `block in with_original_env'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/bundler-2.5.12/lib/bundler.rb:684:in `with_env'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/bundler-2.5.12/lib/bundler.rb:412:in `with_original_env'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/lib/tasks/fly.rake:14:in `block (2 levels) in <main>'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/task.rb:281:in `block in execute'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/task.rb:281:in `each'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/task.rb:281:in `execute'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/task.rb:219:in `block in invoke_with_call_chain'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/task.rb:199:in `synchronize'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/task.rb:199:in `invoke_with_call_chain'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/task.rb:188:in `invoke'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/application.rb:188:in `invoke_task'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/application.rb:138:in `block (2 levels) in top_level'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/application.rb:138:in `each'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/application.rb:138:in `block in top_level'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/application.rb:147:in `run_with_threads'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/application.rb:132:in `top_level'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/commands/rake/rake_command.rb:27:in `block (2 levels) in perform'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/application.rb:214:in `standard_exception_handling'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/commands/rake/rake_command.rb:27:in `block in perform'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/commands/rake/rake_command.rb:44:in `block in with_rake'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/rake_module.rb:59:in `with_application'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/commands/rake/rake_command.rb:41:in `with_rake'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/commands/rake/rake_command.rb:20:in `perform'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/command.rb:156:in `invoke_rake'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/command.rb:73:in `block in invoke'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/command.rb:149:in `with_argv'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/command.rb:69:in `invoke'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/commands.rb:18:in `<main>'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/bootsnap-1.18.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30:in `require'
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] Tasks: TOP => fly:server
2024-07-03T06:53:17.445 app[9185776dfd30e8] fra [info] (See full trace by running task with --trace)
2024-07-03T06:53:17.670 app[9185776dfd30e8] fra [info] INFO Main child exited normally with code: 1
I haven’t done a deploy in about two weeks so I can’t pinpoint the exact time it stopped working, but it’s still not working now, 6 days after I encountered it for the first time.
I have ruby-foreman in my deployment packages in Dockerfile, and a rake task with sh "foreman start --procfile=Procfile.fly". This used to work just fine.
Now I had to add foreman to the Gemfile (which you’re not supposed to do) and do sh "bundle exec foreman start --procfile=Procfile.fly" in the rake task to get it going again.
What changed on your side? Can it be fixed? Am I doing something incorrectly?
Wonder what changed between when it was working fine with my previous Dockerfile
I removed forman from Gemfile and added your line to Dockerfile after # Install packages needed for deployment and it doesn’t work
2024-07-05T17:45:18.190 app[9185776dfd30e8] fra [info] foreman start --procfile=Procfile.fly
2024-07-05T17:45:18.555 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/bundler-2.5.12/lib/bundler/rubygems_integration.rb:265:in `block in replace_bin_path': can't find executable foreman for gem foreman. foreman is not currently included in the bundle, perhaps you meant to add it to your Gemfile? (Gem::Exception)
2024-07-05T17:45:18.555 app[9185776dfd30e8] fra [info] from /rails/vendor/ruby/3.3.0/gems/bundler-2.5.12/lib/bundler/rubygems_integration.rb:293:in `block in replace_bin_path'
2024-07-05T17:45:18.555 app[9185776dfd30e8] fra [info] from /usr/local/bundle/bin/foreman:25:in `<main>'
2024-07-05T17:45:18.562 app[9185776dfd30e8] fra [info] bin/rails aborted!
2024-07-05T17:45:18.565 app[9185776dfd30e8] fra [info] Command failed with status (1): [foreman start --procfile=Procfile.fly]
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/file_utils.rb:65:in `block in create_shell_runner'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/file_utils.rb:57:in `sh'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/lib/tasks/fly.rake:14:in `block (2 levels) in <main>'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/task.rb:281:in `block in execute'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/task.rb:281:in `each'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/task.rb:281:in `execute'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/task.rb:219:in `block in invoke_with_call_chain'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/task.rb:199:in `synchronize'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/task.rb:199:in `invoke_with_call_chain'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/task.rb:188:in `invoke'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/application.rb:188:in `invoke_task'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/application.rb:138:in `block (2 levels) in top_level'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/application.rb:138:in `each'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/application.rb:138:in `block in top_level'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/application.rb:147:in `run_with_threads'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/application.rb:132:in `top_level'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/commands/rake/rake_command.rb:27:in `block (2 levels) in perform'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/application.rb:214:in `standard_exception_handling'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/commands/rake/rake_command.rb:27:in `block in perform'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/commands/rake/rake_command.rb:44:in `block in with_rake'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/rake-13.2.1/lib/rake/rake_module.rb:59:in `with_application'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/commands/rake/rake_command.rb:41:in `with_rake'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/commands/rake/rake_command.rb:20:in `perform'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/command.rb:156:in `invoke_rake'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/command.rb:73:in `block in invoke'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/command.rb:149:in `with_argv'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/command.rb:69:in `invoke'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/railties-7.1.3.4/lib/rails/commands.rb:18:in `<main>'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] /rails/vendor/ruby/3.3.0/gems/bootsnap-1.18.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30:in `require'
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] Tasks: TOP => fly:server
2024-07-05T17:45:18.566 app[9185776dfd30e8] fra [info] (See full trace by running task with --trace)
2024-07-05T17:45:19.444 app[9185776dfd30e8] fra [info] INFO Main child exited normally with code: 1
2024-07-05T17:45:19.458 app[9185776dfd30e8] fra [info] INFO Starting clean up.
2024-07-05T17:45:19.473 app[9185776dfd30e8] fra [info] INFO Umounting /dev/vdc from /cache
2024-07-05T17:45:19.474 app[9185776dfd30e8] fra [info] WARN could not unmount /rootfs: EINVAL: Invalid argument
2024-07-05T17:45:19.475 app[9185776dfd30e8] fra [info] [ 5.689176] reboot: Restarting system
ruby-foreman should also work. Did you recently change to Ruby 3.3.0? I am guessing that somehow bundler is interfering with the gems that are being loaded.
Can I see your fly.rake file? It might be that all you need to do is to add the following around your foreman start line:
I had with_original_env before, but with_unbundled_env still same error:
/usr/local/lib/ruby/site_ruby/3.3.0/rubygems.rb:259:in `find_spec_for_exe': can't find gem foreman (>= 0.a) with executable foreman (Gem::GemNotFoundException)
2024-07-05T18:26:30.007 app[9185776dfd30e8] fra [info] from /usr/local/lib/ruby/site_ruby/3.3.0/rubygems.rb:278:in `activate_bin_path'
2024-07-05T18:26:30.007 app[9185776dfd30e8] fra [info] from /usr/local/bundle/bin/foreman:25:in `<main>'
2024-07-05T18:26:30.012 app[9185776dfd30e8] fra [info] bin/rails aborted!
2024-07-05T18:26:30.015 app[9185776dfd30e8] fra [info] Command failed with status (1): [foreman start --procfile=Procfile.fly]
I’ve updated to 3.3.3 soon after it came out. Not sure if related.
Here’s my rake file:
namespace :fly do
task release: :environment do
Rake::Task["db:migrate:primary"].invoke
Activity.insert({user_id: 1, action: "released", payload: {revision: ENV["GIT_SHA"], description: ENV["GIT_MESSAGE"]}})
end
task server: :environment do
url = "#{ENV["SSH_KEY_URL"]}"
sh "curl -o ~/.ssh/id_rsa #{url}"
sh "chmod 600 ~/.ssh/id_rsa"
Bundler.with_unbundled_env do
sh "foreman start --procfile=Procfile.fly"
end
end
end
and Dockerfile:
# syntax = docker/dockerfile:1
# Make sure RUBY_VERSION matches the Ruby version in .ruby-version and Gemfile
ARG RUBY_VERSION=3.3.3
FROM ruby:$RUBY_VERSION-slim as base
# Rails app lives here
WORKDIR /rails
# Set production environment
ENV BUNDLE_DEPLOYMENT="1" \
BUNDLE_PATH="/usr/local/bundle" \
BUNDLE_WITHOUT="development:test" \
RAILS_ENV="production"
# Update gems and bundler
RUN gem update --system --no-document && \
gem install -N bundler
# Throw-away build stage to reduce size of final image
FROM base as build
# Install packages needed to build gems
RUN --mount=type=cache,id=dev-apt-cache,sharing=locked,target=/var/cache/apt \
--mount=type=cache,id=dev-apt-lib,sharing=locked,target=/var/lib/apt \
apt-get update -qq && \
apt-get install --no-install-recommends -y build-essential default-libmysqlclient-dev libpq-dev libvips pkg-config
# Install application gems
COPY --link Gemfile Gemfile.lock ./
RUN --mount=type=cache,id=bld-gem-cache,sharing=locked,target=/srv/vendor \
bundle config set app_config .bundle && \
bundle config set path /srv/vendor && \
bundle install && \
bundle exec bootsnap precompile --gemfile && \
bundle clean && \
mkdir -p vendor && \
bundle config set path vendor && \
cp -ar /srv/vendor .
# Copy application code
COPY --link . .
# Precompile bootsnap code for faster boot times
RUN bundle exec bootsnap precompile app/ lib/
# Precompiling assets for production without requiring secret RAILS_MASTER_KEY
RUN SECRET_KEY_BASE_DUMMY=1 ./bin/rails assets:precompile
# Final stage for app image
FROM base
# Install packages needed for deployment
RUN --mount=type=cache,id=dev-apt-cache,sharing=locked,target=/var/cache/apt \
--mount=type=cache,id=dev-apt-lib,sharing=locked,target=/var/lib/apt \
apt-get update -qq && \
apt-get install --no-install-recommends -y curl default-mysql-client imagemagick libjemalloc2 libsqlite3-0 libvips postgresql-client openssh-client ruby-foreman
RUN gem install foreman
# Copy built artifacts: gems, application
COPY --from=build "${BUNDLE_PATH}" "${BUNDLE_PATH}"
COPY --from=build /rails /rails
# Run and own only the runtime files as a non-root user for security
RUN groupadd --system --gid 1000 rails && \
useradd rails --uid 1000 --gid 1000 --create-home --shell /bin/bash && \
chown -R 1000:1000 db log storage tmp
USER 1000:1000
# Deployment options
ENV LD_PRELOAD="libjemalloc.so.2" \
MALLOC_CONF="dirty_decay_ms:1000,narenas:2,background_thread:true"
RUN mkdir ~/.ssh && \
echo "Host *" > ~/.ssh/config && \
echo " StrictHostKeyChecking accept-new" >> ~/.ssh/config && \
echo " ControlMaster auto" >> ~/.ssh/config && \
echo " ControlPath ~/.ssh/%r@%h:%p" >> ~/.ssh/config
ARG SERVER_COMMAND="bin/rails fly:server"
ENV SERVER_COMMAND ${SERVER_COMMAND}
CMD ${SERVER_COMMAND}
I can’t predict what the symptoms would be, but anything remote related to bundler is suspect.
Try the workaround. Try 3.3.2. Alternately, create a small startup script (you can name it whatever you like, and it can even be in Ruby if it is marked executable. That script could look something like this:
#!/usr/bin/env ruby
url = "#{ENV["SSH_KEY_URL"]}"
system "curl -o ~/.ssh/id_rsa #{url}"
system "chmod 600 ~/.ssh/id_rsa"
system "foreman start --procfile=Procfile.fly"
And then change the value of SERVER_COMMAND to name the script that you created.
No luck with either of these I guess I’m stuck with the Gemfile solution
One thing that I just remembered could maybe have an effect - this started happening with the “new machines”.
If you’re getting this email, your organization ECT has Fly Apps with Fly Machines on host servers which need to be taken down for upgrades or maintenance. Starting from 06:00 UTC June 20th, we will begin to migrate Fly Machines on these host servers to a different host server. If your app consists of a single Machine, you may notice a few minutes of downtime. If your app consists of multiple Machines, you shouldn’t notice anything at all.
Migrations List:
I guess I’m stuck with the Gemfile solution 