Upgrading to 4.0.0, ruby 2.4, causes unicorn exit status 127

[jcormier]

Upgrading from redmine:3.4.7 to redmine:4.0.0 causes unicorn to exit repeatedly. This is due to the upgrade from ruby 3.3 to 3.4. The files in /srv/docker/redmine/redmine/tmp/ need to be removed.

 $ grep redmine: docker-compose.yml 
  redmine:
    image: sameersbn/redmine:4.0.0
    - /srv/docker/redmine/redmine:/home/redmine/data
 $ docker-compose down
Removing dockerredmine_redmine_1    ... done
Removing dockerredmine_postgresql_1 ... done
Removing network dockerredmine_default
 $ docker-compose up
Creating network "dockerredmine_default" with the default driver
Creating dockerredmine_postgresql_1 ... 
Creating dockerredmine_postgresql_1 ... done
Creating dockerredmine_redmine_1 ... 
Creating dockerredmine_redmine_1 ... done
Attaching to dockerredmine_postgresql_1, dockerredmine_redmine_1
postgresql_1  | Initializing datadir...
redmine_1     | Initializing logdir...
redmine_1     | Initializing datadir...
redmine_1     | Symlinking dotfiles...
redmine_1     | Installing configuration templates...
redmine_1     | Configuring redmine...
postgresql_1  | Initializing certdir...
postgresql_1  | Initializing logdir...
postgresql_1  | Initializing rundir...
postgresql_1  | Setting resolv.conf ACLs...
postgresql_1  | Creating database user: redmine
postgresql_1  | Creating database: redmine_production...
postgresql_1  | ‣ Granting access to redmine user...
postgresql_1  | Starting PostgreSQL 9.6...
postgresql_1  | LOG:  database system was shut down at 2019-01-23 15:39:06 UTC
postgresql_1  | LOG:  MultiXact member wraparound protections are now enabled
postgresql_1  | LOG:  database system is ready to accept connections
postgresql_1  | LOG:  autovacuum launcher started
redmine_1     | Configuring redmine::database...
redmine_1     | Configuring redmine::unicorn...
redmine_1     | Configuring redmine::secret_token...
redmine_1     | Generating a session token...
redmine_1     | Note:
redmine_1     |   All old sessions will become invalid.
redmine_1     |   Please specify the REDMINE_SECRET_TOKEN parameter for persistence.
redmine_1     |   **SHOULD** be defined if you have a load-balancing Redmine cluster.
redmine_1     | Configuring redmine::max_concurrent_ajax_uploads...
redmine_1     | Configuring redmine::sudo_mode...
redmine_1     | Configuring redmine::autologin_cookie...
redmine_1     | Configuring redmine::backups...
redmine_1     | Configuring nginx...
redmine_1     | Configuring nginx::redmine...
redmine_1     | Installing plugins...
redmine_1     | Installing themes...
redmine_1     | 2019-01-23 21:09:08,742 CRIT Supervisor running as root (no user in config file)
redmine_1     | 2019-01-23 21:09:08,742 WARN Included extra file "/etc/supervisor/conf.d/cron.conf" during parsing
redmine_1     | 2019-01-23 21:09:08,742 WARN Included extra file "/etc/supervisor/conf.d/nginx.conf" during parsing
redmine_1     | 2019-01-23 21:09:08,742 WARN Included extra file "/etc/supervisor/conf.d/unicorn.conf" during parsing
redmine_1     | 2019-01-23 21:09:08,751 INFO RPC interface 'supervisor' initialized
redmine_1     | 2019-01-23 21:09:08,752 CRIT Server 'unix_http_server' running without any HTTP authentication checking
redmine_1     | 2019-01-23 21:09:08,752 INFO supervisord started with pid 1
redmine_1     | 2019-01-23 21:09:09,755 INFO spawned: 'unicorn' with pid 229
redmine_1     | 2019-01-23 21:09:09,758 INFO spawned: 'cron' with pid 230
redmine_1     | 2019-01-23 21:09:09,760 INFO spawned: 'nginx' with pid 231
redmine_1     | 2019-01-23 21:09:09,904 INFO exited: unicorn (exit status 127; not expected)
redmine_1     | 2019-01-23 21:09:10,908 INFO spawned: 'unicorn' with pid 235
redmine_1     | 2019-01-23 21:09:10,909 INFO success: cron entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
redmine_1     | 2019-01-23 21:09:10,909 INFO success: nginx entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
redmine_1     | 2019-01-23 21:09:11,011 INFO exited: unicorn (exit status 127; not expected)
redmine_1     | 2019-01-23 21:09:13,016 INFO spawned: 'unicorn' with pid 239
redmine_1     | 2019-01-23 21:09:13,112 INFO exited: unicorn (exit status 127; not expected)
^CGracefully stopping... (press Ctrl+C again to force)
Stopping dockerredmine_redmine_1    ... done
Stopping dockerredmine_postgresql_1 ... done

With removing old ruby files

$ docker-compose down
Removing dockerredmine_redmine_1    ... done
Removing dockerredmine_postgresql_1 ... done
Removing network dockerredmine_default
 $ sudo rm -rf /srv/docker/redmine/redmine/tmp/
 $ docker-compose up
Creating network "dockerredmine_default" with the default driver
Creating dockerredmine_postgresql_1 ... 
Creating dockerredmine_postgresql_1 ... done
Creating dockerredmine_redmine_1 ... 
Creating dockerredmine_redmine_1 ... done
Attaching to dockerredmine_postgresql_1, dockerredmine_redmine_1
postgresql_1  | Initializing datadir...
redmine_1     | Initializing logdir...
redmine_1     | Initializing datadir...
redmine_1     | Symlinking dotfiles...
redmine_1     | Installing configuration templates...
redmine_1     | Configuring redmine...
postgresql_1  | Initializing certdir...
postgresql_1  | Initializing logdir...
postgresql_1  | Initializing rundir...
postgresql_1  | Setting resolv.conf ACLs...
postgresql_1  | Creating database user: redmine
postgresql_1  | Creating database: redmine_production...
postgresql_1  | ‣ Granting access to redmine user...
postgresql_1  | Starting PostgreSQL 9.6...
postgresql_1  | LOG:  database system was shut down at 2019-01-23 15:48:04 UTC
postgresql_1  | LOG:  MultiXact member wraparound protections are now enabled
postgresql_1  | LOG:  autovacuum launcher started
postgresql_1  | LOG:  database system is ready to accept connections
redmine_1     | Configuring redmine::database...
redmine_1     | Configuring redmine::unicorn...
redmine_1     | Configuring redmine::secret_token...
redmine_1     | Generating a session token...
redmine_1     | Note:
redmine_1     |   All old sessions will become invalid.
redmine_1     |   Please specify the REDMINE_SECRET_TOKEN parameter for persistence.
redmine_1     |   **SHOULD** be defined if you have a load-balancing Redmine cluster.
redmine_1     | Configuring redmine::max_concurrent_ajax_uploads...
redmine_1     | Configuring redmine::sudo_mode...
redmine_1     | Configuring redmine::autologin_cookie...
redmine_1     | Configuring redmine::backups...
redmine_1     | Configuring nginx...
redmine_1     | Configuring nginx::redmine...
redmine_1     | Migrating database. Please be patient, this could take a while...
postgresql_1  | ERROR:  database "redmine_production" already exists
postgresql_1  | STATEMENT:  CREATE DATABASE "redmine_production" ENCODING = 'unicode'
redmine_1     | Database 'redmine_production' already exists
redmine_1     | Installing plugins...
redmine_1     | Installing gems required by plugins...
redmine_1     | Migrating plugins. Please be patient, this could take a while...
redmine_1     | Installing themes...
redmine_1     | 2019-01-23 21:18:16,252 CRIT Supervisor running as root (no user in config file)
redmine_1     | 2019-01-23 21:18:16,252 WARN Included extra file "/etc/supervisor/conf.d/cron.conf" during parsing
redmine_1     | 2019-01-23 21:18:16,252 WARN Included extra file "/etc/supervisor/conf.d/nginx.conf" during parsing
redmine_1     | 2019-01-23 21:18:16,252 WARN Included extra file "/etc/supervisor/conf.d/unicorn.conf" during parsing
redmine_1     | 2019-01-23 21:18:16,262 INFO RPC interface 'supervisor' initialized
redmine_1     | 2019-01-23 21:18:16,262 CRIT Server 'unix_http_server' running without any HTTP authentication checking
redmine_1     | 2019-01-23 21:18:16,262 INFO supervisord started with pid 1
redmine_1     | 2019-01-23 21:18:17,266 INFO spawned: 'unicorn' with pid 288
redmine_1     | 2019-01-23 21:18:17,269 INFO spawned: 'cron' with pid 289
redmine_1     | 2019-01-23 21:18:17,272 INFO spawned: 'nginx' with pid 290
redmine_1     | 2019-01-23 21:18:18,498 INFO success: unicorn entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
redmine_1     | 2019-01-23 21:18:18,498 INFO success: cron entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
redmine_1     | 2019-01-23 21:18:18,499 INFO success: nginx entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

Note: Make sure you run docker-compose down or you may end up with errors

redmine_1     | Migrating database. Please be patient, this could take a while...
redmine_1     | bundler: failed to load command: rake (/usr/bin/rake)
redmine_1     | Bundler::GemNotFound: Could not find gem 'rails (= 5.2.2)' in any of the gem sources listed in your Gemfile.
redmine_1     |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/resolver.rb:287:in `block in verify_gemfile_dependencies_are_found!'
redmine_1     |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/resolver.rb:255:in `each'
redmine_1     |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/resolver.rb:255:in `verify_gemfile_dependencies_are_found!'
redmine_1     |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/resolver.rb:49:in `start'
redmine_1     |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/resolver.rb:22:in `resolve'
redmine_1     |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/definition.rb:258:in `resolve'
redmine_1     |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/definition.rb:170:in `specs'
redmine_1     |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/definition.rb:237:in `specs_for'
redmine_1     |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/definition.rb:226:in `requested_specs'
redmine_1     |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/runtime.rb:108:in `block in definition_method'
redmine_1     |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/runtime.rb:20:in `setup'
redmine_1     |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler.rb:107:in `setup'
redmine_1     |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/setup.rb:20:in `<top (required)>'
redmine_1     |   /usr/lib/ruby/2.4.0/rubygems/core_ext/kernel_require.rb:55:in `require'
redmine_1     |   /usr/lib/ruby/2.4.0/rubygems/core_ext/kernel_require.rb:55:in `require'
dockerredmine_redmine_1 exited with code 1

[jcormier]

TODO: Update startup script to detect a change in ruby version and auto clean the old bundle installs.

[nguyenl95]

@jcormier I've met the same issue, the cause is that I deleted the /srv/docker/redmine/redmine/tmp folder

Here is my logs

redmine_1  | Configuring redmine::unicorn...
redmine_1  | Configuring redmine::secret_token...
redmine_1  | Generating a session token...
redmine_1  | Note:
redmine_1  |   All old sessions will become invalid.
redmine_1  |   Please specify the REDMINE_SECRET_TOKEN parameter for persistence.
redmine_1  |   **SHOULD** be defined if you have a load-balancing Redmine cluster.
redmine_1  | Configuring redmine::max_concurrent_ajax_uploads...
redmine_1  | Configuring redmine::sudo_mode...
redmine_1  | Configuring redmine::autologin_cookie...
redmine_1  | Configuring redmine::email_delivery...
redmine_1  | Configuring redmine::incoming_email...
redmine_1  | Configuring redmine::backups...
redmine_1  | Configuring nginx...
redmine_1  | Configuring nginx::redmine...
redmine_1  | Migrating database. Please be patient, this could take a while...
redmine_1  | bundler: failed to load command: rake (/usr/bin/rake)
redmine_1  | Bundler::GemNotFound: Could not find gem 'rails (= 5.2.2)' in any of the gem sources listed in your Gemfile.
redmine_1  |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/resolver.rb:287:in `block in verify_gemfile_dependencies_are_found!'
redmine_1  |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/resolver.rb:255:in `each'
redmine_1  |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/resolver.rb:255:in `verify_gemfile_dependencies_are_found!'
redmine_1  |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/resolver.rb:49:in `start'
redmine_1  |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/resolver.rb:22:in `resolve'
redmine_1  |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/definition.rb:258:in `resolve'
redmine_1  |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/definition.rb:170:in `specs'
redmine_1  |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/definition.rb:237:in `specs_for'
redmine_1  |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/definition.rb:226:in `requested_specs'
redmine_1  |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/runtime.rb:108:in `block in definition_method'
redmine_1  |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/runtime.rb:20:in `setup'
redmine_1  |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler.rb:107:in `setup'
redmine_1  |   /var/lib/gems/2.4.0/gems/bundler-2.0.1/lib/bundler/setup.rb:20:in `<top (required)>'
redmine_1  |   /usr/lib/ruby/2.4.0/rubygems/core_ext/kernel_require.rb:55:in `require'
redmine_1  |   /usr/lib/ruby/2.4.0/rubygems/core_ext/kernel_require.rb:55:in `require'
docker-redmine_redmine_1 exited with code 1
docker-redmine_mysql_1 exited with code 137

[jcormier]

If you remove the /srv/docker/redmine/redmine/tmp folder, you need to make sure you delete the container volume.

With docker-compose this can be done by docker-compose down.

With regular docker command I'm not sure how to do this but some googling should find the answer.

[bung87]

I modify ENV RUBY_VERSION=2.5 also cause unicorn exit status 127 ,the supervisor can't run command bundle exec unicorn-rails or unicorn,I checked the bundle install path ,it shows ruby/2.4.0

[jcormier]

Correct, we don't check the ruby version when determining if the tmp cache needs to be deleted. If you change the ruby version, make sure to bring down the container docker-compose down. And delete the /srv/docker/redmine/redmine/tmp folder.

[bung87]

yeah,I remove the volume and rebuild it works, I can't image why a tmp folder could cause this problem

[jcormier]

The tmp folder contains a cache of the ruby bundle information, so we don't have to reinstall the gems every time the container is started. If you change the ruby version, we need to run through all the bundle install steps again, but we don't because the cache looks like it exists.

This issue is still open, since ideally, we would detect that the cache is for the wrong version of ruby and rerun the bundle step.

[bung87]

my previous experience just build the apt dev packages and gems into image, so it just relys on docker build cache layer, the bad part is the image bigger.

[jcormier]

I can't really speak for @sameersbn original reason for this decision. But I suspect plugins can require additional gems, which would slow everything down on container start.