Bug 1503573

Summary: virt-who hangs on @subscriptionmanager.py:check_report_state:247 - Job hypervisor_update_871b285b-d2fc-4e3b-ab69-90b9b3dbfedd not finished
Product: Red Hat Satellite Reporter: Jan Hutař <jhutar>
Component: Subscriptions - virt-whoAssignee: Barnaby Court <bcourt>
Status: CLOSED WORKSFORME QA Contact: Katello QA List <katello-qa-list>
Severity: high Docs Contact:
Priority: unspecified    
Version: 6.3.0CC: csnyder, hsun, jhutar, sgao, shihliu, yuefliu
Target Milestone: UnspecifiedKeywords: Reopened
Target Release: Unused   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-11-08 11:12:20 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1286684    

Description Jan Hutař 2017-10-18 12:17:03 UTC 
Description of problem:
virt-who hangs on @subscriptionmanager.py:check_report_state:247 - Job hypervisor_update_871b285b-d2fc-4e3b-ab69-90b9b3dbfedd not finished


Version-Release number of selected component (if applicable):
Satelite: satellite-6.3.0-20.0.beta.el7sat.noarch
Client: virt-who-0.19-6.el7_4.noarch


How reproducible:
2 of 2


Steps to Reproduce:
1. Have Satellite 6.3.0 snap 20 with registered RHEL7 client
2. Client have virt-who installed and configured to upload ESX data
3. # virt-who --one-shot --debug


Actual results:
# virt-who --one-shot --debug
[...]
2017-10-18 08:10:14,644 [rhsm.connection INFO] MainProcess(23021):Thread-3 @connection.py:_request:552 - Response: status=200, request="POST /rhsm/hypervisors/Default_Organization?reporter_id=client.example.com-5d7c29a73d8c46dcad7672f741a28be0&cloaked=False&env=Library"
2017-10-18 08:10:14,647 [rhsm.connection INFO] MainProcess(23021):Thread-3 @connection.py:__init__:822 - Connection built: host=sat.example.com port=443 handler=/rhsm auth=identity_cert ca_dir=/etc/rhsm/ca/ insecure=0
2017-10-18 08:10:14,648 [rhsm.connection DEBUG] MainProcess(23021):Thread-3 @connection.py:_request:516 - Making request: GET /rhsm/status/
2017-10-18 08:10:14,646 [virtwho.destination_-7426371236027194430 DEBUG] MainProcess(23021):Thread-3 @subscriptionmanager.py:_connect:131 - Authenticating with certificate: /etc/pki/consumer/cert.pem
2017-10-18 08:10:15,636 [rhsm.connection INFO] MainProcess(23021):Thread-3 @connection.py:_request:552 - Response: status=200, request="GET /rhsm/status/"
2017-10-18 08:10:15,638 [rhsm.connection DEBUG] MainProcess(23021):Thread-3 @connection.py:_request:516 - Making request: GET /rhsm/jobs/hypervisor_update_83ce6988-5a37-4037-8538-a67f01ea97f7?result_data=True
2017-10-18 08:10:15,637 [virtwho.destination_-7426371236027194430 DEBUG] MainProcess(23021):Thread-3 @subscriptionmanager.py:check_report_state:233 - Checking status of job hypervisor_update_83ce6988-5a37-4037-8538-a67f01ea97f7
2017-10-18 08:10:16,636 [rhsm.connection INFO] MainProcess(23021):Thread-3 @connection.py:_request:552 - Response: status=200, request="GET /rhsm/jobs/hypervisor_update_83ce6988-5a37-4037-8538-a67f01ea97f7?result_data=True"
2017-10-18 08:10:16,637 [virtwho.destination_-7426371236027194430 DEBUG] MainProcess(23021):Thread-3 @subscriptionmanager.py:check_report_state:247 - Job hypervisor_update_83ce6988-5a37-4037-8538-a67f01ea97f7 not finished


Expected results:
Should work


Additional info:
On Satellite, that job is really not finished:

# curl -X GET -s -k -u <user>:<pass> https://localhost/rhsm/jobs/hypervisor_update_83ce6988-5a37-4037-8538-a67f01ea97f7?result_data=true | json_reformat 
{
    "id": "hypervisor_update_83ce6988-5a37-4037-8538-a67f01ea97f7",
    "state": "CREATED",
    "startTime": null,
    "finishTime": null,
    "result": null,
    "principalName": "foreman_admin",
    "targetType": "owner",
    "targetId": "Default_Organization",
    "ownerId": "Default_Organization",
    "correlationId": "d10b6f70",
    "resultData": null,
    "statusPath": "/jobs/hypervisor_update_83ce6988-5a37-4037-8538-a67f01ea97f7",
    "done": false,
    "group": "async group",
    "created": "2017-10-18T12:10:14+0000",
    "updated": "2017-10-18T12:10:14+0000"
}

And Foreman still seems to query state of that Candlepin job:

# tail -n 0 -f /var/log/candlepin/*.log
==> /var/log/candlepin/audit.log <==

==> /var/log/candlepin/candlepin.log <==

==> /var/log/candlepin/cpdb.log <==

==> /var/log/candlepin/cpinit.log <==

==> /var/log/candlepin/error.log <==

==> /var/log/candlepin/candlepin.log <==
2017-10-18 08:14:53,851 [thread=http-bio-8443-exec-8] [req=da44db59-8a90-43b4-a873-4ddad4b1671c, org=, csid=d10b6f70] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/jobs/hypervisor_update_83ce6988-5a37-4037-8538-a67f01ea97f7?result_data=true
2017-10-18 08:14:53,854 [thread=http-bio-8443-exec-8] [req=da44db59-8a90-43b4-a873-4ddad4b1671c, org=, csid=d10b6f70] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=3
2017-10-18 08:14:53,861 [thread=http-bio-8443-exec-9] [req=6c802178-4369-4828-83b7-4fecaa09bbb5, org=, csid=f03bf638] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/jobs/hypervisor_update_871b285b-d2fc-4e3b-ab69-90b9b3dbfedd?result_data=true
2017-10-18 08:14:53,864 [thread=http-bio-8443-exec-9] [req=6c802178-4369-4828-83b7-4fecaa09bbb5, org=, csid=f03bf638] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=3
2017-10-18 08:15:09,901 [thread=http-bio-8443-exec-1] [req=d430ee3c-ebc4-45c4-882d-f4d6b950e994, org=, csid=d10b6f70] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/jobs/hypervisor_update_83ce6988-5a37-4037-8538-a67f01ea97f7?result_data=true
2017-10-18 08:15:09,904 [thread=http-bio-8443-exec-1] [req=d430ee3c-ebc4-45c4-882d-f4d6b950e994, org=, csid=d10b6f70] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=3
2017-10-18 08:15:09,909 [thread=http-bio-8443-exec-4] [req=85859cb2-9e66-4010-b210-4116395f7cbf, org=, csid=f03bf638] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/jobs/hypervisor_update_871b285b-d2fc-4e3b-ab69-90b9b3dbfedd?result_data=true
2017-10-18 08:15:09,912 [thread=http-bio-8443-exec-4] [req=85859cb2-9e66-4010-b210-4116395f7cbf, org=, csid=f03bf638] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=3
2017-10-18 08:15:25,953 [thread=http-bio-8443-exec-3] [req=2c4ce6ad-236d-48ac-97f9-2759ab308889, org=, csid=d10b6f70] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/jobs/hypervisor_update_83ce6988-5a37-4037-8538-a67f01ea97f7?result_data=true
2017-10-18 08:15:25,957 [thread=http-bio-8443-exec-3] [req=2c4ce6ad-236d-48ac-97f9-2759ab308889, org=, csid=d10b6f70] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=4
2017-10-18 08:15:25,959 [thread=http-bio-8443-exec-10] [req=e52da085-5a56-443b-b445-a15312e0e30d, org=, csid=f03bf638] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/jobs/hypervisor_update_871b285b-d2fc-4e3b-ab69-90b9b3dbfedd?result_data=true
2017-10-18 08:15:25,962 [thread=http-bio-8443-exec-10] [req=e52da085-5a56-443b-b445-a15312e0e30d, org=, csid=f03bf638] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=3
Comment 1 Jan Hutař 2017-10-18 12:23:29 UTC 
There was discussion about this on upstream #theforeman channel:

    https://botbot.me/freenode/theforeman/search/?q=hypervisor_update_

and this issue was reported:

    http://projects.theforeman.org/issues/21110