Virt-who Hypervisors Task in "pending" with no running steps, never moves

jvbunte · August 19, 2019, 4:26pm

Problem:

Finally got a virt-who daemon properly configured and reporting to Foreman (1.22). The problem is that after virt-who POSTs the data to rhsm, a task is created within Foreman in the “pending” state that has no running steps, no errors, a open lock on user id 5 (virt_who_reporter_1), and very little in the Raw output. (pasted below)

This task just sits here, never any progress update, can’t find much in logs to see if its actually doing anything (doesn’t appear to be) and no hypervisors listed in content hosts for RHEL subscription management.

I don’t think my issue is with virt-who anymore, but rather what foreman should be doing with the data it received from virt-who.

My project with foreman/katello depends on its ability to manage our RHEL licenses for ESXi hosts, this virt-who functionality is critical. Please help me if you can. I’ll fetch any additional information you need.

Expected outcome:

Eventually, see some content hosts I can associate RHEL licenses to. See any sort of progress on the task output, change from “pending” to running? Something to indicate its doing something.

Foreman and Proxy versions:

Foreman 1.22 / Katello 3.12 / virt-who 0.24-4-1

Foreman and Proxy plugin versions:

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.)

/etc/virt-who.d/virt-who-config-1.conf:

# cat /etc/virt-who.d/virt-who-config-1.conf
### This configuration file is managed via the virt-who configure plugin
### manual edits will be deleted.
[virt-who-config-1]
type=esx
hypervisor_id=hostname
owner=MYORG
env=Library
server=VSPHEREIPADDRESS
username=MYLOGIN
encrypted_password=LONGPWHASH
rhsm_hostname=FQDN_FOREMAN
rhsm_username=virt_who_reporter_1
rhsm_encrypted_password=LONGPWHASH
rhsm_prefix=/rhsm
#

Final couple lines from virt-who interval execution, seems like virt-who is pulling the correct info from vSphere and POST’ing it back to foreman/rhsm, gets a 200.

<Lots of ESXi host info removed> 
2019-08-19 12:00:48,366 [rhsm.connection DEBUG] MainProcess(615):Thread-3 @connection.py:_request:545 - Making request: POST /rhsm/hypervisors/intralinks?reporter_id=bsdv4vlcm01.ilnx.com-43860f2762b4429fa7b7ae8d0fa2b2b6&cloaked=False&env=Library
2019-08-19 12:00:49,018 [rhsm.connection INFO] MainProcess(615):Thread-3 @connection.py:_request:588 - Response: status=200, request="POST /rhsm/hypervisors/intralinks?reporter_id=bsdv4vlcm01.ilnx.com-43860f2762b4429fa7b7ae8d0fa2b2b6&cloaked=False&env=Library"

/var/log/foreman/production.log during virt-who run:

2019-08-19T10:44:04 [I|app|6145eda4] Started GET "/rhsm/status/" for MY_IP_ADDRESS at 2019-08-19 10:44:04 -0400
2019-08-19T10:44:04 [I|app|6145eda4] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2019-08-19T10:44:04 [I|app|6145eda4] Completed 200 OK in 55ms (Views: 1.1ms | ActiveRecord: 4.0ms)
2019-08-19T10:44:04 [I|app|c88ee523] Started GET "/rhsm/status" for MY_IP_ADDRESS at 2019-08-19 10:44:04 -0400
2019-08-19T10:44:04 [I|app|c88ee523] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2019-08-19T10:44:04 [I|app|c88ee523] Completed 200 OK in 51ms (Views: 1.2ms | ActiveRecord: 4.5ms)
2019-08-19T10:44:05 [I|app|45ae62a0] Started POST "/rhsm/hypervisors/MY_ORGANIZATION?reporter_id=[FILTERED]&cloaked=False&env=Library" for MY_IP_ADDRESS at 2019-08-19 10:44:05 -0400
2019-08-19T10:44:05 [I|app|45ae62a0] Processing by Katello::Api::Rhsm::CandlepinProxiesController#async_hypervisors_update as JSON
2019-08-19T10:44:05 [I|app|45ae62a0]   Parameters: {"reporter_id"=>"[FILTERED]", "cloaked"=>"False", "env"=>"Library", "owner"=>"MY_ORGANIZATION"}
2019-08-19T10:44:05 [I|kat|45ae62a0] Authorized user virt_who_reporter_1(virt_who_reporter_1)
2019-08-19T10:44:05 [I|bac|45ae62a0] Task {label: Actions::Katello::Host::Hypervisors, id: 5c910ea8-d009-4694-9ad4-afab852b8f94, execution_plan_id: 5345bd12-e154-4ec1-a7d5-85c7fefc19e4} state changed: planning
2019-08-19T10:44:05 [I|bac|] Task {label: Actions::Katello::Host::Hypervisors, id: 5c910ea8-d009-4694-9ad4-afab852b8f94, execution_plan_id: 5345bd12-e154-4ec1-a7d5-85c7fefc19e4} state changed: planned
2019-08-19T10:44:05 [I|app|] Completed 200 OK in 596ms (Views: 0.9ms | ActiveRecord: 80.8ms)
2019-08-19T10:45:53 [I|app|1fad1a54] Started GET "/rhsm/status/" for MY_IP_ADDRESS at 2019-08-19 10:45:53 -0400
2019-08-19T10:45:53 [I|app|1fad1a54] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2019-08-19T10:45:53 [I|app|1fad1a54] Completed 200 OK in 60ms (Views: 1.2ms | ActiveRecord: 4.6ms)
2019-08-19T10:45:53 [I|app|f1460692] Started GET "/rhsm/status" for MY_IP_ADDRESS at 2019-08-19 10:45:53 -0400
2019-08-19T10:45:53 [I|app|f1460692] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2019-08-19T10:45:53 [I|app|f1460692] Completed 200 OK in 50ms (Views: 1.1ms | ActiveRecord: 3.9ms)
2019-08-19T10:45:53 [I|app|92378037] Started POST "/rhsm/hypervisors/MY_ORGANIZATION?reporter_id=[FILTERED]&cloaked=False&env=Library" for MY_IP_ADDRESS at 2019-08-19 10:45:53 -0400
2019-08-19T10:45:53 [I|app|92378037] Processing by Katello::Api::Rhsm::CandlepinProxiesController#async_hypervisors_update as JSON
2019-08-19T10:45:53 [I|app|92378037]   Parameters: {"reporter_id"=>"[FILTERED]", "cloaked"=>"False", "env"=>"Library", "owner"=>"MY_ORGANIZATION"}
2019-08-19T10:45:53 [I|kat|92378037] Authorized user virt_who_reporter_1(virt_who_reporter_1)
2019-08-19T10:45:53 [I|bac|92378037] Task {label: Actions::Katello::Host::Hypervisors, id: 46dab7ad-59f6-4825-8706-59bcf9ebc0c0, execution_plan_id: d820ebb3-4a9d-442a-ac71-e04d82434fb9} state changed: planning
2019-08-19T10:45:53 [I|bac|] Task {label: Actions::Katello::Host::Hypervisors, id: 46dab7ad-59f6-4825-8706-59bcf9ebc0c0, execution_plan_id: d820ebb3-4a9d-442a-ac71-e04d82434fb9} state changed: planned
2019-08-19T10:45:53 [I|app|] Completed 200 OK in 335ms (Views: 0.6ms | ActiveRecord: 40.6ms)
2019-08-19T11:10:45 [I|app|04472bef] Started GET "/foreman_tasks/api/tasks?search=action~organization+%27MY_ORGANIZATION%27+and+result%3Dpending+and+label%3DActions::Katello::Organization::ManifestImport+or+Actions::Katello::Organization::ManifestRefresh+or+Actions::Katello::Organization::ManifestDelete+or+Actions::Katello::UpstreamSubscriptions::BindEntitlements+or+Actions::Katello::UpstreamSubscriptions::UpdateEntitlement+or+Actions::Katello::UpstreamSubscriptions::RemoveEntitlements+or+Actions::Katello::UpstreamSubscriptions::UpdateEntitlements" for MY_CLIENT_ADDRESS at 2019-08-19 11:10:45 -0400
2019-08-19T11:10:45 [I|app|04472bef] Processing by ForemanTasks::Api::TasksController#index as JSON
2019-08-19T11:10:45 [I|app|04472bef]   Parameters: {"search"=>"action~organization 'MY_ORGANIZATION' and result=pending and label=Actions::Katello::Organization::ManifestImport or Actions::Katello::Organization::ManifestRefresh or Actions::Katello::Organization::ManifestDelete or Actions::Katello::UpstreamSubscriptions::BindEntitlements or Actions::Katello::UpstreamSubscriptions::UpdateEntitlement or Actions::Katello::UpstreamSubscriptions::RemoveEntitlements or Actions::Katello::UpstreamSubscriptions::UpdateEntitlements"}
2019-08-19T11:10:45 [I|app|04472bef] Current user set to admin (admin)

jvbunte · August 19, 2019, 4:34pm

Raw Output of “pending” (says its running, but at 0% for 30+min now) task:

Task
Running Steps
Errors
Locks
Raw
Id: fe76edda-4726-4551-85f7-b2b4f4a122ab
Label: Actions::Katello::Host::Hypervisors
Duration: 25 minutes
Raw input:
{"services_checked"=>["candlepin", "candlepin_auth"],
 "hypervisors"=>Step(3).output[:hypervisors],
 "current_request_id"=>nil,
 "current_timezone"=>"UTC",
 "current_user_id"=>5,
 "current_organization_id"=>nil,
 "current_location_id"=>nil}
Raw output:
{}
External Id: a7227ed4-b167-4f41-8585-5c729a7a3bf5

There are “no running steps”, “no errors”, open lock on user id 5 (virt_who_reporter_1), and raw output pasted above.

jvbunte · August 20, 2019, 11:40am

It appears that downgrading to virt-who 0.24.2-1 has at least started a job that is now at 67% complete and I can actually see some of my ESXi hosts listed under Content Hosts. It’s been several minutes and the job still hasn’t completed, but at least there is a blurb under “Running Steps” that was absent with 0.24.4. It did finally complete successfully. I haven’t tried associating my RHEL licenses with a host yet, I’m dreading that being an entirely new issue so I’m getting some beverage first.

Running Steps (was absent using virt-who 0.24.4) :

Action:

Actions::Katello::Host::HypervisorsUpdate
State: running

Input:
{"hypervisors"=>Step(3).output[:hypervisors],
 "remote_user"=>"admin",
 "remote_cp_user"=>"admin",
 "current_request_id"=>nil,
 "current_timezone"=>"UTC",
 "current_user_id"=>5,
 "current_organization_id"=>nil,
 "current_location_id"=>nil}
Output:
{}

It appears the magic bullet for Foreman 1.22 is virt-who 0.24.2-1 and only 0.24.2-1.

Fix the systemd virt-who.service script with :

sed -i 's/Type=notify/Type=simple/' virt-who.service

before copying it into the systemd area as the virt-who daemon never notifies systemd and systemd will just timeout. I spent way more time than I should have figuring that out.

The Plugin for virt-who is kinda broken as well as the virt-who source build process. The script it generates leads you down a very wrong and buggy path. I only got this working from dissecting that script and kludging pieces of it to fix it. The only rpm version (that the script installs) available to CentOS7 users is in CentOS-Base and out of date. You need to get the source for 0.24.2-1 from github (and only that version as newer versions don’t seem to be compatible with Foreman 1.22), install a bunch of python dependencies, some rpm dependencies, and even then the virt-who will not create an rpm as is because of a python-pyyaml vs python2-pyyaml incompatibility. The only way I was able to get this to work was to manually compile/install (btw, the make process says execute “make DESTDIR=/some/path install” which totally ignores whatever path you give and just installs in /usr/bin) after editing the virt-who source file virtwho/version.py as it seems the maintainer doesn’t update this. If you do a virt-who --version it reports 0.22.x, which is confusing especially when you need a very precise version to make this work.

Sorry for the rant here, but I feel like RHEL license management is a pretty valuable feature that was way harder to make work than it should have been.