I should add that it’s just a proportion of each sort of task that ends with these warnings, in a seemingly random pattern.
@John_Beranek for the first one, let me think on it
for the 2nd error, do you have any sort of traceback in /var/log/foreman/ to help see where its coming from?
Big stack…
2020-04-28T08:57:04 [I|bac|] Task {label: Actions::Katello::Host::UploadProfiles, id: 8de555ac-20b1-4e36-8a45-75c1a86e2695, execution_plan_id: 4231b342-2a15-4183-b249-3ac524fe318f} state changed: stopped result: success
2020-04-28T09:08:33 [I|bac|] Task {label: Actions::Katello::Repository::Sync, id: b946a7f3-6fc9-4d86-b873-e3073947b9ee, execution_plan_id: afd9f1b1-927f-40a7-a363-a54c01636c33} state changed: running
2020-04-28T09:08:33 [I|bac|] Task {label: Actions::Katello::Repository::Sync, id: d06b6d81-77f4-431a-903e-49c8bd08a476, execution_plan_id: 3d907bd7-4c0d-4c74-ad5c-f48d27ceffde} state changed: running
2020-04-28T09:08:33 [I|bac|] Task {label: Actions::Katello::Repository::Sync, id: 9cc20d0a-8c17-41de-ab06-af647092b026, execution_plan_id: 989f1c86-0854-416a-92e0-190f5c03eba3} state changed: running
2020-04-28T09:16:52 [I|bac|] Task {label: Actions::Katello::Repository::CapsuleSync, id: 975e582d-5b0a-4627-bfd7-a2b57081e5ff, execution_plan_id: b4b868f6-c82e-44ed-8bf9-dc7c3b831723} state changed: planning
2020-04-28T09:16:52 [I|bac|] Task {label: Actions::Katello::Repository::CapsuleSync, id: 975e582d-5b0a-4627-bfd7-a2b57081e5ff, execution_plan_id: b4b868f6-c82e-44ed-8bf9-dc7c3b831723} state changed: planned
2020-04-28T09:16:53 [E|bac|] undefined local variable or method `finalize' for #<Actions::Katello::Repository::Sync:0x0000000016bdb170>
Did you mean? finalize_step (NameError)
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/action.rb:584:in `block (2 levels) in execute_finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.14.1/app/lib/actions/middleware/execute_if_contents_changed.rb:9:in `finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.17.5/app/lib/actions/middleware/rails_executor_wrap.rb:20:in `block in finalize'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/execution_wrapper.rb:87:in `wrap'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.17.5/app/lib/actions/middleware/rails_executor_wrap.rb:19:in `finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/action/progress.rb:31:in `with_progress_calculation'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/action/progress.rb:23:in `finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.14.1/app/lib/actions/middleware/keep_locale.rb:15:in `block in finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.14.1/app/lib/actions/middleware/keep_locale.rb:22:in `with_locale'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.14.1/app/lib/actions/middleware/keep_locale.rb:15:in `finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.17.5/app/lib/actions/middleware/keep_current_request_id.rb:19:in `block in finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.17.5/app/lib/actions/middleware/keep_current_request_id.rb:49:in `restore_current_request_id'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.17.5/app/lib/actions/middleware/keep_current_request_id.rb:19:in `finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.17.5/app/lib/actions/middleware/keep_current_timezone.rb:19:in `block in finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.17.5/app/lib/actions/middleware/keep_current_timezone.rb:44:in `restore_curent_timezone'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.17.5/app/lib/actions/middleware/keep_current_timezone.rb:19:in `finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.17.5/app/lib/actions/middleware/keep_current_user.rb:19:in `block in finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.17.5/app/lib/actions/middleware/keep_current_user.rb:44:in `restore_curent_user'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.17.5/app/lib/actions/middleware/keep_current_user.rb:19:in `finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.17.5/app/lib/actions/middleware/keep_current_taxonomies.rb:19:in `block in finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.17.5/app/lib/actions/middleware/keep_current_taxonomies.rb:45:in `restore_current_taxonomies'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.17.5/app/lib/actions/middleware/keep_current_taxonomies.rb:19:in `finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware.rb:40:in `finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/middleware/world.rb:31:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/action.rb:583:in `block in execute_finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/action.rb:475:in `block in with_error_handling'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/action.rb:475:in `catch'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/action.rb:475:in `with_error_handling'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/action.rb:582:in `execute_finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/action.rb:285:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:18:in `block (2 levels) in execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/execution_plan/steps/abstract.rb:167:in `with_meta_calculation'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:17:in `block in execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:32:in `open_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.2/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:16:in `execute'It looks like there might be an old dynflow worker running from prior to the upgrade! Notice that that stack trace has ‘katello-3.14’ and ‘foreman-taks-0.17.5’ These are old! Can you try shutting everything down (foreman-maintain service stop) and then looking through ‘ps aux’ for a dynflow process? If its still there, try killing it and starting the services.
Ah, OK - since those errors I did a full reboot of the VM, and I can confirm the only dynflows are now:
foreman 1177 0.0 0.0 4356 584 ? Ss 10:17 0:00 /usr/bin/scl enable tfm sidekiq -e production -r /usr/share/foreman/extras/dynflow-sidekiq.rb -C /etc/foreman/dynflow/worker-hosts-queue.yml
foreman 1219 0.0 0.0 4356 592 ? Ss 10:17 0:00 /usr/bin/scl enable tfm sidekiq -e production -r /usr/share/foreman/extras/dynflow-sidekiq.rb -C /etc/foreman/dynflow/worker.yml
foreman 1220 0.0 0.0 4356 584 ? Ss 10:17 0:00 /usr/bin/scl enable tfm sidekiq -e production -r /usr/share/foreman/extras/dynflow-sidekiq.rb -C /etc/foreman/dynflow/orchestrator.yml
I’m syncing all repos now, to see if all tasks succeed.
OK, all repositories synced without error now.
As for the first error, it seems to be just particular hosts coming up with the problem, something like 50/750 hosts…
Can you confirm that you’re on postgresql 12?
[root@centos7-koji ~]# sudo -u postgres psql foreman
could not change directory to "/root": Permission denied
psql (12.1)
Type "help" for help.
foreman=# quit
Notice the 12.1 there
Yes, the Postgresql migration went fine:
# sudo -u postgres psql
could not change directory to "/var/log/foreman": Permission denied
psql (12.1)
Type "help" for help.
postgres=# \q
# ps auxww|grep postmaster
postgres 1308 0.0 0.3 832132 49972 ? Ss 10:17 0:02 postmaster -D /var/opt/rh/rh-postgresql12/lib/pgsql/data
For the profile updates that fail, some hosts will fail on one update, and then work on the next…
@John_Beranek i’m coming up at a loss for how this could be happening, would you be able to send me your /var/log/foreman/production.log ? I can Private message you my email address
I’ve opened a Pull request here: https://patch-diff.githubusercontent.com/raw/Katello/katello/pull/8689
Would you be able to try the patch:
cd /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.15.0.1
wget https://patch-diff.githubusercontent.com/raw/Katello/katello/pull/8689.patch
patch -p1 < 8689.patch
foreman-rake db:migrate
systemctl restart httpd dynflow*Getting 404s for those links - permissions issue?
Whoops, heres’ the correct links:
cd /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.15.0.1
wget https://github.com/Katello/katello/pull/8689.patch
patch -p1 < 8689.patch
foreman-rake db:migrate
systemctl restart httpd dynflow*
as an update, this does not fully resolve the issue. Part of the issue is that dynflow was still running and creating improper installed package records. I’ve opened a pr (https://github.com/theforeman/foreman-packaging/pull/5140) to fix this ASAP hopefully before too many others hit it.
In the meantime i’m still digging through the best way to resolve it for those that have already upgraded (including you @John_Beranek)
Ah, so in fact it looks like both reported issues are related?
They are in that:
- due to a bug, badly formed installed packages were being saved
- due to an old dynflow running, badly formed installed packages were being saved
- We don’t handly badly formed installed packages well!
i think i fixed 1) in my patch, 2) has to be fixed in packaging, and i’m going to work on cleanup from the fallout of 2), plus adding some stricter enforcement (3)
@John_Beranek okay i’ve got something new for you.
Lets get rid of the old patched code first:
yum reinstall -y tfm-rubygem-katello
and then re-run through the same operations as before:
cd /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.15.0.1
wget https://github.com/Katello/katello/pull/8689.patch
patch -p1 < 8689.patch
foreman-rake db:migrate
systemctl restart httpd dynflow*Thanks, for what it’s worth that patch doesn’t apply correctly to 3.15.0.1 as it attempts to create a file which already exists:
The next patch would create the file db/migrate/20200501155054_installed_package_unique_nvrea.rb,
which already exists! Assume -R? [n]
Apply anyway? [n] y
patching file db/migrate/20200501155054_installed_package_unique_nvrea.rb
Hunk #1 FAILED at 1.
1 out of 1 hunk FAILED -- saving rejects to file db/migrate/20200501155054_installed_package_unique_nvrea.rb.rej
After following your steps I’m still seeing the errors in the log on profile updates. Perhaps due to the patch failure?
OK, doesn’t seem to be the patch failure, as I downloaded this file from your PR and it’s identical to the one in the RPM.
Oh sorry yes, resinstalling the rpm reverted all the changes except for new files that were created, so ignoring that failure is fine.