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 1309165 - virt-who trigger event can't send the report to server immediately for ESX and KVM
Summary: virt-who trigger event can't send the report to server immediately for ESX an...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 6
Classification: Red Hat
Component: virt-who
Version: 6.8
Hardware: x86_64
OS: Linux
medium
medium
Target Milestone: rc
: ---
Assignee: Radek Novacek
QA Contact: Eko
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-02-17 03:31 UTC by Eko
Modified: 2016-12-01 00:35 UTC (History)
4 users (show)

Fixed In Version: virt-who-0.16-5.el6
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-05-10 23:57:33 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)
virt-who log (34.34 KB, text/plain)
2016-03-16 06:06 UTC, Liushihui 		no flags Details
View All


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHEA-2016:0859 0 normal SHIPPED_LIVE virt-who bug fix and enhancement update 2016-05-10 22:44:47 UTC

Description Eko 2016-02-17 03:31:32 UTC 
Description of problem:
for esx and kvm hypervisor, if the host/guest have some changes, virt-who will be triggered by auto and can find the message such as "Report gathered, putting to queue for sending" from rhsm.log, but still need to wait for 60 seconds to send the latest mapping info to server.

Version-Release number of selected component (if applicable):
RHEL-6.8-20160212.2 + ESX + Satellite
virt-who-0.16-3.el6.noarch
subscription-manager-1.16.8-2.el6.x86_64

How reproducible:
always

Steps to Reproduce:
1. config virt-who such as 120s interval time
VIRTWHO_INTERVAL=120
VIRTWHO_ESX=1
VIRTWHO_ESX_OWNER=ACME_Corporation
VIRTWHO_ESX_ENV=Library
VIRTWHO_ESX_SERVER=10.73.2.95
VIRTWHO_ESX_USERNAME=Administrator
VIRTWHO_ESX_PASSWORD=Welcome1!

2. restart virt-who service
# service virt-who restart

3. check rhsm.log, virt-who will loop with 120s interval
2016-02-17 10:58:24,291 [virtwho.init INFO] MainProcess(25062):MainThread @virtwho.py:parseOptions:630 - Using reporter_id='hp-z220-09.qe.lab.eng.nay.redhat.com'
2016-02-17 10:58:24,293 [virtwho.init INFO] MainProcess(25062):MainThread @virtwho.py:main:721 - Using configuration "env/cmdline" ("esx" mode)
2016-02-17 10:58:24,313 [virtwho.main DEBUG] MainProcess(25064):MainThread @virtwho.py:run:229 - Starting infinite loop with 120 seconds interval
2016-02-17 10:58:24,417 [virtwho.env_cmdline DEBUG] Esx-1(25072):MainThread @virt.py:run:358 - Virt backend 'env/cmdline' started
2016-02-17 10:58:24,418 [virtwho.env_cmdline DEBUG] Esx-1(25072):MainThread @esx.py:_prepare:55 - Log into ESX
2016-02-17 10:58:24,737 [virtwho.env_cmdline DEBUG] Esx-1(25072):MainThread @esx.py:_prepare:58 - Creating ESX event filter
2016-02-17 10:58:24,930 [virtwho.env_cmdline DEBUG] Esx-1(25072):MainThread @virt.py:enqueue:351 - Report gathered, putting to queue for sending
2016-02-17 10:58:24,931 [virtwho.env_cmdline DEBUG] Esx-1(25072):MainThread @esx.py:_run:150 - Waiting for ESX changes
2016-02-17 10:58:24,950 [virtwho.main DEBUG] MainProcess(25064):MainThread @subscriptionmanager.py:_connect:121 - Authenticating with certificate: /etc/pki/consumer/cert.pem
2016-02-17 10:58:25,167 [virtwho.main DEBUG] MainProcess(25064):MainThread @subscriptionmanager.py:hypervisorCheckIn:162 - Checking if server has capability 'hypervisor_async'
2016-02-17 10:58:25,367 [virtwho.main DEBUG] MainProcess(25064):MainThread @subscriptionmanager.py:hypervisorCheckIn:174 - Server does not have 'hypervisors_async' capability
2016-02-17 10:58:25,368 [virtwho.main INFO] MainProcess(25064):MainThread @subscriptionmanager.py:hypervisorCheckIn:185 - Sending update in hosts-to-guests mapping for config "env/cmdline": 2 hypervisors and 2 guests found
2016-02-17 10:58:25,368 [virtwho.main DEBUG] MainProcess(25064):MainThread @subscriptionmanager.py:hypervisorCheckIn:186 - Host-to-guest mapping: {
    "3e504d56-3982-037b-f3e6-669289892fa1": [
        {
            "guestId": "42064eca-44da-56fa-1946-9b6f6cb67dab", 
            "state": 1, 
            "attributes": {
                "active": 1, 
                "hypervisorVersion": "6.0.0", 
                "virtWhoType": "esx", 
                "hypervisorType": "VMware ESXi"
            }
        }
    ], 
    "60554d56-20cb-f25e-7ab9-33e7e330dc15": [
        {
            "guestId": "42065514-90a0-35f6-eac6-a146cb989491", 
            "state": 1, 
            "attributes": {
                "active": 1, 
                "hypervisorVersion": "6.0.0", 
                "virtWhoType": "esx", 
                "hypervisorType": "VMware ESXi"
            }
        }
    ]
}
2016-02-17 10:58:25,696 [virtwho.main DEBUG] MainProcess(25064):MainThread @virtwho.py:send_current_report:159 - Report for config "env/cmdline" sent
2016-02-17 11:00:25,002 [virtwho.env_cmdline DEBUG] Esx-1(25072):MainThread @esx.py:_run:150 - Waiting for ESX changes
2016-02-17 11:02:25,071 [virtwho.env_cmdline DEBUG] Esx-1(25072):MainThread @esx.py:_run:150 - Waiting for ESX changes
2016-02-17 11:04:25,135 [virtwho.env_cmdline DEBUG] Esx-1(25072):MainThread @esx.py:_run:150 - Waiting for ESX changes
2016-02-17 11:06:25,206 [virtwho.env_cmdline DEBUG] Esx-1(25072):MainThread @esx.py:_run:150 - Waiting for ESX changes


4. make the host/guests changes, suspend a guest and check rhsm.log
2016-02-17 11:21:09,619 [virtwho.env_cmdline DEBUG] Esx-1(25072):MainThread @esx.py:_run:150 - Waiting for ESX changes

========== Trigger notification immediately ==============
2016-02-17 11:21:49,034 [virtwho.env_cmdline DEBUG] Esx-1(25072):MainThread @virt.py:enqueue:351 - Report gathered, putting to queue for sending
2016-02-17 11:21:49,034 [virtwho.env_cmdline DEBUG] Esx-1(25072):MainThread @esx.py:_run:150 - Waiting for ESX changes

========== Wait for 120s to send the report ==============
2016-02-17 11:23:10,466 [virtwho.main DEBUG] MainProcess(25064):MainThread @subscriptionmanager.py:_connect:121 - Authenticating with certificate: /etc/pki/consumer/cert.pem
2016-02-17 11:23:10,941 [virtwho.main DEBUG] MainProcess(25064):MainThread @subscriptionmanager.py:hypervisorCheckIn:162 - Checking if server has capability 'hypervisor_async'
2016-02-17 11:23:11,142 [virtwho.main DEBUG] MainProcess(25064):MainThread @subscriptionmanager.py:hypervisorCheckIn:174 - Server does not have 'hypervisors_async' capability
2016-02-17 11:23:11,143 [virtwho.main INFO] MainProcess(25064):MainThread @subscriptionmanager.py:hypervisorCheckIn:185 - Sending update in hosts-to-guests mapping for config "env/cmdline": 2 hypervisors and 2 guests found
2016-02-17 11:23:11,143 [virtwho.main DEBUG] MainProcess(25064):MainThread @subscriptionmanager.py:hypervisorCheckIn:186 - Host-to-guest mapping: {
    "3e504d56-3982-037b-f3e6-669289892fa1": [
        {
            "guestId": "42064eca-44da-56fa-1946-9b6f6cb67dab", 
            "state": 3, 
            "attributes": {
                "active": 1, 
                "hypervisorVersion": "6.0.0", 
                "virtWhoType": "esx", 
                "hypervisorType": "VMware ESXi"
            }
        }
    ], 
    "60554d56-20cb-f25e-7ab9-33e7e330dc15": [
        {
            "guestId": "42065514-90a0-35f6-eac6-a146cb989491", 
            "state": 3, 
            "attributes": {
                "active": 1, 
                "hypervisorVersion": "6.0.0", 
                "virtWhoType": "esx", 
                "hypervisorType": "VMware ESXi"
            }
        }
    ]
}
2016-02-17 11:23:11,462 [virtwho.main DEBUG] MainProcess(25064):MainThread @virtwho.py:send_current_report:159 - Report for config "env/cmdline" sent


Actual results:
if the host/guest have some changes, virt-who will be triggered by auto and can find the message such as "Report gathered, putting to queue for sending" from rhsm.log, but still need to wait for 120 seconds to send the latest mapping info to server.

Expected results:
if rhsm.log shows the trigger event notification message, the latest host/guests report should be sent to server at the same time, no 120 seconds delay. 

Additional info:
Comment 2 Radek Novacek 2016-02-23 14:34:55 UTC 
Fixed in virt-who-0.16-5.el6.
Comment 4 Liushihui 2016-03-01 09:13:16 UTC 
Reopen it on virt-who-0.16-5.el6.noarch since virt-who trigger event still can't send the report to server immediately. it still need to wait over 10s, sometimes even over 30s, please see the detail log as the following:

2016-02-26 14:38:01,588 [virtwho.test-esx1 DEBUG] Esx-1(26185):MainThread @virt.py:enqueue:351 - Report gathered, putting to queue for sending
2016-02-26 14:38:01,588 [virtwho.test-esx1 DEBUG] Esx-1(26185):MainThread @esx.py:_run:150 - Waiting for ESX changes
2016-02-26 14:38:01,590 [virtwho.main INFO] MainProcess(26177):MainThread @virtwho.py:run:305 - Report for config "test-esx1" haven't changed, not sending
2016-02-26 14:38:01,666 [virtwho.test-esx1 DEBUG] Esx-1(26185):MainThread @esx.py:getHostGuestMapping:196 - Guest 'vm-43' doesn't have 'config.uuid' property
2016-02-26 14:38:01,666 [virtwho.test-esx1 DEBUG] Esx-1(26185):MainThread @virt.py:enqueue:351 - Report gathered, putting to queue for sending
2016-02-26 14:38:01,666 [virtwho.test-esx1 DEBUG] Esx-1(26185):MainThread @esx.py:_run:150 - Waiting for ESX changes
2016-02-26 14:38:01,669 [virtwho.main INFO] MainProcess(26177):MainThread @virtwho.py:run:305 - Report for config "test-esx1" haven't changed, not sending
2016-02-26 14:38:02,418 [virtwho.test-esx1 DEBUG] Esx-1(26185):MainThread @virt.py:enqueue:351 - Report gathered, putting to queue for sending
2016-02-26 14:38:02,418 [virtwho.test-esx1 DEBUG] Esx-1(26185):MainThread @esx.py:_run:150 - Waiting for ESX changes
==============During this time, esx guest has been updated===============
=======trigger event hasn't detect it immediately==============================
2016-02-26 14:38:36,055 [virtwho.main DEBUG] MainProcess(26177):MainThread @subscriptionmanager.py:_connect:121 - Authenticating with certificate: /etc/pki/consumer/cert.pem
2016-02-26 14:38:41,078 [virtwho.main DEBUG] MainProcess(26177):MainThread @subscriptionmanager.py:hypervisorCheckIn:162 - Checking if server has capability 'hypervisor_async'
2016-02-26 14:38:46,778 [virtwho.main DEBUG] MainProcess(26177):MainThread @subscriptionmanager.py:hypervisorCheckIn:174 - Server does not have 'hypervisors_async' capability
2016-02-26 14:38:46,779 [virtwho.main INFO] MainProcess(26177):MainThread @subscriptionmanager.py:hypervisorCheckIn:185 - Sending update in hosts-to-guests mapping for config "test-esx1": 1 hypervisors and 1 guests found
2016-02-26 14:38:46,779 [virtwho.main DEBUG] MainProcess(26177):MainThread @subscriptionmanager.py:hypervisorCheckIn:186 - Host-to-guest mapping: {
    "77ea4d56-2176-2518-74f6-d350749401dd": [
        {
            "guestId": "422fabb5-5167-cba5-7287-bf0348696c81", 
            "state": 5, 
            "attributes": {
                "active": 0, 
                "hypervisorVersion": "6.0.0", 
                "virtWhoType": "esx", 
                "hypervisorType": "VMware ESXi"
            }
        }
    ]
}
2016-02-26 14:38:53,889 [virtwho.main DEBUG] MainProcess(26177):MainThread @virtwho.py:send_current_report:159 - Report for config "test-esx1" sent
2016-02-26 14:39:02,485 [virtwho.test-esx1 DEBUG] Esx-1(26185):MainThread @esx.py:_run:150 - Waiting for ESX changes
Comment 5 Radek Novacek 2016-03-15 12:16:45 UTC 
This might be caused by rate-limit in candlepin. There should always be at least 60 seconds between two reports for candlepin (except when virt-who is starting). But as the beginning of the log is not there, I can't tell for sure.

Can you please make sure that the delay you're observing is not caused by the rate limit? Can you post whole log here?
Comment 6 Liushihui 2016-03-16 06:05:46 UTC 
Sorry, Radek, I'm not sure how to check rate-limit in satellite6.1(candlepin-0.9.49.9-1.el7.noarch). could you help to check the virt-who's whole log on virt-who-0.16-7.el6.noarch in attachment?
Comment 7 Liushihui 2016-03-16 06:06:43 UTC 
Created attachment 1136847 [details]
virt-who log
Comment 8 Radek Novacek 2016-03-22 14:00:25 UTC 
Sorry, I expressed myself incorrectly, I meant virt-who rate-limit. virt-who now doesn't send reports often than once each 60 seconds (expect for virt-who start).

There should always be at least 60 seconds between two "Sending update in hosts-to-guests mapping for config" lines in the log file. If an event occurs less than 60 seconds from last report, it will be processed when the 60 second timeout ends.

Is it more clear now?
Comment 9 Liushihui 2016-03-24 02:23:14 UTC 
Yes, it's clear now.

Verified it on virt-who-0.16-7.el6 since virt-who trigger event can send the report to server in ESX and KVM mode. The phenomenon is as the following:
1. When trigger event occurred less than 60 seconds from last report, it will be processed when the 60 second timeout ends. There always be at least 60 seconds between two "Sending update in hosts-to-guests mapping for config" lines in the log file. However, when the event occurred, it will show some notice in the log immediately.

2016-03-23 22:10:47,164 [virtwho.main DEBUG] MainProcess(24519):MainThread @virtwho.py:run:231 - Starting infinite loop with 200 seconds interval
2016-03-23 22:10:47,346 [virtwho.env_cmdline DEBUG] Libvirtd-1(24527):MainThread @virt.py:run:358 - Virt backend 'env/cmdline' started
2016-03-23 22:10:47,348 [virtwho.env_cmdline INFO] Libvirtd-1(24527):MainThread @libvirtd.py:_connect:156 - Using libvirt url: ""
2016-03-23 22:10:47,398 [virtwho.env_cmdline DEBUG] Libvirtd-1(24527):MainThread @libvirtd.py:_listDomains:244 - Libvirt domains found: 9bc436d8-20cf-711c-4056-d30f8c709a0f
2016-03-23 22:10:47,399 [virtwho.env_cmdline DEBUG] Libvirtd-1(24527):MainThread @virt.py:enqueue:351 - Report for config "env/cmdline" gathered, putting to queue for sending
2016-03-23 22:10:47,421 [virtwho.main DEBUG] MainProcess(24519):MainThread @subscriptionmanager.py:_connect:121 - Authenticating with certificate: /etc/pki/consumer/cert.pem
2016-03-23 22:10:47,923 [virtwho.main INFO] MainProcess(24519):MainThread @subscriptionmanager.py:sendVirtGuests:147 - Sending update in guests lists for config "env/cmdline": 1 guests found
2016-03-23 22:10:47,923 [virtwho.main DEBUG] MainProcess(24519):MainThread @subscriptionmanager.py:sendVirtGuests:148 - Domain info: [
    {
        "guestId": "9bc436d8-20cf-711c-4056-d30f8c709a0f", 
        "state": 5, 
        "attributes": {
            "active": 0, 
            "hypervisorVersion": "0.12.1", 
            "virtWhoType": "libvirt", 
            "hypervisorType": "QEMU"
        }
    }
]

===================Notice info=========================================
2016-03-23 22:10:49,893 [virtwho.main DEBUG] MainProcess(24519):MainThread @virtwho.py:send_report:161 - Report for config "env/cmdline" sent
2016-03-23 22:11:01,431 [virtwho.env_cmdline DEBUG] Libvirtd-1(24527):libvirtEventLoop @libvirtd.py:_listDomains:244 - Libvirt domains found: 9bc436d8-20cf-711c-4056-d30f8c709a0f
2016-03-23 22:11:01,432 [virtwho.env_cmdline DEBUG] Libvirtd-1(24527):libvirtEventLoop @virt.py:enqueue:351 - Report for config "env/cmdline" gathered, putting to queue for sending
========================================================================

*****************Update info, after 60s since last update ****************
2016-03-23 22:11:49,944 [virtwho.main DEBUG] MainProcess(24519):MainThread @subscriptionmanager.py:_connect:121 - Authenticating with certificate: /etc/pki/consumer/cert.pem
2016-03-23 22:11:50,425 [virtwho.main INFO] MainProcess(24519):MainThread @subscriptionmanager.py:sendVirtGuests:147 - Sending update in guests lists for config "env/cmdline": 1 guests found
2016-03-23 22:11:50,425 [virtwho.main DEBUG] MainProcess(24519):MainThread @subscriptionmanager.py:sendVirtGuests:148 - Domain info: [
    {
        "guestId": "9bc436d8-20cf-711c-4056-d30f8c709a0f", 
        "state": 1, 
        "attributes": {
            "active": 1, 
            "hypervisorVersion": "0.12.1", 
            "virtWhoType": "libvirt", 
            "hypervisorType": "QEMU"
        }
    }
]
2016-03-23 22:11:52,446 [virtwho.main DEBUG] MainProcess(24519):MainThread @virtwho.py:send_report:161 - Report for config "env/cmdline" sent
**************************************************************************

2. When trigger event occurred over 60 seconds from last report(it usually occurred when virt-who refresh interval bigger than 60s), virt-who will send the mapping info immediately.
2016-03-23 22:13:59,153 [virtwho.env_cmdline DEBUG] Libvirtd-1(24527):libvirtEventLoop @libvirtd.py:_listDomains:244 - Libvirt domains found: 9bc436d8-20cf-711c-4056-d30f8c709a0f
2016-03-23 22:13:59,154 [virtwho.env_cmdline DEBUG] Libvirtd-1(24527):libvirtEventLoop @virt.py:enqueue:351 - Report for config "env/cmdline" gathered, putting to queue for sending
2016-03-23 22:13:59,162 [virtwho.main DEBUG] MainProcess(24519):MainThread @subscriptionmanager.py:_connect:121 - Authenticating with certificate: /etc/pki/consumer/cert.pem
2016-03-23 22:13:59,645 [virtwho.main INFO] MainProcess(24519):MainThread @subscriptionmanager.py:sendVirtGuests:147 - Sending update in guests lists for config "env/cmdline": 1 guests found
2016-03-23 22:13:59,645 [virtwho.main DEBUG] MainProcess(24519):MainThread @subscriptionmanager.py:sendVirtGuests:148 - Domain info: [
    {
        "guestId": "9bc436d8-20cf-711c-4056-d30f8c709a0f", 
        "state": 5, 
        "attributes": {
            "active": 0, 
            "hypervisorVersion": "0.12.1", 
            "virtWhoType": "libvirt", 
            "hypervisorType": "QEMU"
        }
    }
]
2016-03-23 22:14:01,498 [virtwho.main DEBUG] MainProcess(24519):MainThread @virtwho.py:send_report:161 - Report for config "env/cmdline" sent
Comment 11 errata-xmlrpc 2016-05-10 23:57:33 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://rhn.redhat.com/errata/RHEA-2016-0859.html
Note You need to log in before you can comment on or make changes to this bug.