Bug 1230041

There is a limit of maximal time that virt-who can wait for ESX event. It's limited by ESX configuration and TCP connection timeout. It would be possible to start new wait right after this timeout and don't send the report if nothing have changed.

I don't see this issue as critical, moving to 6.8.

There will be significant change how the interval works in following version of virt-who:

https://github.com/virt-who/virt-who/wiki/Interval-changes

It means that this bug can't be fixed directly and it might not apply to the new version.

I will let this bug open to check if the new behaviour is appropriate.

Fixed by rebase to virt-who-0.16-1.el6.

*** Bug 1308786 has been marked as a duplicate of this bug. ***

this issue can be duplicated in virt-who-0.16-3.el6.noarch,the interval value is 3600s, but the really loop time is 900s.

1. config VIRTWHO_INTERVAL to 3600, such as:
VIRTWHO_INTERVAL=3600
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
# /etc/init.d/virt-who restart

3. check rhsm.log
# tail -f /var/log/rhsm/rhsm.log
2016-02-16 11:46:34,541 [virtwho.init INFO] MainProcess(5322):MainThread @virtwho.py:parseOptions:630 - Using reporter_id='hp-z220-09.qe.lab.eng.nay.redhat.com'
2016-02-16 11:46:34,543 [virtwho.init INFO] MainProcess(5322):MainThread @virtwho.py:main:721 - Using configuration "env/cmdline" ("esx" mode)
2016-02-16 11:46:34,544 [virtwho.main DEBUG] MainProcess(5322):MainThread @virtwho.py:run:229 - Starting infinite loop with 3600 seconds interval
2016-02-16 11:46:34,646 [virtwho.env_cmdline DEBUG] Esx-1(5329):MainThread @virt.py:run:358 - Virt backend 'env/cmdline' started
2016-02-16 11:46:34,647 [virtwho.env_cmdline DEBUG] Esx-1(5329):MainThread @esx.py:_prepare:55 - Log into ESX
2016-02-16 11:46:34,967 [virtwho.env_cmdline DEBUG] Esx-1(5329):MainThread @esx.py:_prepare:58 - Creating ESX event filter
2016-02-16 11:46:35,115 [virtwho.env_cmdline DEBUG] Esx-1(5329):MainThread @virt.py:enqueue:351 - Report gathered, putting to queue for sending
2016-02-16 11:46:35,115 [virtwho.env_cmdline DEBUG] Esx-1(5329):MainThread @esx.py:_run:150 - Waiting for ESX changes
2016-02-16 11:46:35,130 [virtwho.main DEBUG] MainProcess(5322):MainThread @subscriptionmanager.py:_connect:121 - Authenticating with certificate: /etc/pki/consumer/cert.pem
2016-02-16 11:46:35,357 [virtwho.main DEBUG] MainProcess(5322):MainThread @subscriptionmanager.py:hypervisorCheckIn:162 - Checking if server has capability 'hypervisor_async'
2016-02-16 11:46:35,545 [virtwho.main DEBUG] MainProcess(5322):MainThread @subscriptionmanager.py:hypervisorCheckIn:174 - Server does not have 'hypervisors_async' capability
2016-02-16 11:46:35,546 [virtwho.main INFO] MainProcess(5322):MainThread @subscriptionmanager.py:hypervisorCheckIn:185 - Sending update in hosts-to-guests mapping for config "env/cmdline": 1 hypervisors and 1 guests found
2016-02-16 11:46:35,547 [virtwho.main DEBUG] MainProcess(5322):MainThread @subscriptionmanager.py:hypervisorCheckIn:186 - Host-to-guest mapping: {
    "3e504d56-3982-037b-f3e6-669289892fa1": [
        {
            "guestId": "42064eca-44da-56fa-1946-9b6f6cb67dab", 
            "state": 5, 
            "attributes": {
                "active": 0, 
                "hypervisorVersion": "6.0.0", 
                "virtWhoType": "esx", 
                "hypervisorType": "VMware ESXi"
            }
        }
    ]
}
2016-02-16 11:46:35,812 [virtwho.main DEBUG] MainProcess(5322):MainThread @virtwho.py:send_current_report:159 - Report for config "env/cmdline" sent

=============== loop each 15 minutes, not 60 minutes =================
2016-02-16 12:01:35,217 [virtwho.env_cmdline DEBUG] Esx-1(5329):MainThread @esx.py:_run:150 - Waiting for ESX changes
2016-02-16 12:16:35,270 [virtwho.env_cmdline DEBUG] Esx-1(5329):MainThread @esx.py:_run:150 - Waiting for ESX changes
2016-02-16 12:31:35,350 [virtwho.env_cmdline DEBUG] Esx-1(5329):MainThread @esx.py:_run:150 - Waiting for ESX changes

Do you mean that the problem is that this is logged each 15 minutes?

2016-02-16 12:31:35,350 [virtwho.env_cmdline DEBUG] Esx-1(5329):MainThread @esx.py:_run:150 - Waiting for ESX changes

There is not much we can do about it. This is property of ESX, client needs to reconnect before the connection times out. All I can do is to hide the message but I don't think it is necessary, it's just a debug message after all.

virt-who should now show debug message once for each `interval` + time of getting the update itself. This applied for all hypervisors including those with event listening (libvirt and esx).

Implemented in virt-who-0.16-6.el6.

Verified it on virt-who-0.16-7.el6.noarch since virt-who will show debug info when up to long interval time(3600s), Therefore, verify it.

Verified version:
virt-who-0.16-7.el6.noarch
python-rhsm-1.16.6-1.el6.x86_64
subscription-manager-1.16.8-4.el6.x86_64

Verified process:
1. Register system to satellite6.1
2. Configure virt-who run at esx mode and refresh interval is 3600s
[root@intel-piketon-01 ~]# cat /etc/sysconfig/virt-who  | grep -v ^# | grep -v ^$
VIRTWHO_DEBUG=1
VIRTWHO_INTERVAL=3600
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!
3. Restart virt-who and check virt-who's log
2016-03-16 02:32:47,636 [virtwho.main INFO] MainProcess(27656):MainThread @subscriptionmanager.py:hypervisorCheckIn:185 - Sending update in hosts-to-guests mapping for config "env/cmdline": 1 hypervisors and 1 guests found
2016-03-16 02:32:47,637 [virtwho.main DEBUG] MainProcess(27656):MainThread @subscriptionmanager.py:hypervisorCheckIn:186 - Host-to-guest mapping: {
    "86b2bd00-8bad-11e2-87f4-6c3be514699d": [
        {
            "guestId": "42060bb0-044b-dd8c-c111-361bb5b2f78c", 
            "state": 5, 
            "attributes": {
                "active": 0, 
                "hypervisorVersion": "6.0.0", 
                "virtWhoType": "esx", 
                "hypervisorType": "VMware ESXi"
            }
        }
    ]
}
2016-03-16 02:32:47,903 [virtwho.main DEBUG] MainProcess(27656):MainThread @virtwho.py:send_report:161 - Report for config "env/cmdline" sent
=============After 3600s,virt-who show debug info in the log===========
2016-03-16 03:32:48,918 [virtwho.env_cmdline DEBUG] Esx-1(27665):MainThread @virt.py:enqueue:351 - Report for config "env/cmdline" gathered, putting to queue for sending
2016-03-16 03:32:48,924 [virtwho.main INFO] MainProcess(27656):MainThread @virtwho.py:run:309 - Report for config "env/cmdline" hasn't changed, not sending

Result:
Virt-who send debug info after 3600s.

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