Foreman-nightly-rpm-pipeline 1222 failed

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)

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?

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

Running a pipeline locally now to verify that.

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

For that, I removed this line:

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

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?

As far as I understand

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

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?

This also has a restart:

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:

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

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

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)

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

@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?

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?

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 https://github.com/theforeman/foreman/pull/8856 ?

This appears to be resolved – Jenkins

Good work all!

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