Foreman-nightly-rpm-pipeline 1222 failed

jenkins · October 15, 2021, 11:04am

Foreman RPM nightly pipeline failed:

https://ci.theforeman.org/job/foreman-nightly-rpm-pipeline/1222/

foreman-pipeline-foreman-nightly-centos7-install (passed) (remote job)
foreman-pipeline-foreman-nightly-centos8-install (passed) (remote job)
foreman-pipeline-foreman-nightly-centos8-stream-install (passed) (remote job)
foreman-pipeline-foreman-nightly-centos7-upgrade (failed) (remote job)
foreman-pipeline-foreman-nightly-centos8-upgrade (failed) (remote job)

evgeni · October 15, 2021, 11:36am

the installs passed finally – thanks @ezr-ondrej and @nadjaheitmann!

The upgrades fail to start dynflow tho.

Oct 15 10:56:40 pipe-up-foreman-nightly-centos7.n5.example.com systemd[1]: Starting Foreman jobs daemon - orchestrator on sidekiq...
Oct 15 10:56:43 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: 2021-10-15T10:56:43.572Z 32239 TID-o6z INFO: GitLab reliable fetch activated!
Oct 15 10:56:43 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: 2021-10-15T10:56:43.574Z 32239 TID-o5j INFO: Booting Sidekiq 5.2.7 with redis options {:id=>"Sidekiq-server-PID-32239", :url=>"redis://localhost:6379/0"}
Oct 15 10:56:49 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: API controllers newer than Apipie cache! Run apipie:cache rake task to regenerate cache.
Oct 15 10:56:51 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_puppet-2.0.0.alpha.2/lib/foreman_puppet/register.rb:120: warning: already initialized constant Foreman::Plugin::RbacSupport::AUTO_EXTENDED_ROLES
Oct 15 10:56:51 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /usr/share/foreman/app/registries/foreman/plugin/rbac_support.rb:5: warning: previous definition of AUTO_EXTENDED_ROLES was here
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: 285 extra bytes after the deserialized object
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/msgpack-1.3.3/lib/msgpack.rb:37:in `full_unpack'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/msgpack-1.3.3/lib/msgpack.rb:37:in `load'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.1/lib/dynflow/persistence_adapters/sequel.rb:390:in `load_data'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.1/lib/dynflow/persistence_adapters/sequel.rb:260:in `block in find_coordinator_records'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.1/lib/dynflow/persistence_adapters/sequel.rb:260:in `map'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.1/lib/dynflow/persistence_adapters/sequel.rb:260:in `find_coordinator_records'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.1/lib/dynflow/coordinator_adapters/sequel.rb:30:in `find_records'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.1/lib/dynflow/coordinator.rb:366:in `find_records'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.1/lib/dynflow/coordinator.rb:372:in `find_worlds'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.1/lib/dynflow/world/invalidation.rb:131:in `worlds_validity_check'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.1/lib/dynflow/world/invalidation.rb:118:in `perform_validity_checks'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.1/lib/dynflow/rails.rb:46:in `block in initialize!'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.1/lib/dynflow/rails.rb:38:in `tap'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.1/lib/dynflow/rails.rb:38:in `initialize!'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /usr/share/foreman/extras/dynflow-sidekiq.rb:34:in `<top (required)>'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/rh/rh-ruby27/root/usr/share/rubygems/rubygems/core_ext/kernel_require.rb:83:in `require'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/rh/rh-ruby27/root/usr/share/rubygems/rubygems/core_ext/kernel_require.rb:83:in `require'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/cli.rb:292:in `boot_system'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/cli.rb:46:in `run'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/bin/sidekiq:12:in `<top (required)>'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/bin/sidekiq:23:in `load'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com dynflow-sidekiq@orchestrator[32239]: /opt/theforeman/tfm/root/usr/bin/sidekiq:23:in `<main>'
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com systemd[1]: dynflow-sidekiq@orchestrator.service: main process exited, code=exited, status=1/FAILURE
Oct 15 10:57:06 pipe-up-foreman-nightly-centos7.n5.example.com systemd[1]: Failed to start Foreman jobs daemon - orchestrator on sidekiq.

@aruzicka could it be that dynflow fails to load its own messages from before the upgrade?

evgeni · October 15, 2021, 12:13pm

After talking to Adam: this is probably due to Dynflow not being stopped during the upgrade.

Running a pipeline locally now to verify that.

evgeni · October 15, 2021, 12:57pm

And indeed, if I shutdown the services before the upgrade, it seems to pass fine.

For that, I removed this line:

github.com

theforeman/forklift/blob/a3821f08ff3e28cc658c6373df9f163de87ddad6/roles/foreman_installer/tasks/upgrade.yml#L4

    
      
          ---
          - name: 'Stop services'
            command: foreman-maintain service stop
            when: foreman_installer_scenario != 'foreman'
          
          
- name: 'Update packages'
            import_role:
              name: update_os_packages
          
          
- name: 'Upgrade postgresql'
            import_role:
              name: theforeman.operations.postgresql_upgrade
            when:
              - ansible_os_family == "RedHat"

However, this would fail on Debian, where we don’t have foreman-maintain (yet).

ekohl · October 18, 2021, 9:36am

So when do we need to stop Dynflow? Is it during the package upgrade from < 1.6? Or can we migrate the Dynflow DB and then restart it.

If it reads files at runtime and can’t handle a difference between the DB and what’s on disk then I’d argue that packaging should detect the upgrade and stop the service(s). Then the installer will rectify it.

In short: do we know what the sequence of events is?

aruzicka · October 18, 2021, 9:41am

As far as I understand

Dynflow (rpm) gets upgraded
Foreman (rpm) gets upgraded
Foreman gets restarted (possibly from %post?)
As part of startup dynflow inside the foreman process migrates the db (dynflow runs migrations on startup)
dynflow-sidekiq@whatever services are still running, but the db suddenly doesn’t match
dynflow-sidekiq@whatever services get restarted
dynflow-sidekiq@whatever services cannot start, because the db now contains bogus data created in 5

evgeni · October 18, 2021, 9:48am

Given the error is:

285 extra bytes after the deserialized object
 /opt/theforeman/tfm/root/usr/share/gems/gems/msgpack-1.3.3/lib/msgpack.rb:37:in `full_unpack'
 /opt/theforeman/tfm/root/usr/share/gems/gems/msgpack-1.3.3/lib/msgpack.rb:37:in `load'
 /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.1/lib/dynflow/persistence_adapters/sequel.rb:390:in `load_data'

It more sounds like it’s the new code that is trying to load old data?

ekohl · October 18, 2021, 10:53am

This also has a restart:

github.com

theforeman/foreman-packaging/blob/4ad405949263bfb84fc184285fe664004f61b01d/packages/foreman/foreman/foreman.spec#L674


      
          %{_unitdir}/%{dynflow_sidekiq_service_name}.service
          %{_datadir}/%{name}/extras/dynflow-sidekiq.rb
          
          %post dynflow-sidekiq
          %systemd_post %{dynflow_sidekiq_service_name}.service
          
          %preun dynflow-sidekiq
          %systemd_preun %{dynflow_sidekiq_service_name}.service
          
          %postun dynflow-sidekiq
          %systemd_postun_with_restart %{dynflow_sidekiq_service_name}.service
          
          %package service
          Summary: Foreman systemd service support
          Group:  Applications/System
          # start specfile service Requires
          Requires: %{?scl_prefix}rubygem(puma) >= 5.1
          Requires: %{?scl_prefix}rubygem(puma) < 6.0
          # end specfile service Requires
          Requires: %{?scl_prefix}rubygem(puma-status)
          Requires: %{name} = %{version}-%{release}

In EL7 and EL8 this resolves to a systemctl try-restart. Recent Fedoras have /usr/bin/systemctl set-property $unit Markers=+needs-restart.

Yes, that’s here:

github.com

theforeman/foreman-packaging/blob/4ad405949263bfb84fc184285fe664004f61b01d/packages/foreman/foreman/foreman.spec#L1031


      
          %tmpfiles_create %{_tmpfilesdir}/%{name}.conf
          exit 0
          
          %post service
          %systemd_post %{name}.socket %{name}.service
          
          %preun service
          %systemd_preun %{name}.socket %{name}.service
          
          %postun service
          %systemd_postun_with_restart %{name}.service
          %systemd_postun %{name}.socket
          
          %changelog
          * Thu Aug 05 2021 Patrick Creech <pcreech@redhat.com> - 3.1.0-0.1.develop
          - Bump version to 3.1-develop
          
          * Thu Jul 22 2021 Tomer Brisker <tbrisker@gmail.com> - 3.0.0-0.1.develop
          - Bump version to 3.0-develop
          
          * Wed Jun 02 2021 Amir Feferkuchen <afeferku@redhat.com> - 2.6.0-0.2.develop

So it should be running new code, likely with an old DB.

aruzicka · October 18, 2021, 11:01am

I meant tfm-rubygem-dynflow, not foreman-dynflow-sidekiq

evgeni · October 18, 2021, 11:15am

I think we actually can’t know (for sure) which dynflow is running, as the events "tfm-rubygem-dynflow is updated" and "%post of foreman-dynflow-sidekiq triggers" can happen in any order?

(at least with the current packaging, we could enforce a %post dependency on the newer dynflow, which would force yum to sort the events)

ekohl · October 18, 2021, 12:11pm

@evgeni Are you suggesting to change this line to be >= 1.6.0:

github.com

theforeman/foreman/blob/213b97728edfec55e822fa28025460ea0d30c70d/Gemfile#L51

    
      
          gem 'activerecord-session_store', '>= 2.0.0', '< 3'
          gem 'sprockets', '~> 4.0'
          gem 'sprockets-rails', '~> 3.0'
          gem 'record_tag_helper', '~> 1.0'
          gem 'responders', '~> 3.0'
          gem 'roadie-rails', '~> 2.0'
          gem 'deacon', '~> 1.0'
          gem 'webpack-rails', '~> 0.9.8'
          gem 'mail', '~> 2.7'
          gem 'sshkey', '~> 1.9'
          gem 'dynflow', '>= 1.4.4', '< 2.0.0'
          gem 'daemons'
          gem 'bcrypt', '~> 3.1'
          gem 'get_process_mem'
          gem 'rack-cors', '~> 1.0.2', require: 'rack/cors'
          gem 'jwt', '~> 2.2.2'
          gem 'graphql', '~> 1.8.0'
          gem 'graphql-batch'
          
          
Dir["#{File.dirname(FOREMAN_GEMFILE)}/bundler.d/*.rb"].each do |bundle|
            instance_eval(Bundler.read_file(bundle))

@aruzicka can you remind me? do the DB migrations for dynflow run as part of foreman-rake db:migrate or part of the dynflow/sidekiq startup?

evgeni · October 18, 2021, 12:21pm

No, maybe? Does Requires: A > 1.0 imply that A > 1.0 is available during %post? Or does it need to be Require(post): A > 1.0?

aruzicka · October 19, 2021, 8:40am

Both. They run after foreman migration when db:migrate is invoked, but they also run during startup of any process which uses dynflow.

How about this as an alternative approach Fixes #33723 - Make dynflow-sidekiq services PartOf foreman.service by adamruzicka · Pull Request #8856 · theforeman/foreman · GitHub ?

ehelms · October 19, 2021, 8:47pm

This appears to be resolved – Jenkins

Good work all!

system · October 26, 2021, 8:48pm

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.