Remote execution don't work

Support
1

Problem: Jobs are not executed

Expected outcome: Jobs are running on remote site

Foreman and Proxy versions: Foreman 3.1.0

Foreman and Proxy plugin versions: foreman, forman_cli, foreman_cli_puppet, foreman_proxy, foreman_plugin_ansible, foreman_plugin_puppet, foreman_plugin_puppetdb, foreman_plugin_remote_execution, foreman_compute_vmware, foreman_proxy_plugin_ansible, foreman_proxy_plugin_dynflow, foreman_proxy_plugin_remote_execution_ssh

Distribution and version: Debian 10

Other relevant data:
If i try to execute a job remote on a node follwoing error message is displayed:

 1:
Initialization error: RestClient::NotFound - 404 Not Found
   2:
Initialization error: RestClient::NotFound - 404 Not Found
   3:
Initialization error: RestClient::NotFound - 404 Not Found
   4:
Initialization error: RestClient::NotFound - 404 Not FoundError loading data from proxy: NoMethodError - undefined method `code' for "404 Not Found":String
   5:
Did you mean?  encode

The proxy log contains the following:

2022-01-20T13:46:57  [D] Executor heartbeat
2022-01-20T13:46:59  [D] accept: 10.0.2.15:48594
2022-01-20T13:46:59  [D] Rack::Handler::WEBrick is invoked.
2022-01-20T13:47:05 9d64b471 [I] Started GET /dynflow/tasks/count state=running
2022-01-20T13:47:05 9d64b471 [D] verifying remote client 10.0.2.15 against trusted_hosts ["foreman.domain.local", "10.0.2.15"]
2022-01-20T13:47:05 9d64b471 [I] Finished GET /dynflow/tasks/count with 200 (34.56 ms)
2022-01-20T13:47:05  [D] close: 10.0.2.15:48594
2022-01-20T13:47:06  [D] accept: 10.0.2.15:48596
2022-01-20T13:47:06  [D] Rack::Handler::WEBrick is invoked.
2022-01-20T13:47:06 9d64b471 [I] Started POST /dynflow/tasks/launch 
2022-01-20T13:47:06 9d64b471 [D] verifying remote client 10.0.2.15 against trusted_hosts ["foreman.domain.local", "10.0.2.15"]
2022-01-20T13:47:06 9d64b471 [W] Error processing request '9d64b471-22c0-469a-b69c-d65434b8d753: <**Dynflow::Errors::PersistenceError>: caused by Sequel::DatabaseError: SQLite3::SQLException: no such table: main.dynflow_execution_plans_backup0
/usr/lib/ruby/vendor_ruby/sqlite3/database.rb:91:in `initialize'
/usr/lib/ruby/vendor_ruby/sqlite3/database.rb:91:in `new'
/usr/lib/ruby/vendor_ruby/sqlite3/database.rb:91:in `prepare'
/usr/lib/ruby/vendor_ruby/sqlite3/database.rb:137:in `execute'
/usr/lib/ruby/vendor_ruby/sequel/adapters/sqlite.rb:189:in `block (2 levels) in _execute'
/usr/lib/ruby/vendor_ruby/sequel/database/logging.rb:38:in `log_connection_yield'
/usr/lib/ruby/vendor_ruby/sequel/adapters/sqlite.rb:189:in `block in _execute'
/usr/lib/ruby/vendor_ruby/sequel/connection_pool/threaded.rb:92:in `hold'
/usr/lib/ruby/vendor_ruby/sequel/database/connecting.rb:270:in `synchronize'
/usr/lib/ruby/vendor_ruby/sequel/adapters/sqlite.rb:180:in `_execute'
/usr/lib/ruby/vendor_ruby/sequel/adapters/sqlite.rb:146:in `execute_insert'
/usr/lib/ruby/vendor_ruby/sequel/dataset/actions.rb:1099:in `execute_insert'
/usr/lib/ruby/vendor_ruby/sequel/dataset/actions.rb:399:in `insert'
/usr/lib/ruby/vendor_ruby/dynflow/persistence_adapters/sequel.rb:341:in `block in save'
/usr/lib/ruby/vendor_ruby/dynflow/persistence_adapters/sequel.rb:490:in `with_retry'
/usr/lib/ruby/vendor_ruby/dynflow/persistence_adapters/sequel.rb:341:in `save'
/usr/lib/ruby/vendor_ruby/dynflow/persistence_adapters/sequel.rb:178:in `save_action'
/usr/lib/ruby/vendor_ruby/dynflow/persistence.rb:46:in `save_action'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan/steps/plan_step.rb:108:in `initialize_action'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan.rb:405:in `block in add_plan_step'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan.rb:400:in `tap'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan.rb:400:in `add_plan_step'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan.rb:279:in `prepare'
/usr/lib/ruby/vendor_ruby/dynflow/world.rb:218:in `block (2 levels) in plan_with_options'
/usr/lib/ruby/vendor_ruby/dynflow/coordinator.rb:326:in `acquire'
/usr/lib/ruby/vendor_ruby/dynflow/world.rb:217:in `block in plan_with_options'
/usr/lib/ruby/vendor_ruby/dynflow/world.rb:216:in `tap'
/usr/lib/ruby/vendor_ruby/dynflow/world.rb:216:in `plan_with_options'
/usr/lib/ruby/vendor_ruby/smart_proxy_dynflow/task_launcher/abstract.rb:39:in `block in trigger'
/usr/lib/ruby/vendor_ruby/dynflow/world.rb:178:in `trigger'
/usr/lib/ruby/vendor_ruby/smart_proxy_dynflow/task_launcher/abstract.rb:38:in `trigger'
/usr/lib/ruby/vendor_ruby/smart_proxy_dynflow/task_launcher/batch.rb:5:in `launch!'
/usr/lib/ruby/vendor_ruby/smart_proxy_dynflow/api.rb:40:in `block in <class:Api>'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1635:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1635:in `block in compile!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:992:in `block (3 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1011:in `route_eval'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:992:in `block (2 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1040:in `block in process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1038:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1038:in `process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:990:in `block in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:989:in `each'/usr/lib/ruby/vendor_ruby/sinatra/base.rb:989:in `route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1097:in `block in dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1076:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1076:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1076:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1094:in `dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:924:in `block in call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1076:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1076:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1076:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:924:in `call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:913:in `call'
/usr/share/foreman-proxy/lib/proxy/log.rb:105:in `call'
/usr/share/foreman-proxy/lib/proxy/request_id_middleware.rb:11:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/xss_header.rb:18:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/path_traversal.rb:16:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/json_csrf.rb:26:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/base.rb:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/base.rb:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/frame_options.rb:31:in `call'
/usr/lib/ruby/vendor_ruby/rack/null_logger.rb:9:in `call'
/usr/lib/ruby/vendor_ruby/rack/head.rb:12:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/show_exceptions.rb:22:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:194:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1957:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1502:in `block in call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1729:in `synchronize'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1502:in `call'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:68:in `block in call'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:53:in `each'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:53:in `call'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:68:in `block in call'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:53:in `each'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:53:in `call'
/usr/lib/ruby/vendor_ruby/rack/builder.rb:153:in `call'
/usr/lib/ruby/vendor_ruby/rack/handler/webrick.rb:86:in `service'
/usr/lib/ruby/2.5.0/webrick/httpserver.rb:140:in `service'
/usr/lib/ruby/2.5.0/webrick/httpserver.rb:96:in `run'
/usr/lib/ruby/2.5.0/webrick/server.rb:307:in `block in start_thread'
/usr/lib/ruby/vendor_ruby/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2022-01-20T13:47:06 9d64b471 [I] Finished POST /dynflow/tasks/launch with 500 (46.41 ms)
2022-01-20T13:47:06 9d64b471 [D] close: 10.0.2.15:48596
2022-01-20T13:47:07  [D] accept: 10.0.2.15:48598
2022-01-20T13:47:07  [D] Rack::Handler::WEBrick is invoked.
2022-01-20T13:47:07 9d64b471 [I] Started GET /dynflow/tasks/status 
2022-01-20T13:47:07 9d64b471 [D] verifying remote client 10.0.2.15 against trusted_hosts ["foreman.domain.local", "10.0.2.15"]
2022-01-20T13:47:07 9d64b471 [I] Finished GET /dynflow/tasks/status with 404 (2.17 ms)
2022-01-20T13:47:07  [D] close: 10.0.2.15:48598

Anybody knows what is going wrong here?

Best Regards,
Klaus

1 Like
2

Same problem

3

If i create this missing table with the same schema as dynflow_execution_plans and run the job again the next error is a constraint violation:

2022-01-21T10:27:53 da85031b [D] verifying remote client 10.0.2.15 against trusted_hosts ["foreman.domain.local", "10.0.2.15"]
2022-01-21T10:27:53 da85031b [W] Error processing request 'da85031b-41dc-4843-95e5-7ddbc768e712: <Dynflow::Errors::PersistenceError>: caused by Sequel::ForeignKeyConstraintViolation: SQLite3::ConstraintException: FOREIGN KEY constraint failed
4

Looks like on buster it is completely busted.

It seems to work fine on ubuntu focal so not all deb-derivatives suffer from it. Possibly it is caused by some wrong interaction between third party libraries.

Focal has

ii  libsqlite3-0:amd64                    3.31.1-4ubuntu0.2                 amd64        SQLite 3 shared library
ii  ruby-sequel                           5.29.0-1                          all          Simple, flexible, and powerful SQL database access toolkit for Ruby
ii  ruby-sqlite3                          1.4.2-2build1                     amd64        SQLite3 interface for Ruby
ii  sqlite3                               3.31.1-4ubuntu0.2                 amd64        Command line interface for SQLite 3

Buster has

ii  libsqlite3-0:amd64                    3.27.2-3+deb10u1              amd64        SQLite 3 shared library
ii  ruby-sequel                           5.15.0-1                      all          Simple, flexible, and powerful SQL database access toolkit for Ruby
ii  ruby-sqlite3                          1.3.13-1+b2                   amd64        SQLite3 interface for Ruby
ii  sqlite3                               3.27.2-3+deb10u1              amd64        Command line interface for SQLite 3

If I pull in ruby-sequel from rubygems, it starts working. I’m not really sure how to address this, the way I did it was rather hacky. If I’m reading things right ruby-sequel comes from debian’s repos so we can’t really update it unless we start shipping an updated version in our repos. You could probably pull in ruby-sequel from bullseye, but then you’d be stepping into unsupported waters and ymmv.

2 Likes
5

@aruzicka: Thank you. This solved the problem. After installing ruby-sequel from bullseye it works like a charm

ii  ruby-sequel    5.41.0-1     all          Simple, flexible, and powerful SQL database access toolkit for Ruby

Best regards
Klaus

6

@kmeyer
i installed ruby-sequel 5.41.0-1 from bullseye too. But it is not helps me. (install & reboot)

What did you do yet for solution?

‘create this missing table with the same schema as dynflow_execution_plans’ - how?
can you share your SQLite3 database with structure only? (whitout data)

7

I have deleted the dynflow sqlite3 datebase. When restarting foreman-proxy a new database will be created.
Try:
apt-get purge ruby-sequel
Then some other dependencies will also be purged. After that reinstall the deleted packages and finally install ruby-sequel from bullseye.

8 
rm /var/lib/foreman-proxy/dynflow/dynflow.sqlite
systemctl restart foreman-proxy

works for me! thanks!

9

Hello

i have the same problem (same error), but on CentOS7 distribution, with 2 locations(Backend ans Middleware) and a foreman-proxy for each location.
Job ran successfully on hosts in Backend and failed on hosts in Middleware location if ran against mixed locations (Backend and Middleware)
Doesn’t mater if i’ve dynflow.sqlite or not(dynflow.yml has empty value of :database: )

But if i run a job only on the hosts of Middlware location - it finished successfully

proxy.log on error:
2022-01-27T09:28:48 [D] Rack::Handler::WEBrick is invoked.
2022-01-27T09:28:48 49c831df [I] Started GET /dynflow/tasks/count state=running
2022-01-27T09:28:48 49c831df [D] verifying remote client foreman against trusted_hosts [“foreman”, “foreman-proxy-mdw”]
2022-01-27T09:28:48 49c831df [I] Finished GET /dynflow/tasks/count with 200 (1.03 ms)
2022-01-27T09:28:48 [D] close: foreman:55984
2022-01-27T09:28:49 [D] accept: foreman:56002
2022-01-27T09:28:49 [D] accept: foreman:56004
2022-01-27T09:28:49 [D] Rack::Handler::WEBrick is invoked.
2022-01-27T09:28:49 49c831df [I] Started GET /dynflow/tasks/status
2022-01-27T09:28:49 49c831df [D] verifying remote client foreman against trusted_hosts [“foreman”, “foreman-mdw”]
2022-01-27T09:28:49 49c831df [I] Finished GET /dynflow/tasks/status with 404 (0.52 ms)
2022-01-27T09:28:49 [D] Rack::Handler::WEBrick is invoked.
2022-01-27T09:28:49 49c831df [I] Started GET /dynflow/tasks/status
2022-01-27T09:28:49 49c831df [D] verifying remote client foreman against trusted_hosts [“foreman”, “foreman-mdw”]
2022-01-27T09:28:49 49c831df [I] Finished GET /dynflow/tasks/status with 404 (0.48 ms)
2022-01-27T09:28:49 [D] close: foreman:56002
2022-01-27T09:28:49 [D] close: foreman:56004

Any help would be appreciated.

tnx

10

This seems to be a completely different thing once we get deeper than “rex doesn’t work”. Could you open a new thread for it?