Bug 1309165

Fixed in virt-who-0.16-5.el6.

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

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?

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?

Created attachment 1136847 [details]
virt-who log

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?

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

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