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