Hello all!
Since a colleague tried to install additional plugins, at least openscap, graphite and cockpit) and, as they didn’t work, tried to remove them, “my”[tm] katello/foreman stopped to work properly with “remote jobs”.
I assume there are some gems broken. Details about installed packages are below, installation has initially be done via foreman-installer.
These days we manage around 300 hosts with it, running since some months. We have always been able to update the releases without any problems.
A remote job via ssh fails and gives the message " 1: Failed to initialize: RuntimeError - The only applicable proxy foreman.domain is down"
I double checked the proxy is selected on all items necessary, subnets, locations, …
The problem can be broken down to dynflow* although both are running:
dynflowd.service loaded active running
smart_proxy_dynflow_core.service loaded active running
telnet to localhost:8008 works.
tcpdump on the target hosts doesn’t even show a connect while running a job, passwordless login via ssh from foreman to host works perfectly.
My hope has been the new update(s) could fix it, but …
DEBUG-logging is ON
#############
Versions:
foreman.domain Templates, Logs, BMC, Dynflow, Ansible, Discovery, Pulp, TFTP, Puppet CA, Puppet, HTTPBoot, and SSH : 1.23.0
foreman-tasks 0.16.1
foreman_ansible 3.0.5
foreman_bootdisk 15.1.0
foreman_column_view 0.4.0
foreman_discovery 15.1.0
foreman_docker 5.0.0
foreman_hooks 0.3.15
foreman_monitoring 1.0.1
foreman_remote_execution 1.8.2
foreman_templates 6.0.3
katello 3.13.0.rc2.1
puppetdb_foreman 5.0.0
#############
logs: smart_proxy_dynflow_core.log, proxy.log, production.log
The following log does not take any notice of the attempt of the remote job:
smart_proxy_dynflow_core.log:
tor heartbeatExecutor heartbeatExecutor heartbeatExecutor heartbeataccept: 127.0.0.1:53362SSL_accept returned=1 errno=0 state=SSLv2/v3 read client hello A: unknown protocol (OpenSSL::SSL::SSLError)
/opt/rh/rh-ruby25/root/usr/share/ruby/webrick/server.rb:299:in `accept'
/opt/rh/rh-ruby25/root/usr/share/ruby/webrick/server.rb:299:in `block (2 levels) in start_thread'
/opt/rh/rh-ruby25/root/usr/share/ruby/webrick/utils.rb:263:in `timeout'
/opt/rh/rh-ruby25/root/usr/share/ruby/webrick/server.rb:297:in `block in start_thread'close: 127.0.0.1:53362Executor heartbeatExecutor heartbeatExecutor heartbeatExecutor heartbeatExecutor heartbeatExecutor
The proxy.log is more verbose:
proxy.log:
2019-09-18T16:06:28 [D] accept: 172.25.12.55:34666
2019-09-18T16:06:28 [D] Rack::Handler::WEBrick is invoked.
2019-09-18T16:06:28 bf4b7df8 [I] Started GET /dynflow/tasks/count state=running
2019-09-18T16:06:28 bf4b7df8 [D] verifying remote client foreman.domain (based on SSL_CLIENT_CERT) against trusted_hosts ["foreman-domain"]
2019-09-18T16:06:28 bf4b7df8 [D] Proxy request from foreman-domain:9090/dynflow/tasks/count to https://foreman-domain:8008/tasks/count
2019-09-18T16:06:28 bf4b7df8 [W] Error processing request 'bf4b7df8-19a7-41ba-a7f9-be7235365bc6
Errno::ECONNREFUSED: Connection refused - connect(2)
/usr/share/ruby/net/http.rb:878:in `initialize'
/usr/share/ruby/net/http.rb:878:in `open'
/usr/share/ruby/net/http.rb:878:in `block in connect'
/usr/share/ruby/timeout.rb:52:in `timeout'
/usr/share/ruby/net/http.rb:877:in `connect'
/usr/share/ruby/net/http.rb:862:in `do_start'
/usr/share/ruby/net/http.rb:851:in `start'
/usr/share/ruby/net/http.rb:1373:in `request'
/usr/share/gems/gems/rest-client-1.6.7/lib/restclient/net_http_ext.rb:51:in `request'
/usr/share/foreman-proxy/lib/proxy/request.rb:49:in `send_request'
/usr/share/gems/gems/smart_proxy_dynflow-0.2.3/lib/smart_proxy_dynflow/callback.rb:23:in `relay'
/usr/share/gems/gems/smart_proxy_dynflow-0.2.3/lib/smart_proxy_dynflow/callback.rb:29:in `relay'
/usr/share/gems/gems/smart_proxy_dynflow-0.2.3/lib/smart_proxy_dynflow/helpers.rb:5:in `relay_request'
/usr/share/gems/gems/smart_proxy_dynflow-0.2.3/lib/smart_proxy_dynflow/api.rb:62:in `block in <class:Api>'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1611:in `call'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1611:in `block in compile!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:975:in `[]'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:975:in `block (3 levels) in route!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:994:in `route_eval'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:975:in `block (2 levels) in route!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1015:in `block in process_route'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1013:in `catch'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1013:in `process_route'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:973:in `block in route!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:972:in `each'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:972:in `route!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1085:in `block in dispatch!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `block in invoke'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `catch'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `invoke'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1082:in `dispatch!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:907:in `block in call!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `block in invoke'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `catch'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `invoke'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:907:in `call!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:895:in `call'
/usr/share/foreman-proxy/lib/proxy/log.rb:96:in `call'
/usr/share/foreman-proxy/lib/proxy/request_id_middleware.rb:11:in `call'
/usr/share/gems/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'
/usr/share/gems/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
/usr/share/gems/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'
/usr/share/gems/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/usr/share/gems/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/usr/share/gems/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
/usr/share/gems/gems/rack-1.6.4/lib/rack/nulllogger.rb:9:in `call'
/usr/share/gems/gems/rack-1.6.4/lib/rack/head.rb:13:in `call'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/show_exceptions.rb:25:in `call'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:182:in `call'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:2013:in `call'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1487:in `block in call'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1787:in `synchronize'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1487:in `call'
/usr/share/gems/gems/rack-1.6.4/lib/rack/urlmap.rb:66:in `block in call'
/usr/share/gems/gems/rack-1.6.4/lib/rack/urlmap.rb:50:in `each'
/usr/share/gems/gems/rack-1.6.4/lib/rack/urlmap.rb:50:in `call'
/usr/share/gems/gems/rack-1.6.4/lib/rack/urlmap.rb:66:in `block in call'
/usr/share/gems/gems/rack-1.6.4/lib/rack/urlmap.rb:50:in `each'
/usr/share/gems/gems/rack-1.6.4/lib/rack/urlmap.rb:50:in `call'
/usr/share/gems/gems/rack-1.6.4/lib/rack/builder.rb:153:in `call'
/usr/share/gems/gems/rack-1.6.4/lib/rack/handler/webrick.rb:88:in `service'
/usr/share/ruby/webrick/httpserver.rb:138:in `service'
/usr/share/ruby/webrick/httpserver.rb:94:in `run'
/usr/share/ruby/webrick/server.rb:295:in `block in start_thread'
/usr/share/gems/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `call'
/usr/share/gems/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2019-09-18T16:06:28 bf4b7df8 [I] Finished GET /dynflow/tasks/count with 500 (2.8 ms)
2019-09-18T16:06:28 bf4b7df8 [D] close: 172.25.12.55:34666
out of the job to production.log, with a “500 Internal Server Error”:
2019-09-18T16:19:54 [I|aud|9b48e74c] JobInvocation (218) create event on concurrency_level
2019-09-18T16:19:54 [I|aud|9b48e74c] JobInvocation (218) create event on time_span
2019-09-18T16:19:54 [I|aud|9b48e74c] JobInvocation (218) create event on execution_timeout_interval
2019-09-18T16:19:54 [I|aud|9b48e74c] JobInvocation (218) create event on password [redacted]
2019-09-18T16:19:54 [I|aud|9b48e74c] JobInvocation (218) create event on key_passphrase
2019-09-18T16:19:54 [I|aud|9b48e74c] JobInvocation (218) create event on remote_execution_feature_id
2019-09-18T16:19:54 [I|aud|9b48e74c] JobInvocation (218) create event on sudo_password
2019-09-18T16:19:54 [I|bac|9b48e74c] Task {label: Actions::RemoteExecution::RunHostsJob, id: b27b62e7-87a1-4073-a22e-2f7f82870281, execution_plan_id: 2caca4f7-e30b-45e5-b524-f78e48afeb42} state changed: planning
2019-09-18T16:19:54 [I|bac|] Task {label: Actions::RemoteExecution::RunHostsJob, id: b27b62e7-87a1-4073-a22e-2f7f82870281, execution_plan_id: 2caca4f7-e30b-45e5-b524-f78e48afeb42} state changed: planned
2019-09-18T16:19:54 [I|app|] Redirected to https://foreman-domain/job_invocations/218
2019-09-18T16:19:54 [I|app|] Completed 302 Found in 250ms (ActiveRecord: 47.3ms)
2019-09-18T16:19:54 [I|app|a2ae6511] Started GET "/job_invocations/218" for 192.168.111.102 at 2019-09-18 16:19:54 +0200
2019-09-18T16:19:54 [I|app|a2ae6511] Processing by JobInvocationsController#show as HTML
2019-09-18T16:19:54 [I|app|a2ae6511] Parameters: {"id"=>"218"}
2019-09-18T16:19:54 [I|app|a2ae6511] Rendering /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-1.8.2/app/views/job_invocations/show.html.erb within layouts/application
2019-09-18T16:19:54 [I|app|a2ae6511] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-1.8.2/app/views/job_invocations/_card_results.html.erb (0.2ms)
2019-09-18T16:19:54 [I|app|a2ae6511] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-1.8.2/app/views/job_invocations/_card_schedule.html.erb (1.7ms)
2019-09-18T16:19:54 [I|app|a2ae6511] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-1.8.2/app/views/job_invocations/_card_target_hosts.html.erb (2.0ms)
2019-09-18T16:19:54 [I|app|a2ae6511] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-1.8.2/app/views/job_invocations/_card_user_input.html.erb (2.1ms)
2019-09-18T16:19:54 [I|app|a2ae6511] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-1.8.2/app/views/job_invocations/_host_name_td.html.erb (0.4ms)
2019-09-18T16:19:54 [I|app|a2ae6511] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-1.8.2/app/views/job_invocations/_host_status_td.html.erb (0.3ms)
2019-09-18T16:19:54 [I|app|a2ae6511] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-1.8.2/app/views/job_invocations/_host_actions_td.html.erb (1.0ms)
2019-09-18T16:19:54 [I|app|a2ae6511] Rendered common/_pagination.html.erb (0.4ms)
2019-09-18T16:19:54 [I|app|a2ae6511] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-1.8.2/app/views/job_invocations/_tab_hosts.html.erb (6.2ms)
2019-09-18T16:19:54 [I|app|a2ae6511] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-1.8.2/app/views/job_invocations/_tab_overview.html.erb (20.0ms)
2019-09-18T16:19:54 [I|app|a2ae6511] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-1.8.2/app/views/job_invocations/_user_input.html.erb (10.1ms)
2019-09-18T16:19:54 [I|app|a2ae6511] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-1.8.2/app/views/job_invocations/_tab_preview_templates.html.erb (17.8ms)
2019-09-18T16:19:54 [I|app|a2ae6511] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-1.8.2/app/views/job_invocations/show.html.erb within layouts/application (55.8ms)
2019-09-18T16:19:54 [I|app|a2ae6511] Rendered layouts/_application_content.html.erb (0.3ms)
2019-09-18T16:19:54 [I|app|a2ae6511] Rendering layouts/base.html.erb
2019-09-18T16:19:54 [I|app|a2ae6511] Rendered layouts/base.html.erb (23.9ms)
2019-09-18T16:19:54 [I|app|a2ae6511] Completed 200 OK in 98ms (Views: 70.3ms | ActiveRecord: 14.5ms)
2019-09-18T16:19:14 [I|bac|] Task {label: Actions::RemoteExecution::RunHostsJob, id: 59588cb2-ef99-4b0c-9257-3f46fdade3c6, execution_plan_id: 7e0f9da3-9afe-4fc5-b5d8-927412bb944c} state changed: stopped result: warning
2019-09-18T16:19:14 [I|bac|] Task {label: Actions::RemoteExecution::RunHostsJob, id: 59588cb2-ef99-4b0c-9257-3f46fdade3c6, execution_plan_id: 7e0f9da3-9afe-4fc5-b5d8-927412bb944c} state changed: stopped result: warning
2019-09-18T16:19:54 [I|bac|] Task {label: Actions::RemoteExecution::RunHostsJob, id: b27b62e7-87a1-4073-a22e-2f7f82870281, execution_plan_id: 2caca4f7-e30b-45e5-b524-f78e48afeb42} state changed: running
2019-09-18T16:19:54 [I|bac|] Task {label: Actions::RemoteExecution::RunHostJob, id: 0dbf11ae-76ab-460a-8ab5-2fc693d6f97f, execution_plan_id: bdfed444-02d7-4b20-a956-6fbde186cd46} state changed: planning
2019-09-18T16:19:54 [W|app|] Could not fetch task counts from foreman-domain, skipped.
RestClient::InternalServerError: 500 Internal Server Error
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/abstract_response.rb:223:in `exception_with_response'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/abstract_response.rb:103:in `return!'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/request.rb:809:in `process_result'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/request.rb:725:in `block in transmit'
/opt/rh/rh-ruby25/root/usr/share/ruby/net/http.rb:910:in `start'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/request.rb:715:in `transmit'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/request.rb:145:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/request.rb:52:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/resource.rb:51:in `get'
/usr/share/foreman/lib/proxy_api/resource.rb:73:in `block (2 levels) in get'
/usr/share/foreman/app/services/foreman/telemetry_helper.rb:27:in `telemetry_duration_histogram'
/usr/share/foreman/lib/proxy_api/resource.rb:70:in `block in get'
/usr/share/foreman/lib/proxy_api/resource.rb:113:in `with_logger'
/usr/share/foreman/lib/proxy_api/resource.rb:69:in `get'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.16.1/app/lib/proxy_api/foreman_dynflow/dynflow_proxy.rb:35:in `tasks_count'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.16.1/app/services/foreman_tasks/proxy_selector.rb:48:in `block in get_counts'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.16.1/app/services/foreman_tasks/proxy_selector.rb:45:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.16.1/app/services/foreman_tasks/proxy_selector.rb:45:in `each_with_object'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.16.1/app/services/foreman_tasks/proxy_selector.rb:45:in `get_counts'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.16.1/app/services/foreman_tasks/proxy_selector.rb:35:in `select_by_jobs_count'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.16.1/app/services/foreman_tasks/proxy_selector.rb:25:in `block in determine_proxy'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.16.1/app/services/foreman_tasks/proxy_selector.rb:23:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.16.1/app/services/foreman_tasks/proxy_selector.rb:23:in `determine_proxy'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-1.8.2/app/lib/actions/remote_execution/run_host_job.rb:156:in `determine_proxy!'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution-1.8.2/app/lib/actions/remote_execution/run_host_job.rb:33:in `plan'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/action.rb:492:in `block (3 levels) in execute_plan'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/middleware/stack.rb:26:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/middleware.rb:18:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/middleware.rb:35:in `plan'
For any hint many thanks in advance!
horst
