Bug 1309165 - virt-who trigger event can't send the report to server immediately for ESX and KVM
virt-who trigger event can't send the report to server immediately for ESX an...
Status: CLOSED ERRATA
Product: Red Hat Enterprise Linux 6
Classification: Red Hat
Component: virt-who (Show other bugs)
6.8
x86_64 Linux
medium Severity medium
: rc
: ---
Assigned To: Radek Novacek
Eko
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2016-02-16 22:31 EST by Eko
Modified: 2016-11-30 19:35 EST (History)
4 users (show)

See Also:
Fixed In Version: virt-who-0.16-5.el6
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2016-05-10 19:57:33 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


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


External Trackers
Tracker ID Priority Status Summary Last Updated
Red Hat Product Errata RHEA-2016:0859 normal SHIPPED_LIVE virt-who bug fix and enhancement update 2016-05-10 18:44:47 EDT

  None (edit)
Description Eko 2016-02-16 22:31:32 EST
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@vsphere.local
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 09:34:55 EST
Fixed in virt-who-0.16-5.el6.
Comment 4 Liushihui 2016-03-01 04:13:16 EST
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 08:16:45 EDT
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 02:05:46 EDT
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 02:06 EDT
Created attachment 1136847 [details]
virt-who log
Comment 8 Radek Novacek 2016-03-22 10:00:25 EDT
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-23 22:23:14 EDT
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 19:57:33 EDT
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.