Project

General

Profile

Bug #35214 ยป foreman-proxy.log

Lars Wagner, 07/14/2022 05:30 AM

 
2022-07-14T07:26:06 [D] Executor heartbeat
2022-07-14T07:26:21 [D] Executor heartbeat
2022-07-14T07:26:25 [D] accept: 10.2.0.104:41166
2022-07-14T07:26:25 [D] Rack::Handler::WEBrick is invoked.
2022-07-14T07:26:25 875e29b8 [I] Started GET /dynflow/tasks/count state=running
2022-07-14T07:26:25 875e29b8 [D] verifying remote client 10.2.0.104 against trusted_hosts ["foreman.internal", "foreman-proxy.internal"]
2022-07-14T07:26:25 875e29b8 [I] Finished GET /dynflow/tasks/count with 200 (7.12 ms)
2022-07-14T07:26:25 [D] close: 10.2.0.104:41166
2022-07-14T07:26:25 [D] accept: 10.2.0.104:41172
2022-07-14T07:26:25 [D] Rack::Handler::WEBrick is invoked.
2022-07-14T07:26:25 875e29b8 [I] Started POST /dynflow/tasks/launch
2022-07-14T07:26:25 875e29b8 [D] verifying remote client 10.2.0.104 against trusted_hosts ["foreman.internal", "foreman-proxy.internal"]
2022-07-14T07:26:25 875e29b8 [D] ExecutionPlan 0465361f-cabc-4cdf-8d15-b9309252aadf pending >> planning
2022-07-14T07:26:25 875e29b8 [D] Step 0465361f-cabc-4cdf-8d15-b9309252aadf: 1 pending >> running in phase Plan Proxy::Dynflow::Action::Batch
2022-07-14T07:26:25 875e29b8 [D] Step 0465361f-cabc-4cdf-8d15-b9309252aadf: 1 running >> success in phase Plan Proxy::Dynflow::Action::Batch
2022-07-14T07:26:25 875e29b8 [D] ExecutionPlan 0465361f-cabc-4cdf-8d15-b9309252aadf planning >> planned
2022-07-14T07:26:25 [D] ExecutionPlan 0465361f-cabc-4cdf-8d15-b9309252aadf planned >> running
2022-07-14T07:26:25 875e29b8 [I] Finished POST /dynflow/tasks/launch with 200 (16.33 ms)
2022-07-14T07:26:25 [D] Step 0465361f-cabc-4cdf-8d15-b9309252aadf: 2 pending >> running in phase Run Proxy::Dynflow::Action::Batch
2022-07-14T07:26:25 875e29b8 [D] ExecutionPlan 3ae6dd3b-69ab-48da-b66d-035f2a4baa63 pending >> planning
2022-07-14T07:26:25 875e29b8 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 1 pending >> running in phase Plan Proxy::Salt::SaltTaskLauncher::SaltRunnerAction
2022-07-14T07:26:25 875e29b8 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 4 pending >> running in phase Plan Proxy::Dynflow::Callback::Action
2022-07-14T07:26:25 875e29b8 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 4 running >> success in phase Plan Proxy::Dynflow::Callback::Action
2022-07-14T07:26:25 [D] close: 10.2.0.104:41172
2022-07-14T07:26:25 875e29b8 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 1 running >> success in phase Plan Proxy::Salt::SaltTaskLauncher::SaltRunnerAction
2022-07-14T07:26:25 875e29b8 [D] ExecutionPlan 3ae6dd3b-69ab-48da-b66d-035f2a4baa63 planning >> planned
2022-07-14T07:26:25 875e29b8 [D] Step 0465361f-cabc-4cdf-8d15-b9309252aadf: 2 running >> suspended in phase Run Proxy::Dynflow::Action::Batch
2022-07-14T07:26:25 [D] ExecutionPlan 3ae6dd3b-69ab-48da-b66d-035f2a4baa63 planned >> running
2022-07-14T07:26:25 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 2 pending >> running in phase Run Proxy::Salt::SaltTaskLauncher::SaltRunnerAction
2022-07-14T07:26:25 875e29b8 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 2 running >> suspended in phase Run Proxy::Salt::SaltTaskLauncher::SaltRunnerAction
2022-07-14T07:26:25 [D] start runner 3d0f7dfc-79d7-47f4-9749-453a5fa89590
2022-07-14T07:26:25 [D] Running command 'salt --show-jid --saltfile=/etc/foreman-proxy/settings.d/salt.saltfile myserver.internal state.template_str state.highstate:
module.run:
- state.highstate:'
2022-07-14T07:26:25 [D] refresh runner 3d0f7dfc-79d7-47f4-9749-453a5fa89590
2022-07-14T07:26:25 [D] refreshing runner
2022-07-14T07:26:25 [D] planning to refresh 3d0f7dfc-79d7-47f4-9749-453a5fa89590
2022-07-14T07:26:26 [D] Ticker ticking for 1 events
2022-07-14T07:26:26 [D] refresh runner 3d0f7dfc-79d7-47f4-9749-453a5fa89590
2022-07-14T07:26:26 [D] refreshing runner
2022-07-14T07:26:26 [D] planning to refresh 3d0f7dfc-79d7-47f4-9749-453a5fa89590
2022-07-14T07:26:26 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 2 got event #<Proxy::Dynflow::Runner::Update:0x0000562b2fe279c0>
2022-07-14T07:26:26 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 2 suspended >> running in phase Run Proxy::Salt::SaltTaskLauncher::SaltRunnerAction
2022-07-14T07:26:26 875e29b8 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 2 running >> suspended in phase Run Proxy::Salt::SaltTaskLauncher::SaltRunnerAction
2022-07-14T07:26:27 [D] Ticker ticking for 1 events
2022-07-14T07:26:27 [D] refresh runner 3d0f7dfc-79d7-47f4-9749-453a5fa89590
2022-07-14T07:26:27 [D] refreshing runner
2022-07-14T07:26:27 [D] planning to refresh 3d0f7dfc-79d7-47f4-9749-453a5fa89590
2022-07-14T07:26:27 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 2 got event #<Proxy::Dynflow::Runner::Update:0x0000562b2fd385a0>
2022-07-14T07:26:27 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 2 suspended >> running in phase Run Proxy::Salt::SaltTaskLauncher::SaltRunnerAction
2022-07-14T07:26:27 875e29b8 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 2 running >> suspended in phase Run Proxy::Salt::SaltTaskLauncher::SaltRunnerAction
2022-07-14T07:26:28 [D] Ticker ticking for 1 events
2022-07-14T07:26:28 [D] refresh runner 3d0f7dfc-79d7-47f4-9749-453a5fa89590
2022-07-14T07:26:28 [D] refreshing runner
2022-07-14T07:26:28 [D] finish runner 3d0f7dfc-79d7-47f4-9749-453a5fa89590
2022-07-14T07:26:28 [D] closing session for command [3d0f7dfc-79d7-47f4-9749-453a5fa89590],0 actors left
2022-07-14T07:26:28 [D] terminate 3d0f7dfc-79d7-47f4-9749-453a5fa89590
2022-07-14T07:26:28 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 2 got event #<Proxy::Dynflow::Runner::Update:0x0000562b2f849328>
2022-07-14T07:26:28 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 2 suspended >> running in phase Run Proxy::Salt::SaltTaskLauncher::SaltRunnerAction
2022-07-14T07:26:28 875e29b8 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 2 running >> success in phase Run Proxy::Salt::SaltTaskLauncher::SaltRunnerAction
2022-07-14T07:26:28 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 5 pending >> running in phase Run Proxy::Dynflow::Callback::Action
2022-07-14T07:26:29 875e29b8 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 5 running >> success in phase Run Proxy::Dynflow::Callback::Action
2022-07-14T07:26:29 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 3 pending >> running in phase Finalize Proxy::Salt::SaltTaskLauncher::SaltRunnerAction
2022-07-14T07:26:29 875e29b8 [E] Script execution failed
2022-07-14T07:26:29 875e29b8 [D] Step 3ae6dd3b-69ab-48da-b66d-035f2a4baa63: 3 running >> error in phase Finalize Proxy::Salt::SaltTaskLauncher::SaltRunnerAction
2022-07-14T07:26:29 [D] ExecutionPlan 3ae6dd3b-69ab-48da-b66d-035f2a4baa63 running >> stopped
2022-07-14T07:26:30 [D] accept: 10.2.0.104:41364
2022-07-14T07:26:30 [D] Rack::Handler::WEBrick is invoked.
2022-07-14T07:26:30 cc99582f [I] Started HEAD /
2022-07-14T07:26:30 cc99582f [I] Finished HEAD / with 404 (0.39 ms)
2022-07-14T07:26:35 [D] Step 0465361f-cabc-4cdf-8d15-b9309252aadf: 2 got event Dynflow::Action::WithPollingSubPlans::Poll
2022-07-14T07:26:35 [D] Step 0465361f-cabc-4cdf-8d15-b9309252aadf: 2 suspended >> running in phase Run Proxy::Dynflow::Action::Batch
2022-07-14T07:26:35 875e29b8 [E] <RuntimeError> A sub task failed
/usr/lib/ruby/vendor_ruby/dynflow/action/with_sub_plans.rb:231:in `check_for_errors!'
/usr/lib/ruby/vendor_ruby/dynflow/action/with_sub_plans.rb:137:in `try_to_finish'
/usr/lib/ruby/vendor_ruby/dynflow/action/with_polling_sub_plans.rb:19:in `poll'
/usr/lib/ruby/vendor_ruby/dynflow/action/with_polling_sub_plans.rb:11:in `run'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:582:in `block (3 levels) in execute_run'
/usr/lib/ruby/vendor_ruby/dynflow/middleware/stack.rb:27:in `pass'
/usr/lib/ruby/vendor_ruby/dynflow/middleware.rb:19:in `pass'
/usr/lib/ruby/vendor_ruby/dynflow/action/progress.rb:31:in `with_progress_calculation'
/usr/lib/ruby/vendor_ruby/dynflow/action/progress.rb:17:in `run'
/usr/lib/ruby/vendor_ruby/dynflow/middleware/stack.rb:23:in `call'
/usr/lib/ruby/vendor_ruby/dynflow/middleware/stack.rb:27:in `pass'
/usr/lib/ruby/vendor_ruby/dynflow/middleware.rb:19:in `pass'
/usr/lib/ruby/vendor_ruby/smart_proxy_dynflow/middleware/keep_current_request_id.rb:15:in `block in run'
/usr/lib/ruby/vendor_ruby/smart_proxy_dynflow/middleware/keep_current_request_id.rb:49:in `restore_current_request_id'
/usr/lib/ruby/vendor_ruby/smart_proxy_dynflow/middleware/keep_current_request_id.rb:15:in `run'
/usr/lib/ruby/vendor_ruby/dynflow/middleware/stack.rb:23:in `call'
/usr/lib/ruby/vendor_ruby/dynflow/middleware/stack.rb:27:in `pass'
/usr/lib/ruby/vendor_ruby/dynflow/middleware.rb:19:in `pass'
/usr/lib/ruby/vendor_ruby/dynflow/middleware.rb:32:in `run'
/usr/lib/ruby/vendor_ruby/dynflow/middleware/stack.rb:23:in `call'
/usr/lib/ruby/vendor_ruby/dynflow/middleware/world.rb:31:in `execute'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:581:in `block (2 levels) in execute_run'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:580:in `catch'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:580:in `block in execute_run'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:483:in `block in with_error_handling'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:483:in `catch'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:483:in `with_error_handling'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:575:in `execute_run'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:296:in `execute'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan/steps/abstract_flow_step.rb:18:in `block (2 levels) in execute'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan/steps/abstract.rb:167:in `with_meta_calculation'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan/steps/abstract_flow_step.rb:17:in `block in execute'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan/steps/abstract_flow_step.rb:32:in `open_action'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan/steps/abstract_flow_step.rb:16:in `execute'
/usr/lib/ruby/vendor_ruby/dynflow/director.rb:94:in `execute'
/usr/lib/ruby/vendor_ruby/dynflow/executors/parallel/worker.rb:15:in `block in on_message'
/usr/lib/ruby/vendor_ruby/dynflow/executors.rb:18:in `run_user_code'
/usr/lib/ruby/vendor_ruby/dynflow/executors/parallel/worker.rb:14:in `on_message'
/usr/lib/ruby/vendor_ruby/concurrent/actor/context.rb:46:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/executes_context.rb:7:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/dynflow/actor.rb:122:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/awaits.rb:15:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/usr/lib/ruby/vendor_ruby/dynflow/actor.rb:56:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/buffer.rb:38:in `process_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/buffer.rb:31:in `process_envelopes?'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/buffer.rb:20:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/termination.rb:55:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/removes_child.rb:10:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/core.rb:162:in `process_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/core.rb:96:in `block in on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/core.rb:119:in `block (2 levels) in schedule_execution'
/usr/lib/ruby/vendor_ruby/concurrent/synchronization/mutex_lockable_object.rb:41:in `block in synchronize'
/usr/lib/ruby/vendor_ruby/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
/usr/lib/ruby/vendor_ruby/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
/usr/lib/ruby/vendor_ruby/concurrent/actor/core.rb:116:in `block in schedule_execution'
/usr/lib/ruby/vendor_ruby/concurrent/executor/serialized_execution.rb:18:in `call'
/usr/lib/ruby/vendor_ruby/concurrent/executor/serialized_execution.rb:96:in `work'
/usr/lib/ruby/vendor_ruby/concurrent/executor/serialized_execution.rb:77:in `block in call_job'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:353:in `run_task'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:342:in `block (3 levels) in create_worker'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:325:in `loop'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:325:in `block (2 levels) in create_worker'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:324:in `catch'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:324:in `block in create_worker'
/usr/lib/ruby/vendor_ruby/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2022-07-14T07:26:35 875e29b8 [D] Step 0465361f-cabc-4cdf-8d15-b9309252aadf: 2 running >> error in phase Run Proxy::Dynflow::Action::Batch
2022-07-14T07:26:35 [D] ExecutionPlan 0465361f-cabc-4cdf-8d15-b9309252aadf running >> stopped
2022-07-14T07:26:36 [D] Executor heartbeat
    (1-1/1)