1506263 – Virt-who polls job status too quickly [rhel-7.4.z]

RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 1506263 - Virt-who polls job status too quickly [rhel-7.4.z]

Summary: Virt-who polls job status too quickly [rhel-7.4.z]

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Enterprise Linux 7
Classification:	Red Hat
Component:	virt-who
Sub Component:
Version:	7.4
Hardware:	Unspecified
OS:	Unspecified
Priority:	high
Severity:	medium
Target Milestone:	rc
Target Release:	---
Assignee:	candlepin-bugs
QA Contact:	Eko
Docs Contact:
URL:
Whiteboard:
Depends On:	1503700
Blocks:
TreeView+	depends on / blocked

Reported:	2017-10-25 14:03 UTC by Oneata Mircea Teodor
Modified:	2019-10-28 07:20 UTC (History)
CC List:	8 users (show)
Fixed In Version:	virt-who-0.19-7.el7_4
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:	1503700
Environment:
Last Closed:	2017-11-30 15:51:03 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)
(before fixed) /var/log/candlepin/candlepin.log (9.35 KB, text/plain) 2017-10-26 06:02 UTC, Eko	no flags	Details
(after fixed) /var/log/candlepin/candlepin.log (9.36 KB, text/plain) 2017-10-26 06:03 UTC, Eko	no flags	Details
View All

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Product Errata	RHBA-2017:3314	0	normal	SHIPPED_LIVE	virt-who bug fix update	2017-11-30 20:17:03 UTC

Description Oneata Mircea Teodor 2017-10-25 14:03:39 UTC

This bug has been copied from bug #1503700 and has been proposed to be backported to 7.4 z-stream (EUS).

Comment 3 Eko 2017-10-26 06:01:42 UTC

Hi Chris,

About the polls job status, we can't see any "poll job status" messages from the rhsm.log by virt-who logged. Because we don't have the permission to check the candlepin.log in stage candlepin, we only can check the "GET" Request from candlepin.log in satellite6.3, 

According to my testing, I can't find the valid "poll job state" message as you said: with an exponential backoff from 2 second polling time to 32 seconds.
How do I reproduce this issue and how to check it? could you give me some suggestions to verify this issue?  
 
The below is the log message from satellite candlepin.log about "Request: verb=GET, uri=/candlepin/status"

1). before fixed (virt-who-0.19-6.el7_4)
restart virt-who and check /var/log/candlepin/candlepin.log in satellite:
# grep "uri=/candlepin/status" before_fixed.log 
2017-10-26 13:27:19,015 [thread=http-bio-8443-exec-7] [req=72549cd7-a125-4e35-a9a6-5afe7fff6372, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2017-10-26 13:27:19,065 [thread=http-bio-8443-exec-5] [req=7397446a-8f55-45a2-96ab-3a25cdc8c1f8, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2017-10-26 13:27:19,213 [thread=http-bio-8443-exec-4] [req=046a3c23-4bfd-4faf-86a5-f539ff979bcc, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2017-10-26 13:27:19,230 [thread=http-bio-8443-exec-3] [req=3da36495-836e-46e4-a90b-c3de0ca4190a, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2017-10-26 13:27:19,346 [thread=http-bio-8443-exec-1] [req=9bdefd5d-72af-4e0e-b6a7-9a7c64a05159, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status

when restart virt-who, there are 5 "Get" Requests for "uri=/candlepin/status", and all the request time: "2017-10-26 13:27:19"

2). after fixed (virt-who-0.19-7.el7_4)
restart virt-who and check /var/log/candlepin/candlepin.log in satellite:
# grep "uri=/candlepin/status" after_fixed.log 
2017-10-26 13:47:46,205 [thread=http-bio-8443-exec-10] [req=14e76b5a-24d5-4e71-80c8-14f0d5782505, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2017-10-26 13:47:46,256 [thread=http-bio-8443-exec-1] [req=2240a7bc-559f-417d-91d9-f174873c699d, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2017-10-26 13:47:46,407 [thread=http-bio-8443-exec-2] [req=38c3245c-7fb7-47a4-aac0-c3c3547cd9c7, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2017-10-26 13:47:46,430 [thread=http-bio-8443-exec-6] [req=67e33b60-d2fa-4853-8d0f-79154e33a811, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2017-10-26 13:48:01,554 [thread=http-bio-8443-exec-7] [req=abf3da51-182b-488c-b5be-2c04367ed621, org=, csid=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status


when restart virt-who, also there are 5 "Get" Requests for "uri=/candlepin/status", and 4 requests time is:2017-10-26 13:47:46, the last request time is: "2017-10-26 13:48:01"

Comment 4 Eko 2017-10-26 06:02:51 UTC

Created attachment 1343556 [details]
(before fixed) /var/log/candlepin/candlepin.log

Comment 5 Eko 2017-10-26 06:03:28 UTC

Created attachment 1343557 [details]
(after fixed) /var/log/candlepin/candlepin.log

Comment 6 Eko 2017-10-27 07:49:16 UTC

Thanks Chris for sharing about how to test this issue, now we can verify it as following test results.

1). if no 429 code, virt-who will check the job state after 15 seconds
2017-10-27 14:45:20,761 [rhsm.connection INFO] MainProcess(22093):Thread-3 @connection.py:_request:552 - Response: status=200, request="POST /rhsm/hypervisors/Default_Organization?reporter_id=bootp-73-131-133.rhts.eng.pek2.redhat.com-27e5f2240411403f8b88c3c341e102b0&cloaked=False&env=Library"

======== Waiting for 15 seconds to send the "GET" request to check the job state =======  

2017-10-27 14:45:35,780 [rhsm.connection INFO] MainProcess(22093):Thread-3 @connection.py:__init__:822 - Connection built: host=bootp-73-131-133.rhts.eng.pek2.redhat.com port=443 handler=/rhsm auth=basic username=admin
2017-10-27 14:45:35,779 [virtwho.destination_-1557685887681118964 DEBUG] MainProcess(22093):Thread-3 @subscriptionmanager.py:_connect:127 - Authenticating with RHSM username admin
2017-10-27 14:45:35,781 [rhsm.connection DEBUG] MainProcess(22093):Thread-3 @connection.py:_request:516 - Making request: GET /rhsm/status/
2017-10-27 14:45:35,828 [rhsm.connection INFO] MainProcess(22093):Thread-3 @connection.py:_request:552 - Response: status=200, request="GET /rhsm/status/"
2017-10-27 14:45:35,830 [rhsm.connection DEBUG] MainProcess(22093):Thread-3 @connection.py:_request:516 - Making request: GET /rhsm/jobs/hypervisor_update_a020d5a6-a23b-4e2e-a9fc-c53d53db08a5?result_data=True
2017-10-27 14:45:35,829 [virtwho.destination_-1557685887681118964 DEBUG] MainProcess(22093):Thread-3 @subscriptionmanager.py:check_report_state:233 - Checking status of job hypervisor_update_a020d5a6-a23b-4e2e-a9fc-c53d53db08a5
2017-10-27 14:45:35,894 [rhsm.connection INFO] MainProcess(22093):Thread-3 @connection.py:_request:552 - Response: status=200, request="GET /rhsm/jobs/hypervisor_update_a020d5a6-a23b-4e2e-a9fc-c53d53db08a5?result_data=True"
2017-10-27 14:45:35,894 [virtwho.destination_-1557685887681118964 DEBUG] MainProcess(22093):Thread-3 @subscriptionmanager.py:check_report_state:258 - Number of mappings unchanged: 2
2017-10-27 14:45:35,895 [virtwho.destination_-1557685887681118964 INFO] MainProcess(22093):Thread-3 @subscriptionmanager.py:check_report_state:259 - Mapping for config "destination_-1557685887681118964" updated

2). if there is a 429 code, but no Retry-After setting, virt-who will waiting for 30 seconds to check the job state by default.
2017-10-27 14:38:12,096 [rhsm.connection INFO] MainProcess(21379):Thread-3 @connection.py:_request:552 - Response: status=429, request="GET /rhsm/jobs/hypervisor_update_0f3c3225-4873-47b6-9d6f-22f25f958c9a?result_data=True"
2017-10-27 14:38:12,096 [virtwho.destination_4482547385105569854 DEBUG] MainProcess(21379):Thread-3 @virt.py:_send_data:652 - 429 encountered while checking job state, checking again in "30"

=========== Waiting for 30 seconds and then check the job state again =========

2017-10-27 14:38:42,132 [rhsm.connection INFO] MainProcess(21379):Thread-3 @connection.py:__init__:822 - Connection built: http_proxy=bootp-73-131-133.rhts.eng.pek2.redhat.com:12345 host=bootp-73-131-133.rhts.eng.pek2.redhat.com port=443 handler=/rhsm auth=basic username=admin
2017-10-27 14:38:42,133 [rhsm.connection DEBUG] MainProcess(21379):Thread-3 @connection.py:_request:501 - Using proxy: bootp-73-131-133.rhts.eng.pek2.redhat.com:12345
2017-10-27 14:38:42,133 [rhsm.connection DEBUG] MainProcess(21379):Thread-3 @connection.py:_request:516 - Making request: GET /rhsm/status/
2017-10-27 14:38:42,132 [virtwho.destination_4482547385105569854 DEBUG] MainProcess(21379):Thread-3 @subscriptionmanager.py:_connect:127 - Authenticating with RHSM username admin
2017-10-27 14:38:42,423 [rhsm.connection INFO] MainProcess(21379):Thread-3 @connection.py:_request:552 - Response: status=200, request="GET /rhsm/status/"
2017-10-27 14:38:42,424 [rhsm.connection DEBUG] MainProcess(21379):Thread-3 @connection.py:_request:501 - Using proxy: bootp-73-131-133.rhts.eng.pek2.redhat.com:12345
2017-10-27 14:38:42,424 [rhsm.connection DEBUG] MainProcess(21379):Thread-3 @connection.py:_request:516 - Making request: GET /rhsm/jobs/hypervisor_update_0f3c3225-4873-47b6-9d6f-22f25f958c9a?result_data=True
2017-10-27 14:38:42,423 [virtwho.destination_4482547385105569854 DEBUG] MainProcess(21379):Thread-3 @subscriptionmanager.py:check_report_state:233 - Checking status of job hypervisor_update_0f3c3225-4873-47b6-9d6f-22f25f958c9a

3). if there is a 429 code, and Retry-After is setting to 10,  virt-who will waiting for 10 seconds to check the job state.
2017-10-27 14:49:06,472 [rhsm.connection INFO] MainProcess(22400):Thread-3 @connection.py:_request:552 - Response: status=429, request="GET /rhsm/jobs/hypervisor_update_183676be-091b-41e2-bcc8-350a0610b6b0?result_data=True"
2017-10-27 14:49:06,473 [virtwho.destination_4482547385105569854 DEBUG] MainProcess(22400):Thread-3 @virt.py:_send_data:652 - 429 encountered while checking job state, checking again in "10"

======== Waiting for 10 seconds and then check the job state again =================

2017-10-27 14:49:16,484 [rhsm.connection INFO] MainProcess(22400):Thread-3 @connection.py:__init__:822 - Connection built: http_proxy=bootp-73-131-133.rhts.eng.pek2.redhat.com:12345 host=bootp-73-131-133.rhts.eng.pek2.redhat.com port=443 handler=/rhsm auth=basic username=admin
2017-10-27 14:49:16,484 [virtwho.destination_4482547385105569854 DEBUG] MainProcess(22400):Thread-3 @subscriptionmanager.py:_connect:127 - Authenticating with RHSM username admin
2017-10-27 14:49:16,486 [rhsm.connection DEBUG] MainProcess(22400):Thread-3 @connection.py:_request:501 - Using proxy: bootp-73-131-133.rhts.eng.pek2.redhat.com:12345
2017-10-27 14:49:16,486 [rhsm.connection DEBUG] MainProcess(22400):Thread-3 @connection.py:_request:516 - Making request: GET /rhsm/status/
2017-10-27 14:49:16,767 [rhsm.connection INFO] MainProcess(22400):Thread-3 @connection.py:_request:552 - Response: status=200, request="GET /rhsm/status/"
2017-10-27 14:49:16,768 [rhsm.connection DEBUG] MainProcess(22400):Thread-3 @connection.py:_request:501 - Using proxy: bootp-73-131-133.rhts.eng.pek2.redhat.com:12345
2017-10-27 14:49:16,768 [rhsm.connection DEBUG] MainProcess(22400):Thread-3 @connection.py:_request:516 - Making request: GET /rhsm/jobs/hypervisor_update_183676be-091b-41e2-bcc8-350a0610b6b0?result_data=True
2017-10-27 14:49:16,768 [virtwho.destination_4482547385105569854 DEBUG] MainProcess(22400):Thread-3 @subscriptionmanager.py:check_report_state:233 - Checking status of job hypervisor_update_183676be-091b-41e2-bcc8-350a0610b6b0


4). if there is a 500 or 404 error code, virt-who will show the error message:
2017-10-27 14:50:03,587 [rhsm.connection INFO] MainProcess(22400):Thread-3 @connection.py:_request:552 - Response: status=500, request="GET /rhsm/jobs/hypervisor_update_183676be-091b-41e2-bcc8-350a0610b6b0?result_data=True"
2017-10-27 14:50:03,588 [virtwho.destination_4482547385105569854 ERROR] MainProcess(22400):Thread-3 @virt.py:_send_data:655 - Error during job check: 
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/virtwho/virt/virt.py", line 643, in _send_data
    self.dest.check_report_state(batch_host_guest_report)
  File "/usr/lib/python2.7/site-packages/virtwho/manager/subscriptionmanager/subscriptionmanager.py", line 242, in check_report_state
    raise ManagerError("Communication with subscription manager failed with code %d: %s" % (e.code, str(e)))
ManagerError: Communication with subscription manager failed with code 500:

Comment 8 errata-xmlrpc 2017-11-30 15:51:03 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2017:3314

Note You need to log in before you can comment on or make changes to this bug.