Virt-who service won't start, times out

Problem:

Trying to install virt-who for RHEL subscription / ESXi Host management. This functionality is critical to my needs. This is long and painful, I’m sorry in advance but I’m at the end of my rope with this.

Couple of problems:

First Problem, virt-who version out of date

  1. Installed “tfm-rubygem-foreman_virt_who_configure” (mislabeld in documentation btw) plugin for Foreman (1.22) / Katello (3.12).
  2. Restarted Foreman, plugin shows up in menu as expected.
  3. Use plugin to create a virt-who entry for my vSphere (Version 6.5.0.20000 Build 9451637), submit entry, click “Deploy” tab.
  4. hammer virt-who module not installed, monkeyed with this for a while, so many broken things with the hammer virt-who configure module. Abandon hammer module completely to use deploy script.
  5. Cut/Paste deploy script, execute deploy script.
  6. Script installs virt-who (0.22.5) rpm from CentOS Base (7.6) repository which is out of date and the script says 0.24.2 is minimal virt-who version.
  7. Have to engage in quest to install correct version of virt-who, which is in the RHEL satellite-tools repo now. I don’t have access to this repo through my RHEL subscriptions because we don’t have a Satellite subscription (or I’d be using Satellite).
  8. This is the end of the first problem, the version that the plugin tries to install is out of date and incompatible. I know this should probably go to the plugin maintainer, but my real issue is my next problem:

Second Problem : Can’t get github versions of virt-who to work - NOTE, I realize that this should also go to virt-who author/maintainer, but read to the end, I eventually get the latest version to run but it fails connecting to rhsm because it says rhsm is missing an attribute.

  1. Find virt-who project/source on github.
  2. clone git repo
  3. install deps (pip install -r requirements.txt, yum-builddep virt-who.spec)
  4. attempt to run “make rpm” which fails because python2-pyyaml isn’t found because this script expects python-pyyaml which is deprecated. Try to kludge this, get sick of python bullshit.
  5. abandon rpm plan to trick deploy script
  6. just compile a binary from the source with “make DESTDIR=/usr install” as per the README.md.
  7. compiles just fine, wheee!!
  8. test virt-who with “one-shot” to make sure my config file at least works, it doesn’t. Apparently the plugin adds a line to the virt-who config file for “env=Library” which is no longer compatible with the current version of virt-who, so I just commented that line out.
  9. “virt-who -d -o” again, logs show it connected to my vSphere server, had a couple complains about a couple hosts missing some attribute (thats fine), seems to finish its data collection, then tries to upload that data to the rhsm instance (foreman) and fails because of a missing attribute.
"AttributeError: 'UEPConnection' object has no attribute 'hypervisorHeartbeat'" 
  1. Get pissed. Try to download the virt-who that the deploy script said was the minimum supported version, 0.24.2.
  2. 0.24.2 compiles fine, need to re-add “env=Library” to config for this version to work
  3. 0.24-2 seems to one-shot ok, debug log shows a 200 for POSTing the data to rhsm, yet no data ever shows up in Foreman.
  4. Attempt to start virt-who 0.24.2 service, it just hangs and eventually systemd times it out :
# systemctl status virt-who.service -l
● virt-who.service - Daemon for reporting virtual guest IDs to subscription-manager
   Loaded: loaded (/usr/lib/systemd/system/virt-who.service; enabled; vendor preset: disabled)
   Active: failed (Result: timeout) since Thu 2019-08-15 09:15:32 EDT; 1min 7s ago
  Process: 25555 ExecStart=/usr/bin/virt-who (code=exited, status=0/SUCCESS)
 Main PID: 25555 (code=exited, status=0/SUCCESS)

Aug 15 09:14:01 FOREMANFQDN systemd[1]: Starting Daemon for reporting virtual guest IDs to subscription-manager...
Aug 15 09:15:31 FOREMANFQDN systemd[1]: virt-who.service start operation timed out. Terminating.
Aug 15 09:15:32 FOREMANFQDN systemd[1]: Failed to start Daemon for reporting virtual guest IDs to subscription-manager.
Aug 15 09:15:32 FOREMANFQDN systemd[1]: Unit virt-who.service entered failed state.
Aug 15 09:15:32 FOREMANFQDN systemd[1]: virt-who.service failed.

  1. Now, I don’t much care about the old version hanging, I’m much more interested in using the current build of virt-who with Foreman. (full log below) and am seeking help on making that happen. So, my issue is using the most current virt-who, when it tries to send that data to rhsm, it fails because it’s reporting that some object is missing an attribute. This is what seems to be needing attention. Or, if someone can tell me which release of virt-who is currently working with Foreman 1.22, I’d be happy to just use that.

Expected outcome:

virt-who runs, posts data to rhsm and hosts/guests are imported into Foreman.

Foreman and Proxy versions:

Installed Packages
Name        : foreman
Arch        : noarch
Version     : 1.22.0
Release     : 1.el7
Size        : 157 M
Repo        : installed
From repo   : foreman
Summary     : Systems Management web application
URL         : https://theforeman.org
License     : GPLv3+ with exceptions
Description : Foreman is aimed to be a Single Address For All Machines Life Cycle Management.
            : Foreman is based on Ruby on Rails, and this package bundles Rails and all
            : plugins required for Foreman to work.
Name        : katello
Arch        : noarch
Version     : 3.12.2
Release     : 1.el7
Size        : 397
Repo        : installed
From repo   : katello
Summary     : A package for managing application life-cycle for Linux systems
URL         : https://theforeman.org/plugins/katello
License     : GPLv2
Description : Provides a package for managing application life-cycle for Linux systems.

Foreman and Proxy plugin versions:

Installed Packages
Name        : tfm-rubygem-foreman_virt_who_configure
Arch        : noarch
Version     : 0.4.1
Release     : 1.fm1_22.el7
Size        : 21 M
Repo        : installed
From repo   : katello
Summary     : A plugin to make virt-who configuration easy
URL         : https://github.com/theforeman/foreman_virt_who_configure
License     : GPLv3
Description : A plugin to make virt-who configuration easy.

Other relevant data:
[e.g. logs from Foreman and/or the Proxy, modified templates, commands issued, etc]
(for logs, surround with three back-ticks to get proper formatting, e.g.)

This is the /var/log/rhsm/rhsm.log from running virt-who 0.25.4-1 “one-shot” from the command line, I replaced my servername with FOREMANFQDN:

# cat rhsm.log
2019-08-15 09:23:56,747 [virtwho.config ERROR] MainProcess(26645):MainThread @config.py:parse_file:421 - Unable to read configuration file /etc/virt-who.conf
2019-08-15 09:23:56,751 [virtwho.rhsm_log DEBUG] MainProcess(26645):MainThread @config.py:init_config:1550 - [global]: Value for "interval" not set, using default: 3600
2019-08-15 09:23:56,751 [virtwho.rhsm_log DEBUG] MainProcess(26645):MainThread @config.py:init_config:1550 - [global]: Value for "log_per_config" not set, using default: False
2019-08-15 09:23:56,751 [virtwho.rhsm_log DEBUG] MainProcess(26645):MainThread @config.py:init_config:1550 - [global]: Value for "print_" not set, using default: False
2019-08-15 09:23:56,752 [virtwho.rhsm_log DEBUG] MainProcess(26645):MainThread @config.py:init_config:1550 - [global]: Value for "reporter_id" not set, using default: bsdv4vlcm01.ilnx.com-43860f2762b4429fa7b7ae8d0fa2b2b6
2019-08-15 09:23:56,752 [virtwho.rhsm_log DEBUG] MainProcess(26645):MainThread @config.py:init_config:1550 - [global]: Value for "log_dir" not set, using default: /var/log/rhsm
2019-08-15 09:23:56,752 [virtwho.rhsm_log DEBUG] MainProcess(26645):MainThread @config.py:init_config:1550 - [global]: Value for "configs" not set, using default: []
2019-08-15 09:23:56,752 [virtwho.rhsm_log DEBUG] MainProcess(26645):MainThread @config.py:init_config:1550 - [global]: Value for "log_file" not set, using default: rhsm.log
2019-08-15 09:23:56,752 [virtwho.rhsm_log DEBUG] MainProcess(26645):MainThread @config.py:init_config:1550 - [virt-who-config-1]: Value for "simplified_vim" not set, using default: True
2019-08-15 09:23:56,753 [virtwho.rhsm_log INFO] MainProcess(26645):MainThread @executor.py:__init__:54 - Using config named 'virt-who-config-1'
2019-08-15 09:23:56,753 [virtwho.rhsm_log INFO] MainProcess(26645):MainThread @main.py:main:162 - Using configuration "virt-who-config-1" ("esx" mode)
2019-08-15 09:23:56,753 [virtwho.rhsm_log INFO] MainProcess(26645):MainThread @main.py:main:164 - Using reporter_id='FOREMANFQDN-43860f2762b4429fa7b7ae8d0fa2b2b6'
2019-08-15 09:23:56,762 [rhsm.https DEBUG] MainProcess(26645):MainThread @https.py:<module>:56 - Using standard libs to provide httplib and ssl
2019-08-15 09:23:56,776 [virtwho.main DEBUG] MainProcess(26645):Thread-2 @virt.py:run:407 - Thread 'virt-who-config-1' started
2019-08-15 09:23:56,776 [virtwho.main DEBUG] MainProcess(26645):Thread-2 @esx.py:_prepare:130 - Log into ESX
2019-08-15 09:23:57,256 [virtwho.main DEBUG] MainProcess(26645):Thread-2 @esx.py:_prepare:133 - Creating ESX event filter
2019-08-15 09:24:03,921 [virtwho.main DEBUG] MainProcess(26645):Thread-2 @esx.py:getHostGuestMapping:270 - Host 'host-2942' doesn't have hypervisor_id property
2019-08-15 09:24:03,927 [virtwho.main DEBUG] MainProcess(26645):Thread-2 @esx.py:getHostGuestMapping:270 - Host 'host-3092' doesn't have hypervisor_id property
2019-08-15 09:24:03,938 [virtwho.main INFO] MainProcess(26645):Thread-2 @virt.py:_send_data:982 - Report for config "virt-who-config-1" gathered, placing in datastore
2019-08-15 09:24:04,180 [virtwho.main DEBUG] MainProcess(26645):Thread-2 @virt.py:run:435 - Thread 'virt-who-config-1' stopped after running once
2019-08-15 09:24:04,801 [rhsm.connection INFO] MainProcess(26645):Thread-3 @connection.py:__init__:871 - Connection built: host=FOREMANFQDN port=443 handler=/rhsm auth=basic username=virt_who_reporter_1
2019-08-15 09:24:04,796 [virtwho.destination_-5163520369811620371 DEBUG] MainProcess(26645):Thread-3 @virt.py:run:407 - Thread 'destination_-5163520369811620371' started
2019-08-15 09:24:04,802 [rhsm.connection DEBUG] MainProcess(26645):Thread-3 @connection.py:_request:545 - Making request: GET /rhsm/status/
2019-08-15 09:24:04,798 [virtwho.destination_-5163520369811620371 DEBUG] MainProcess(26645):Thread-3 @subscriptionmanager.py:_connect:144 - Authenticating with RHSM username virt_who_reporter_1
2019-08-15 09:24:04,798 [virtwho.destination_-5163520369811620371 INFO] MainProcess(26645):Thread-3 @subscriptionmanager.py:_connect:155 - X-Correlation-ID: 72623b873be3439186e05fd6e1a463ac
2019-08-15 09:24:04,912 [rhsm.connection INFO] MainProcess(26645):Thread-3 @connection.py:_request:588 - Response: status=200, request="GET /rhsm/status/"
2019-08-15 09:24:04,914 [virtwho.destination_-5163520369811620371 ERROR] MainProcess(26645):Thread-3 @virt.py:run:421 - Thread 'destination_-5163520369811620371' fails with exception:
Traceback (most recent call last):
  File "virtwho/virt/virt.py", line 412, in run
    self._run()
  File "virtwho/virt/virt.py", line 368, in _run
    self._send_data(data_to_send)
  File "virtwho/virt/virt.py", line 604, in _send_data
    self.dest.hypervisorHeartbeat(config=self.config, options=self.options)
  File "virtwho/manager/subscriptionmanager/subscriptionmanager.py", line 265, in hypervisorHeartbeat
    result = connection.hypervisorHeartbeat(config['owner'], named_options)
AttributeError: 'UEPConnection' object has no attribute 'hypervisorHeartbeat'
2019-08-15 09:24:04,915 [virtwho.destination_-5163520369811620371 INFO] MainProcess(26645):Thread-3 @virt.py:_send_data:615 - Error report received
2019-08-15 09:24:04,915 [virtwho.destination_-5163520369811620371 DEBUG] MainProcess(26645):Thread-3 @virt.py:run:435 - Thread 'destination_-5163520369811620371' stopped after running once
2019-08-15 09:24:05,799 [virtwho.main DEBUG] MainProcess(26645):MainThread @__main__.py:main:25 - virt-who terminated
2019-08-15 09:24:05,800 [virtwho.main DEBUG] MainProcess(26645):MainThread @executor.py:terminate:225 - virt-who is shutting down
#

Hello, if you’re getting hypervisors stuck task, it may be something on candlepin side. Also dynflow workers is worth checking, go to dynflow console and see the status (or see if other tasks are progressing). The virt-who version should be enforced by the deployment script. If virt-who hangs, it probably can’t connect to the hypervisor for some reason.

Actually, I got past this issue by downgrading to virt-who 0.24.2, that is the only version of virt-who out of their github repo that seems to work with Foreman 1.22.

0.24.4 causes the Hypervisors stuck task, 0.24.2 did not. 0.25.4 doesn’t even get there due to a missing attribute on some object (error above).

I detailed a few of the issues in a different post about virt-who. For the purposes of this post, I asked for it to just be deleted because I had gotten past the problems in this post but a mod said no.

Hello, I asked someone who’s more familiar with this, hopefully this reply will help to people running to the same issue

Eko:
I have tried the package virt-who-0.24.4 with foreman 1.22.0 and I can’t reproduce this issue.

But I guess the TFM issue is caused by the encrypted_password and
rhsm_encrypted_password,

When virt-who package was uninstalled, the /var/lib/virt-who/key will be
removed, you have to create the new encrypted_password by virt-who-password.

My suggestion is:

1). Install virt-who-0.24.7-1.el7.noarch.rpm to try again, it’s the
final version and already shipped with RHEL7.7.

2). Using ‘password’ and ‘rhsm_password’ to instead encrypted_password
and rhsm_encrypted_password in the virt-who configure file.

You seem to be under the impression I have access to that RPM, I do not. I am using CentOS and the only version of virt-who available in BASE is an even older unsupported version that is incompatible with Foreman 1.22. My only option was to download the source from github and attempt to build myself. The “make rpm” function in source doesn’t complete due to some python library being renamed and it can’t find it, even though it is installed. I was able to manually compile the source, despite non-functional “DESTDIR” directives, but I suppose I can attempt to compile the most recent version and confirm the existence of encrypted_password and rhsm_encrypted_password. I have sort of moved on from this issue once I got the older version working, I’ll try to make some time to revisit.

I see the package at http://mirror.centos.org/centos/7/cr/x86_64/Packages/virt-who-0.24.7-1.el7.noarch.rpm

Ah, I don’t have the CR repo installed. I don’t recall that repo being listed as required in the Foreman documentation, nor listed in the virt-who documentation that I recall. If this is one of those “Well, duh, of course you need the CR repo” then that’s my mistake.

BASE is outdated:

# yum info virt-who
Loaded plugins: enabled_repos_upload, fastestmirror, package_upload, product-id, search-disabled-
              : repos, subscription-manager, tracer_upload
This system is registered with an entitlement server, but is not receiving updates. You can use subscription-manager to assign subscriptions.
Loading mirror speeds from cached hostfile
 * base: mirrors.mit.edu
 * centos-sclo-rh: mirrors.mit.edu
 * epel: mirrors.mit.edu
 * extras: mirrors.mit.edu
 * updates: mirrors.mit.edu
Available Packages
Name        : virt-who
Arch        : noarch
Version     : 0.22.5
Release     : 1.el7
Size        : 232 k
Repo        : base/7/x86_64
Summary     : Agent for reporting virtual guest IDs to subscription-manager
URL         : https://github.com/candlepin/virt-who
License     : GPLv2+
Description : Agent that collects information about virtual guests present in the system and
            : report them to the subscription manager.

Uploading Enabled Repositories Report
#

No, I don’t think it should be necessary normally, but if you want to test the version that will follow and should work, here’s where you get it from.

Thanks, I’ll give that version a shot.

I was able to get that RPM to work. One thing, for whoever is building these RPM’s, they aren’t updating the version information found in “setup.py”. For example, this version RPM is marked as 0.24.7, yet “virt-who --verison” reports 0.22.1:

# virt-who --version
virt-who 0.22.1

That is very frustrating when trying to troubleshoot different versions.

So, the RPM seems to work in the sense it installed a virt-who binary, and after fixing the config file rhsm_encrypted_password, seems to login to Foreman ok, but after the initial run, I’m not seeing any ESXi hosts being populated in my “All Hosts” view now. (Using “Any Location” view).

I do see the host information running the exe in “oneshot” mode. The log also says it found the hosts and would be reporting it to Foreman.

Edit: also, to be clear, I reverted back my Foreman VM snapshot to pre-virt-who configuration, its just a bare (working) Foreman 1.22 with no other virt-who stuff. This is a totally clean install attempt with no cruft laying around.

Sep 16 12:37:24 my_foreman systemd: Started Daemon for reporting virtual guest IDs to subscription-manager.
Sep 16 12:37:32 my_foreman /usr/bin/virt-who: 2019-09-16 12:37:32,374 [virtwho.main INFO] MainProcess(16714):Thread-2 @virt.py:_send_data:969 - Report for config "virt-who-config-1" gathered, placing in datastore
Sep 16 12:37:33 my_foreman /usr/bin/virt-who: 2019-09-16 12:37:32,993 [virtwho.destination_-7244243523893140581 INFO] MainProcess(16714):Thread-3 @virt.py:_send_data:639 - Hosts-to-guests mapping for config "virt-who-config-1": 41 hypervisors and 1104 guests found
Sep 16 12:37:33 my_foreman /usr/bin/virt-who: 2019-09-16 12:37:32,994 [virtwho.destination_-7244243523893140581 INFO] MainProcess(16714):Thread-3 @virt.py:_send_data:670 - Sending updated Host-to-guest mapping to "MY_ORG" including 41 hypervisors and 1104 guests
Sep 16 12:37:33 my_foreman /usr/bin/virt-who: 2019-09-16 12:37:32,996 [virtwho.destination_-7244243523893140581 INFO] MainProcess(16714):Thread-3 @subscriptionmanager.py:_connect:155 - X-Correlation-ID: 1535e5eace2540f395843b867148b81d
Sep 16 12:42:09 my_foreman /usr/bin/virt-who: 2019-09-16 12:42:09,696 [virtwho.main INFO] MainProcess(16714):Thread-2 @virt.py:_send_data:969 - Report for config "virt-who-config-1" gathered, placing in datastore
Sep 16 12:42:09 my_foreman /usr/bin/virt-who: 2019-09-16 12:42:09,918 [virtwho.main INFO] MainProcess(16714):Thread-2 @virt.py:_send_data:969 - Report for config "virt-who-config-1" gathered, placing in datastore

The scan interval is set for two hours, I’ll check back after that just to see, but so far, nothing showing up in “All Hosts” with “Any Location” view, and no errors to report.

Can you check under Monitor > tasks? You should see a hypervisor checkin task. I’m curious if ended with a warning or threw an error?

You might also tail /var/log/foreman/production.log and /var/log/candlepin/candlepin.log while you restart virt-who to see if anything interesting is printed there.

Same problem as before, it started a task (well, there are four of them stacked up now), its been running for an hour, no Running Steps, no errors, no locks, and the only output from the task at all is the RAW input:

Id: dc7dbccb-ba43-49b8-be0d-0d3d85ea8d19
Label: Actions::Katello::Host::Hypervisors
Duration: about 1 hour
Raw input:
{"services_checked"=>["candlepin", "candlepin_auth"],
 "hypervisors"=>Step(3).output[:hypervisors],
 "current_request_id"=>nil,
 "current_timezone"=>"UTC",
 "current_user_id"=>nil,
 "current_organization_id"=>nil,
 "current_location_id"=>nil}
Raw output:
{}
External Id: f5b7edee-79bc-4817-b5e9-f02e4162b617

I do know for a fact that this worked with 0.24.2 (I think, its been a couple weeks now) and the task finished in less than a minute or two and all my ESXi hosts were visible under “All Hosts”.

Ok, I think it might be configuration related.

I did the following:

  1. Killed the stuck tasks (Foreman.blah("").destroy)
  2. foreman-rake katello:reimport
  3. Downloaded github virt-who 0.24.2 binary
  4. executed (without changing anything else) “./virt-who -d -o -c /etc/virt-who.d/virt-who-config-1.conf” and my task is again stuck with no running steps, no errors, no locks, nothing.

The dynflow console table yields:

Id: 91fc0843-a688-4eb1-bd02-51a333d5599d

Label: Actions::Katello::Host::Hypervisors

Status: running

Result: pending

Started at: 2019-09-16 17:39:36 UTC

Ended at:

Plan
Run
Finalize
Execution History
3: Actions::Candlepin::AsyncHypervisors (pending)
5: Actions::Katello::Host::HypervisorsUpdate (pending)
sequence		concurrence
Back

It never moves on from here.

The only thing I can think of is the virt-who passwords, but I configured my virt-who-config-1.conf with the following:

[virt-who-config-1]
type=esx
hypervisor_id=hostname
owner=MY_ORG
env=Library
server=IP_ADDRESS
username=MY_USER
encrypted_password=MY_PASSWORD_ENCRYPTED_WITH_V-W-Password
rhsm_hostname=FQND_TO_FOREMAN
rhsm_username=virt_who_reporter_1
rhsm_encrypted_password=84884b922649290f5b60c8394a032cb6
rhsm_prefix=/rhsm

Now, the rhsm_encrypted_password is the LAST hash in /var/lib/virt-who/key. There were no errors when it connected to Foreman, and the task started, so I assumed this was the correct hash to use. If I am mistaken, or there is another thing I need to change, please inform. Thanks.

PS: It appears this newer version ignores the “env=” line, but 0.24.2 requires it, so I left it in there. The log specifically says 0.24.7 ignores that unknown configuration option, so it appears harmless to leave it.

This is log output from virt-who-0.24.2 using the 0.24.7 configs, unchanged.

last bit of virt-who output (esxi info removed):

2019-09-16 14:20:20,607 [rhsm.connection DEBUG] MainProcess(40127):Thread-3 @connection.py:_request:545 - Making request: POST /rhsm/hypervisors/MY_ORG?reporter_id=MY_FOREMAN_FQDN-43860f2762b4429fa7b7ae8d0fa2b2b6&cloaked=False&env=Library
2019-09-16 14:20:21,250 [rhsm.connection INFO] MainProcess(40127):Thread-3 @connection.py:_request:588 - Response: status=200, request="POST /rhsm/hypervisors/MY_ORG?reporter_id=MY_FOREMAN_FQDN-43860f2762b4429fa7b7ae8d0fa2b2b6&cloaked=False&env=Library"
2019-09-16 14:20:21,328 [virtwho.destination_-1593291127803739355 DEBUG] MainProcess(40127):Thread-3 @virt.py:run:426 - Thread 'destination_-1593291127803739355' terminated
2019-09-16 14:20:21,799 [virtwho.main DEBUG] MainProcess(40127):MainThread @__main__.py:main:25 - virt-who terminated
2019-09-16 14:20:21,799 [virtwho.main DEBUG] MainProcess(40127):MainThread @executor.py:terminate:225 - virt-who is shutting down

production.log:

2019-09-16T14:20:19 [I|app|60f3ba45] Started GET "/rhsm/status/" for 10.34.193.114 at 2019-09-16 14:20:19 -0400
2019-09-16T14:20:19 [I|app|60f3ba45] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2019-09-16T14:20:19 [I|app|60f3ba45] Completed 200 OK in 91ms (Views: 1.1ms | ActiveRecord: 25.3ms)
2019-09-16T14:20:20 [I|app|ca111187] Started GET "/rhsm/consumers/81d2227b-8732-4c9f-b1be-4b4ce6990e91" for 10.34.193.114 at 2019-09-16 14:20:20 -0400
2019-09-16T14:20:20 [I|app|ca111187] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_show as JSON
2019-09-16T14:20:20 [I|app|ca111187]   Parameters: {"id"=>"81d2227b-8732-4c9f-b1be-4b4ce6990e91"}
2019-09-16T14:20:20 [I|app|ca111187] Current user set to 81d2227b-8732-4c9f-b1be-4b4ce6990e91 (regular)
2019-09-16T14:20:20 [I|app|ca111187] Completed 200 OK in 96ms (Views: 13.1ms | ActiveRecord: 8.6ms)
2019-09-16T14:20:20 [I|app|5ae8ef26] Started GET "/rhsm/consumers/81d2227b-8732-4c9f-b1be-4b4ce6990e91/owner" for 10.34.193.114 at 2019-09-16 14:20:20 -0400
2019-09-16T14:20:20 [I|app|5ae8ef26] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2019-09-16T14:20:20 [I|app|5ae8ef26]   Parameters: {"id"=>"81d2227b-8732-4c9f-b1be-4b4ce6990e91"}
2019-09-16T14:20:20 [I|app|5ae8ef26] Current user set to 81d2227b-8732-4c9f-b1be-4b4ce6990e91 (regular)
2019-09-16T14:20:20 [I|app|5ae8ef26] Completed 200 OK in 66ms (Views: 0.3ms | ActiveRecord: 4.7ms)
2019-09-16T14:20:20 [I|app|30e5ebdc] Started GET "/rhsm/status" for 10.34.193.114 at 2019-09-16 14:20:20 -0400
2019-09-16T14:20:20 [I|app|30e5ebdc] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2019-09-16T14:20:20 [I|app|30e5ebdc] Completed 200 OK in 43ms (Views: 1.0ms | ActiveRecord: 2.7ms)
2019-09-16T14:20:20 [I|app|54875d08] Started POST "/rhsm/hypervisors/MY_ORG?reporter_id=[FILTERED]&cloaked=False&env=Library" for 10.34.193.114 at 2019-09-16 14:20:20 -0400
2019-09-16T14:20:20 [I|app|54875d08] Processing by Katello::Api::Rhsm::CandlepinProxiesController#async_hypervisors_update as JSON
2019-09-16T14:20:20 [I|app|54875d08]   Parameters: {"reporter_id"=>"[FILTERED]", "cloaked"=>"False", "env"=>"Library", "owner"=>"MY_ORG"}
2019-09-16T14:20:20 [I|app|54875d08] Current user set to 81d2227b-8732-4c9f-b1be-4b4ce6990e91 (regular)
2019-09-16T14:20:20 [I|bac|54875d08] Task {label: Actions::Katello::Host::Hypervisors, id: 6f63ddcc-deb8-4dc1-bf6f-450da561684d, execution_plan_id: 4c165bac-9af6-4f60-aa23-7de0b3cb33fa} state changed: planning
2019-09-16T14:20:20 [I|app|] Current user set to 81d2227b-8732-4c9f-b1be-4b4ce6990e91 (regular)
2019-09-16T14:20:21 [I|app|] Current user set to 81d2227b-8732-4c9f-b1be-4b4ce6990e91 (regular)
2019-09-16T14:20:21 [I|bac|] Task {label: Actions::Katello::Host::Hypervisors, id: 6f63ddcc-deb8-4dc1-bf6f-450da561684d, execution_plan_id: 4c165bac-9af6-4f60-aa23-7de0b3cb33fa} state changed: planned
2019-09-16T14:20:21 [I|app|] Current user set to 81d2227b-8732-4c9f-b1be-4b4ce6990e91 (regular)
2019-09-16T14:20:21 [I|app|] Current user set to 81d2227b-8732-4c9f-b1be-4b4ce6990e91 (regular)
2019-09-16T14:20:21 [I|app|] Current user set to 81d2227b-8732-4c9f-b1be-4b4ce6990e91 (regular)
2019-09-16T14:20:21 [I|app|] Current user set to 81d2227b-8732-4c9f-b1be-4b4ce6990e91 (regular)
2019-09-16T14:20:21 [I|app|] Completed 200 OK in 499ms (Views: 0.5ms | ActiveRecord: 38.9ms)

candlepin.log:

2019-09-16 14:20:00,032 [thread=QuartzScheduler_Worker-10] [job=SweepBarJob-6ce72469-4876-4df0-9c4c-f23143636366, org=, csid=] INFO  org.candlepin.pinsetter.tasks.KingpinJob - Starting job: org.candlepin.pinsetter.tasks.SweepBarJob
2019-09-16 14:20:00,036 [thread=QuartzScheduler_Worker-10] [job=SweepBarJob-6ce72469-4876-4df0-9c4c-f23143636366, org=, csid=] INFO  org.candlepin.pinsetter.tasks.KingpinJob - Job completed: time=4
2019-09-16 14:20:19,982 [thread=http-bio-8443-exec-5] [req=d763111e-3566-4f24-be16-fab5fa3da220, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2019-09-16 14:20:19,988 [thread=http-bio-8443-exec-5] [req=d763111e-3566-4f24-be16-fab5fa3da220, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=6
2019-09-16 14:20:20,113 [thread=http-bio-8443-exec-10] [req=a838c228-0628-4644-8cf8-8d639a1563c9, org=, csid=ca111187-8f13-49a5-9fc2-70f6004cc396] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/consumers/81d2227b-8732-4c9f-b1be-4b4ce6990e91
2019-09-16 14:20:20,147 [thread=http-bio-8443-exec-10] [req=a838c228-0628-4644-8cf8-8d639a1563c9, org=MY_ORG, csid=ca111187-8f13-49a5-9fc2-70f6004cc396] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=34
2019-09-16 14:20:20,302 [thread=http-bio-8443-exec-7] [req=904f07b2-0d1c-4930-964f-c1f9d24b46a6, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/consumers/81d2227b-8732-4c9f-b1be-4b4ce6990e91/owner
2019-09-16 14:20:20,322 [thread=http-bio-8443-exec-7] [req=904f07b2-0d1c-4930-964f-c1f9d24b46a6, org=MY_ORG, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=20
2019-09-16 14:20:20,445 [thread=http-bio-8443-exec-1] [req=42e49dea-1fc7-4af5-a204-045b8bdc8fe6, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2019-09-16 14:20:20,448 [thread=http-bio-8443-exec-1] [req=42e49dea-1fc7-4af5-a204-045b8bdc8fe6, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=4
2019-09-16 14:20:20,810 [thread=http-bio-8443-exec-4] [req=60b3d519-335b-4c89-8833-4582892157f9, org=, csid=54875d08-c0b7-49fc-8b76-54106e11e715] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=POST, uri=/candlepin/hypervisors/MY_ORG
2019-09-16 14:20:20,840 [thread=http-bio-8443-exec-4] [req=60b3d519-335b-4c89-8833-4582892157f9, org=MY_ORG, csid=54875d08-c0b7-49fc-8b76-54106e11e715] INFO  org.candlepin.resource.HypervisorResource - Hypervisor update by principal: {"type":"trusteduser","name":"foreman_admin"}
2019-09-16 14:20:20,889 [thread=http-bio-8443-exec-4] [req=60b3d519-335b-4c89-8833-4582892157f9, org=MY_ORG, csid=54875d08-c0b7-49fc-8b76-54106e11e715] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=202, content-type="application/json", time=83
2019-09-16 14:20:20,936 [thread=QuartzScheduler_Worker-1] [job=hypervisor_update_23727021-4db2-4cf9-aa17-870b1fd30f57, org=MY_ORG, csid=] INFO  org.candlepin.pinsetter.tasks.KingpinJob - Starting job: org.candlepin.pinsetter.tasks.HypervisorUpdateJob$$EnhancerByGuice$$663b758d
2019-09-16 14:20:21,044 [thread=http-bio-8443-exec-3] [req=90a93f3e-f304-436a-997a-8034401b4346, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2019-09-16 14:20:21,048 [thread=http-bio-8443-exec-3] [req=90a93f3e-f304-436a-997a-8034401b4346, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=4
2019-09-16 14:20:21,079 [thread=http-bio-8443-exec-6] [req=7eeceac1-7782-4872-bc7b-3dbabfacca07, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2019-09-16 14:20:21,082 [thread=http-bio-8443-exec-6] [req=7eeceac1-7782-4872-bc7b-3dbabfacca07, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=4
2019-09-16 14:20:21,595 [thread=QuartzScheduler_Worker-1] [job=hypervisor_update_23727021-4db2-4cf9-aa17-870b1fd30f57, org=MY_ORG, csid=] INFO  org.candlepin.pinsetter.tasks.HypervisorUpdateJob - Summary for report from null by principal {"type":"trusteduser","name":"foreman_admin"}
 Created: 0, Updated: 2, Unchanged: 39, Failed: 0
2019-09-16 14:20:21,607 [thread=QuartzScheduler_Worker-1] [job=hypervisor_update_23727021-4db2-4cf9-aa17-870b1fd30f57, org=MY_ORG, csid=] INFO  org.candlepin.pinsetter.tasks.KingpinJob - Job completed: time=671

That’s everything I got, if you want more, tell me where.

If I’m reading that candlepin log correctly, it seems like it completed, yet the task never moves on. It’s still stuck there today. 0% complete, no running steps, no errors, no output.

Would you be able to get the task output for that async hypervisor task:

Go to monitor > tasks.
Look for the ‘Hypervisors’ task. Click on it
Click on ‘dynflow console’
click on the AsyncHypervisors Step
Grab the “Output” from there.

Here’s an example of what mine looks like (its complete though):

Also, i’d recommend against doing this. You can clear tasks with the foreman-tasks task cleaner:

doing it just via .destroy() will not fully delete the task.

Here is my Dynflow output:

Thanks for this link, I’ll try getting this working later.

Google recommended me the .destroy method.