foreman-nightly-deb-pipeline 775 failed

Foreman DEB nightly pipeline failed:

https://ci.theforeman.org/job/foreman-nightly-deb-pipeline/775/

foreman-pipeline-foreman-nightly-debian10-install (passed) (remote job)
foreman-pipeline-foreman-nightly-ubuntu1804-install (passed) (remote job)
foreman-pipeline-foreman-nightly-debian10-upgrade (failed) (remote job)
foreman-pipeline-foreman-nightly-ubuntu2004-install (passed) (remote job)
foreman-pipeline-foreman-nightly-ubuntu1804-upgrade (failed) (remote job)
foreman-pipeline-foreman-nightly-ubuntu2004-upgrade (failed) (remote job)

I spun one of the upgrade pipelines up locally and this is what I see happening (but not clear why).

  • Upgrade makes it to nightly and runs the installer
  • Installer code for the new infrastructure roles reports a 404
    • This 404 happens because according to Foreman the new APIs do not exist
    • Check the code, and the API code is present in the build on the box
  • Manually restart foreman
  • The APIs are now present and the installer continues onward (and for me then fails on a dynflow problem)

This leads me to conclude one of two things:

a) something during upgrade that should be causing a restart of foreman.service is not happening after the package gets updated
b) there is an ordering problem in the installer with the service getting restarted when the package updates and before we call any of the APIs in Foreman

We don’t see this issue in RPM based setups.

I do not know if its related, or unconvered an additional (or already known failure) so for the record, the dynflow failure seen after fixing the API issue is:

2021-10-28 15:21:32 [ERROR ] [configure] Systemd start for dynflow-sidekiq@orchestrator failed!
2021-10-28 15:21:32 [ERROR ] [configure] journalctl log for dynflow-sidekiq@orchestrator:
2021-10-28 15:21:32 [ERROR ] [configure] -- Logs begin at Thu 2021-10-28 13:08:45 UTC, end at Thu 2021-10-28 15:21:32 UTC. --
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:23 pipe-up-foreman-nightly-ubuntu2004 systemd[1]: Stopping Foreman jobs daemon - orchestrator on sidekiq...
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:24 pipe-up-foreman-nightly-ubuntu2004 systemd[1]: dynflow-sidekiq@orchestrator.service: Succeeded.
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:24 pipe-up-foreman-nightly-ubuntu2004 systemd[1]: Stopped Foreman jobs daemon - orchestrator on sidekiq.
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:24 pipe-up-foreman-nightly-ubuntu2004 systemd[1]: Starting Foreman jobs daemon - orchestrator on sidekiq...
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:25 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: 2021-10-28T15:20:25.354Z 93316 TID-20s8 INFO: GitLab reliable fetch activated!
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:25 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: 2021-10-28T15:20:25.364Z 93316 TID-2104 INFO: Booting Sidekiq 5.2.9 with redis options {:id=>"Sidekiq-server-PID-93316", :url=>"redis://localhost:6379/0"}
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:26 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/graphql-1.8.18/lib/graphql/schema/mutation.rb:70: warning: Using the last argument as keyword parameters is deprecated; maybe ** should be added to the call
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:26 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/graphql-1.8.18/lib/graphql/schema/member/has_fields.rb:51: warning: The called method `field' is defined here
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:26 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/app/models/concerns/has_many_common.rb:48: warning: Using the last argument as keyword parameters is deprecated; maybe ** should be added to the call
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:26 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/activerecord-6.0.3.7/lib/active_record/associations.rb:1370: warning: The called method `has_many' is defined here
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:26 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/app/models/concerns/has_many_common.rb:53: warning: Using the last argument as keyword parameters is deprecated; maybe ** should be added to the call
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:26 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/activerecord-6.0.3.7/lib/active_record/associations.rb:1826: warning: The called method `has_and_belongs_to_many' is defined here
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:26 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/app/models/concerns/has_many_common.rb:77: warning: Using the last argument as keyword parameters is deprecated; maybe ** should be added to the call
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:26 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/activerecord-6.0.3.7/lib/active_record/associations.rb:1657: warning: The called method `belongs_to' is defined here
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:27 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/scoped_search-4.1.9/lib/scoped_search/definition.rb:309: warning: Using the last argument as keyword parameters is deprecated; maybe ** should be added to the call
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:27 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/scoped_search-4.1.9/lib/scoped_search/definition.rb:27: warning: The called method `initialize' is defined here
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:27 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: API controllers newer than Apipie cache! Run apipie:cache rake task to regenerate cache.
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:27 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/app/registries/foreman/settings/general.rb:53: warning: Passing the keyword argument as the last hash parameter is deprecated
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:27 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/app/registries/foreman/setting_manager.rb:98: warning: The called method `validates' is defined here
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:27 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/app/registries/foreman/settings/email.rb:82: warning: Passing the keyword argument as the last hash parameter is deprecated
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:27 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/app/registries/foreman/setting_manager.rb:98: warning: The called method `validates' is defined here
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:27 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/app/services/setting_registry.rb:135: warning: Using the last argument as keyword parameters is deprecated; maybe ** should be added to the call
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:27 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/app/services/setting_registry.rb:164: warning: The called method `_add' is defined here
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:27 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/foreman_puppet-2.0.0.alpha.2/lib/foreman_puppet/register.rb:120: warning: already initialized constant Foreman::Plugin::RbacSupport::AUTO_EXTENDED_ROLES
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:27 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/app/registries/foreman/plugin/rbac_support.rb:5: warning: previous definition of AUTO_EXTENDED_ROLES was here
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:28 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/graphql-1.8.18/lib/graphql/schema/input_object.rb:79: warning: Using the last argument as keyword parameters is deprecated; maybe ** should be added to the call
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:28 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/graphql-1.8.18/lib/graphql/schema/member/has_arguments.rb:16: warning: The called method `argument' is defined here
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: 273 extra bytes after the deserialized object
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/msgpack-1.3.3/lib/msgpack.rb:37:in `full_unpack'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/msgpack-1.3.3/lib/msgpack.rb:37:in `load'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/dynflow-1.6.1/lib/dynflow/persistence_adapters/sequel.rb:390:in `load_data'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/dynflow-1.6.1/lib/dynflow/persistence_adapters/sequel.rb:260:in `block in find_coordinator_records'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/dynflow-1.6.1/lib/dynflow/persistence_adapters/sequel.rb:260:in `map'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/dynflow-1.6.1/lib/dynflow/persistence_adapters/sequel.rb:260:in `find_coordinator_records'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/dynflow-1.6.1/lib/dynflow/coordinator_adapters/sequel.rb:30:in `find_records'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/dynflow-1.6.1/lib/dynflow/coordinator.rb:366:in `find_records'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/dynflow-1.6.1/lib/dynflow/coordinator.rb:372:in `find_worlds'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/dynflow-1.6.1/lib/dynflow/world/invalidation.rb:131:in `worlds_validity_check'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/dynflow-1.6.1/lib/dynflow/world/invalidation.rb:118:in `perform_validity_checks'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/dynflow-1.6.1/lib/dynflow/rails.rb:46:in `block in initialize!'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/dynflow-1.6.1/lib/dynflow/rails.rb:38:in `tap'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/dynflow-1.6.1/lib/dynflow/rails.rb:38:in `initialize!'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/extras/dynflow-sidekiq.rb:34:in `<top (required)>'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/sidekiq-5.2.9/lib/sidekiq/cli.rb:292:in `require'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/sidekiq-5.2.9/lib/sidekiq/cli.rb:292:in `boot_system'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/sidekiq-5.2.9/lib/sidekiq/cli.rb:46:in `run'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/gems/sidekiq-5.2.9/bin/sidekiq:12:in `<top (required)>'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/bin/sidekiq:23:in `load'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 dynflow-sidekiq@orchestrator[93316]: /usr/share/foreman/vendor/ruby/2.7.0/bin/sidekiq:23:in `<main>'
2021-10-28 15:21:32 [ERROR ] [configure] Oct 28 15:20:34 pipe-up-foreman-nightly-ubuntu2004 systemd[1]: dynflow-sidekiq@orchestrator.service: Main process exited, code=exited, status=1/FAILURE
2021-10-28 15:21:32 [ERROR ] [configure] /Stage[main]/Foreman::Service/Foreman::Dynflow::Worker[orchestrator]/Service[dynflow-sidekiq@orchestrator]/ensure: change from 'stopped' to 'running' failed: Systemd start for dynflow-sidekiq@orche

Further digging, what looks like is happening is:

  • Installer updates Foreman RPM
  • No service restart is issued
  • New infrastructure roles code executes and new APIs are not loaded

@ekohl This sounds like an ordering problem where the package install happens, then the API calls are able to happen before the services are restarted (which I assume a service restart ought to be triggered by package update and in theory happen before hand) ?

The PR that introduced this is: https://github.com/theforeman/puppet-foreman/pull/965

Normally the installer restarts the service if there was a change prior. That can be a change to the config file but given that’s quite stable, more often that it detects a db:migrate is needed. That refreshes the service.

However, sometimes it doesn’t need to migrate since there aren’t any new migrations. Another can be that the migrations already ran outside of the installer. I think the latter may now be happening.

We have this postinst script in deb packaging:

This means we run db:migrate as part of apt upgrade.

The observant reader may notice that this is different from RPM where we don’t do this but do restart:

So I think that this part may not restart the service or restart it at the wrong time:

I would check if it does. You can probably check with journalctl -u foreman.service | grep Starting when it (re)started and match those timestamps to the log files (/var/log/foreman/db_migrate.log*) to reconstruct the timeline.

I am planning to test a solution to this with

However, when doing Debian automated builds I sorta broke PR builds for nightly packages. That I am trying to fix first via:

As that change will allow me to get scratch builds of the nightly Debian foreman package and test if the packaging change works or not for upgrades.

Testing it locally, the proposed fix at https://github.com/theforeman/foreman-packaging/pull/7216 solves the first problem of foreman not being restarted on update and new APIs missing.

@aruzicka after I solved ^ I see the following error related to dynflow (until we merge the packaging change I cannot confirm if our pipelines see the same issue) but I wanted to raise this to start discussion:

    2021-11-02 18:01:58 [NOTICE] [configure] 1250 configuration steps out of 1447 steps complete.
    2021-11-02 18:02:02 [ERROR ] [configure] Systemd start for dynflow-sidekiq@orchestrator failed!
    2021-11-02 18:02:02 [ERROR ] [configure] journalctl log for dynflow-sidekiq@orchestrator:
    2021-11-02 18:02:02 [ERROR ] [configure] -- Logs begin at Tue 2021-11-02 17:25:54 UTC, end at Tue 2021-11-02 18:02:02 UTC. --
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: E, [2021-11-02T17:57:43.759010 #17311] ERROR -- /parallel-executor-core: unexpected character () at line 1, column 1 [parse.c:704] (MultiJson::ParseError)
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/multi_json-1.15.0/lib/multi_json/adapters/oj.rb:34:in `load'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/multi_json-1.15.0/lib/multi_json/adapter.rb:21:in `load'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/multi_json-1.15.0/lib/multi_json.rb:122:in `load'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/persistence_adapters/sequel.rb:362:in `load_data'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/persistence_adapters/sequel.rb:243:in `block in find_coordinator_records'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/persistence_adapters/sequel.rb:243:in `map'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/persistence_adapters/sequel.rb:243:in `find_coordinator_records'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/coordinator_adapters/sequel.rb:30:in `find_records'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/coordinator.rb:366:in `find_records'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/executors/abstract/core.rb:80:in `heartbeat'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/executors/sidekiq/core.rb:36:in `heartbeat'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: [ concurrent-ruby ]
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/executors/abstract/core.rb:113:in `on_message'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: [ concurrent-ruby ]
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:35 pipe-up-foreman-nightly-debian10 systemd[1]: Stopping Foreman jobs daemon - orchestrator on sidekiq...
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:36 pipe-up-foreman-nightly-debian10 systemd[1]: dynflow-sidekiq@orchestrator.service: Succeeded.
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:36 pipe-up-foreman-nightly-debian10 systemd[1]: Stopped Foreman jobs daemon - orchestrator on sidekiq.
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:36 pipe-up-foreman-nightly-debian10 systemd[1]: Starting Foreman jobs daemon - orchestrator on sidekiq...
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:37 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: 2021-11-02T17:58:37.337Z 22253 TID-gsg2iuc7x INFO: GitLab reliable fetch activated!
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:37 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: 2021-11-02T17:58:37.346Z 22253 TID-gsg2s1z6p INFO: Booting Sidekiq 5.2.9 with redis options {:id=>"Sidekiq-server-PID-22253", :url=>"redis://localhost:6379/0"}
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:40 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/foreman_puppet-2.0.0.alpha.2/lib/foreman_puppet/register.rb:120: warning: already initialized constant Foreman::Plugin::RbacSupport::AUTO_EXTENDED_ROLES
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:40 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/app/registries/foreman/plugin/rbac_support.rb:5: warning: previous definition of AUTO_EXTENDED_ROLES was here
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: 271 extra bytes after the deserialized object
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/msgpack-1.3.3/lib/msgpack.rb:37:in `full_unpack'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/msgpack-1.3.3/lib/msgpack.rb:37:in `load'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/persistence_adapters/sequel.rb:390:in `load_data'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/persistence_adapters/sequel.rb:260:in `block in find_coordinator_records'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/persistence_adapters/sequel.rb:260:in `map'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/persistence_adapters/sequel.rb:260:in `find_coordinator_records'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/coordinator_adapters/sequel.rb:30:in `find_records'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/coordinator.rb:366:in `find_records'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/coordinator.rb:372:in `find_worlds'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/world/invalidation.rb:131:in `worlds_validity_check'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/world/invalidation.rb:118:in `perform_validity_checks'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/rails.rb:46:in `block in initialize!'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/rails.rb:38:in `tap'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/rails.rb:38:in `initialize!'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/extras/dynflow-sidekiq.rb:34:in `<top (required)>'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/cli.rb:292:in `require'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/cli.rb:292:in `boot_system'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/cli.rb:46:in `run'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/bin/sidekiq:12:in `<top (required)>'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/bin/sidekiq:23:in `load'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/bin/sidekiq:23:in `<main>'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 systemd[1]: dynflow-sidekiq@orchestrator.service: Main process exited, code=exited, status=1/FAILURE
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 systemd[1]: dynflow-sidekiq@orchestrator.service: Failed with result 'exit-code'.
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 systemd[1]: Failed to start Foreman jobs daemon - orchestrator on sidekiq.
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:51 pipe-up-foreman-nightly-debian10 systemd[1]: dynflow-sidekiq@orchestrator.service: Service RestartSec=1s expired, scheduling restart.
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:51 pipe-up-foreman-nightly-debian10 systemd[1]: dynflow-sidekiq@orchestrator.service: Scheduled restart job, restart counter is at 1.
    2021-11-02 18:02:02 [ERROR ] [configure] /Stage[main]/Foreman::Service/Foreman::Dynflow::Worker[orchestrator]/Service[dynflow-sidekiq@orchestrator]/ensure: change from 'stopped' to 'running' failed: Systemd start for dynflow-sidekiq@orchestrator failed!
    2021-11-02 18:02:02 [ERROR ] [configure] journalctl log for dynflow-sidekiq@orchestrator:
    2021-11-02 18:02:02 [ERROR ] [configure] -- Logs begin at Tue 2021-11-02 17:25:54 UTC, end at Tue 2021-11-02 18:02:02 UTC. --
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: E, [2021-11-02T17:57:43.759010 #17311] ERROR -- /parallel-executor-core: unexpected character () at line 1, column 1 [parse.c:704] (MultiJson::ParseError)
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/multi_json-1.15.0/lib/multi_json/adapters/oj.rb:34:in `load'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/multi_json-1.15.0/lib/multi_json/adapter.rb:21:in `load'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/multi_json-1.15.0/lib/multi_json.rb:122:in `load'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/persistence_adapters/sequel.rb:362:in `load_data'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/persistence_adapters/sequel.rb:243:in `block in find_coordinator_records'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/persistence_adapters/sequel.rb:243:in `map'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/persistence_adapters/sequel.rb:243:in `find_coordinator_records'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/coordinator_adapters/sequel.rb:30:in `find_records'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/coordinator.rb:366:in `find_records'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/executors/abstract/core.rb:80:in `heartbeat'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/executors/sidekiq/core.rb:36:in `heartbeat'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: [ concurrent-ruby ]
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.5.0/lib/dynflow/executors/abstract/core.rb:113:in `on_message'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:57:43 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[17311]: [ concurrent-ruby ]
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:35 pipe-up-foreman-nightly-debian10 systemd[1]: Stopping Foreman jobs daemon - orchestrator on sidekiq...
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:36 pipe-up-foreman-nightly-debian10 systemd[1]: dynflow-sidekiq@orchestrator.service: Succeeded.
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:36 pipe-up-foreman-nightly-debian10 systemd[1]: Stopped Foreman jobs daemon - orchestrator on sidekiq.
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:36 pipe-up-foreman-nightly-debian10 systemd[1]: Starting Foreman jobs daemon - orchestrator on sidekiq...
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:37 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: 2021-11-02T17:58:37.337Z 22253 TID-gsg2iuc7x INFO: GitLab reliable fetch activated!
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:37 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: 2021-11-02T17:58:37.346Z 22253 TID-gsg2s1z6p INFO: Booting Sidekiq 5.2.9 with redis options {:id=>"Sidekiq-server-PID-22253", :url=>"redis://localhost:6379/0"}
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:40 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/foreman_puppet-2.0.0.alpha.2/lib/foreman_puppet/register.rb:120: warning: already initialized constant Foreman::Plugin::RbacSupport::AUTO_EXTENDED_ROLES
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:40 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/app/registries/foreman/plugin/rbac_support.rb:5: warning: previous definition of AUTO_EXTENDED_ROLES was here
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: 271 extra bytes after the deserialized object
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/msgpack-1.3.3/lib/msgpack.rb:37:in `full_unpack'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/msgpack-1.3.3/lib/msgpack.rb:37:in `load'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/persistence_adapters/sequel.rb:390:in `load_data'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/persistence_adapters/sequel.rb:260:in `block in find_coordinator_records'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/persistence_adapters/sequel.rb:260:in `map'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/persistence_adapters/sequel.rb:260:in `find_coordinator_records'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/coordinator_adapters/sequel.rb:30:in `find_records'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/coordinator.rb:366:in `find_records'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/coordinator.rb:372:in `find_worlds'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/world/invalidation.rb:131:in `worlds_validity_check'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/world/invalidation.rb:118:in `perform_validity_checks'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/rails.rb:46:in `block in initialize!'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/rails.rb:38:in `tap'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.6.1/lib/dynflow/rails.rb:38:in `initialize!'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/extras/dynflow-sidekiq.rb:34:in `<top (required)>'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/cli.rb:292:in `require'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/cli.rb:292:in `boot_system'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/cli.rb:46:in `run'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/bin/sidekiq:12:in `<top (required)>'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/bin/sidekiq:23:in `load'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 dynflow-sidekiq@orchestrator[22253]: /usr/share/foreman/vendor/ruby/2.5.0/bin/sidekiq:23:in `<main>'
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 systemd[1]: dynflow-sidekiq@orchestrator.service: Main process exited, code=exited, status=1/FAILURE
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 systemd[1]: dynflow-sidekiq@orchestrator.service: Failed with result 'exit-code'.
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:50 pipe-up-foreman-nightly-debian10 systemd[1]: Failed to start Foreman jobs daemon - orchestrator on sidekiq.
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:51 pipe-up-foreman-nightly-debian10 systemd[1]: dynflow-sidekiq@orchestrator.service: Service RestartSec=1s expired, scheduling restart.
    2021-11-02 18:02:02 [ERROR ] [configure] Nov 02 17:58:51 pipe-up-foreman-nightly-debian10 systemd[1]: dynflow-sidekiq@orchestrator.service: Scheduled restart job, restart counter is at 1.

That looks like a twist on Foreman-nightly-rpm-pipeline 1222 failed - #6 by aruzicka . In the excerpt from the logs we can see two different version of dynflow 1.5.0 and 1.6.1 accessing the same db which would explain why the older version cannot read certain data.

Ahh, so the reason we see it as by adding the restart after upgrade for dynflow as well (https://github.com/theforeman/foreman-packaging/pull/7216/files#diff-31259e983b99c066c7accde927c0f32e398fdad0353b4f9ea0bbf79e603bce9fR52-R53) this brings this problem into reality for Debian upgrades? The change introduced makes it consistent with RPM environment, and you solved it for RPM so its interesting we still see it here.

So I’m still trying to dig deeper into this, but one thing that I noticed, and I found rather interesting:

We’re using a template service for dynflow (dynflow-sidekiq@), which we then instantiate for the orchestrator and the worker(s).

Our RPM %postun script contains: systemctl try-restart dynflow-sidekiq@.service, but this is actually not possible:

# systemctl try-restart dynflow-sidekiq@.service
Failed to try-restart dynflow-sidekiq@.service: Unit name dynflow-sidekiq@.service is missing the instance name.
See system logs and 'systemctl status dynflow-sidekiq@.service' for details. 

Our DEB postinst scripts don’t contain anything like that, because dh_systemd detects that we’re asking it to do silly things, and ignores us.

So before Adams PartOf change, nothing in packaging restarted dynflow, and we were maybe just lucky all the time (or the installer helped a bit, idk).

This doesn’t explain not a bit of the current behaviour we see on Debian, but I still hope you’re enjoying the coffee on you keyboard.

Should the %postun have systemctl try-restart dynflow-sidekiq@\*.service instead? If anything at all?

A clear maybe :wink:

And the winner is: running db:migrate in postinst of foreman.deb – removing that (thus aligning to what we do in RPM) and the upgrade seems to pass for me.

1 Like

a similar change will need to be done to all plugins, as plugins also call db:migrate and can result in “funny” things.

Yepp, the plugins definitely need to drop that db:migrate, as otherwise we end up in the situation where the installer doesn’t detect the upgrade properly (there are no migrations to run), and doesn’t restart foreman.service once more, resulting in:

[ ERROR ] [configure] /Stage[main]/Foreman::Register/Foreman_host[foreman-pipe-up-foreman-nightly-debian10.n41.example.com]: Could not evaluate: Error making GET request to Foreman at https://pipe-up-foreman-nightly-debian10.n41.example.com/api/v2/hosts: Response: 503 Service Unavailable: The webserver was unable to reach the backend service. Is Foreman running at pipe-up-foreman-nightly-debian10.n41.example.com?

(Eric, Ewoud, remember me asking “who should kick puma?”, here it is again)

Anyways, dropping it from foreman-puppet in https://github.com/theforeman/foreman-packaging/pull/7225

And tackling it on a broader “all the plugins” scheme in https://github.com/theforeman/foreman-packaging/pull/7226

Great, Debian nightlies are green. Now to clean up all the other plugins, so actual user deployments also work as intended.

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