Description of problem: python-rhsm is returning wrong association When delete the last guest in host. Version-Release number of selected component (if applicable): subscription-manager-1.1.22-1.el6.x86_64 virt-who-0.8-5.el6.noarch python-rhsm-1.1.8-1.el6.x86_64 katello-glue-candlepin-1.2.1-14h.el6_3.noarch katello-configure-1.2.3-2h.el6_3.noarch katello-candlepin-cert-key-pair-1.0-1.noarch katello-headpin-1.2.1-14h.el6_3.noarch katello-cli-common-1.2.1-12h.el6_3.noarch katello-certs-tools-1.2.1-1h.el6_3.noarch katello-common-1.2.1-14h.el6_3.noarch katello-cli-1.2.1-12h.el6_3.noarch katello-selinux-1.2.1-2h.el6_3.noarch katello-headpin-all-1.2.1-14h.el6_3.noarch candlepin-0.7.23-1.el6_3.noarch candlepin-tomcat6-0.7.23-1.el6_3.noarch How reproducible: always Steps to Reproduce: 1.Install ESX host1 and host2 2.Install guest1 in host1 (Only 1 guest exist) 3.Register ESX host1 to SAM via virt-who in RHEL6.4 snapshot 4 4.Delete guest1 from host1, check log info in /var/log/rhsm/rhsm.log Actual results: Even though no more guest exist in host1, guest1 UUID still exist in "Update host" INFO for host1, see following log in /var/log/rhsm/rhsm.log 2013-01-22 12:06:55,817 [WARNING] @virt-who.py:462 - Listening for events is not available in VDSM, ESX, RHEV-M or Hyper-V mode 2013-01-22 12:07:01,470 [DEBUG] @virt-who.py:475 - Virt-who is running in esx mode 2013-01-22 12:07:01,470 [DEBUG] @virt-who.py:482 - Starting infinite loop with 360 seconds interval and event handling 2013-01-22 12:07:02,764 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4c00-1031-8053-b8c04f4e3258: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 4209faec-6c96-7bb3-d0f5-e5861a16479a, 42094dad-ed2d-03d4-ed91-b538c886a424], 44454c4c-4200-1034-8039-b8c04f503258: []} 2013-01-22 12:07:02,968 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 4209faec-6c96-7bb3-d0f5-e5861a16479a, 42094dad-ed2d-03d4-ed91-b538c886a424] ---------------------------------------------------------------------------- 2013-01-22 12:07:02,968 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4200-1034-8039-b8c04f503258 with guests: [42094dad-ed2d-03d4-ed91-b538c886a424] ---------------------------------------------------------------------------- Expected results: Since there's no guest in host1 any more, guest UUID should not exist for host1 in rhsm.log. ---------------------------------------------------------------------------- 2013-01-22 12:07:02,968 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4200-1034-8039-b8c04f503258 with guests: [] ---------------------------------------------------------------------------- Additional info: This bug exists in ESX, Hyperv, RHEL+RHEVM(rhevm mode) host/guest association.
This looks like a candlepin bug. The python-rhsm code seems to be doing the right thing (pretty thin wrapper around the request...). I think the problem is in candlepin in HypervisorResource.hypervisorCheckIn public HypervisorCheckInResult hypervisorCheckIn(...){ ... withIds.setGuestIds(guestIds); if (consumerResource.performConsumerUpdates(withIds, consumer)) { consumerCurator.update(consumer); } result.updated(consumer); ... return result; { Looks like updated consumers are always returned in the result['updated'] list, even if no guest consumer updates were required.
I can not seem to reproduce this issue when testing against candlepin directly. The code in comment 2 seems to be doing what it is designed to do -- report any host consumers (includes current guestIds), that have been 'checked', in the updated results. Perhaps the result could be a little more fine grained and could return 'unchanged', or something along those lines. That being said, the logs posted in the BZ description baffle me. Looking at them a little closer, you can see that virt-who shows that candlepin has reported that BOTH hosts have been associated with guest '42094dad-ed2d-03d4-ed91-b538c886a424'. Is there any chance of getting the candlepin logs from the SAM instance? It would be very helpful if candlepin logging was set to DEBUG, and the test retried. Thanks.
I retested this bug in ESX with candlepin logging set to DEBUG model. log4j.logger.org.candlepin=DEBUG >> /etc/candlepin/candlepin.conf candlepin logs attached in file catalina.out. Following is my test steps: 1. Add guest1(42091819-2060-b183-a38f-abf719aa2cb5) to ESX host1(44454c4c-4200-1034-8039-b8c04f503258) 2013-01-24 03:24:43,027 [WARNING] @virt-who.py:462 - Listening for events is not available in VDSM, ESX, RHEV-M or Hyper-V mode 2013-01-24 03:24:48,516 [DEBUG] @virt-who.py:475 - Virt-who is running in esx mode 2013-01-24 03:24:48,516 [DEBUG] @virt-who.py:482 - Starting infinite loop with 360 seconds interval and event handling 2013-01-24 03:24:49,856 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4c00-1031-8053-b8c04f4e3258: [42094dad-ed2d-03d4-ed91-b538c886a424, 4209faec-6c96-7bb3-d0f5-e5861a16479a, 4209c2b5-5f70-ac1e-3d72-52ee34fb854a], 44454c4c-4200-1034-8039-b8c04f503258: [42091819-2060-b183-a38f-abf719aa2cb5]} 2013-01-24 03:24:50,334 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [42094dad-ed2d-03d4-ed91-b538c886a424, 4209faec-6c96-7bb3-d0f5-e5861a16479a, 4209c2b5-5f70-ac1e-3d72-52ee34fb854a] 2013-01-24 03:24:50,334 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4200-1034-8039-b8c04f503258 with guests: [42091819-2060-b183-a38f-abf719aa2cb5] 2. Add guest1(42093e2e-e557-fdb6-7193-b13f203c32ec) to ESX host1(44454c4c-4200-1034-8039-b8c04f503258) 2013-01-24 03:26:33,182 [WARNING] @virt-who.py:462 - Listening for events is not available in VDSM, ESX, RHEV-M or Hyper-V mode 2013-01-24 03:26:38,654 [DEBUG] @virt-who.py:475 - Virt-who is running in esx mode 2013-01-24 03:26:38,662 [DEBUG] @virt-who.py:482 - Starting infinite loop with 360 seconds interval and event handling 2013-01-24 03:26:40,100 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4c00-1031-8053-b8c04f4e3258: [42094dad-ed2d-03d4-ed91-b538c886a424, 4209faec-6c96-7bb3-d0f5-e5861a16479a, 4209c2b5-5f70-ac1e-3d72-52ee34fb854a], 44454c4c-4200-1034-8039-b8c04f503258: [42091819-2060-b183-a38f-abf719aa2cb5, 42093e2e-e557-fdb6-7193-b13f203c32ec]} 2013-01-24 03:26:40,584 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [42094dad-ed2d-03d4-ed91-b538c886a424, 4209faec-6c96-7bb3-d0f5-e5861a16479a, 4209c2b5-5f70-ac1e-3d72-52ee34fb854a] 2013-01-24 03:26:40,585 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4200-1034-8039-b8c04f503258 with guests: [42091819-2060-b183-a38f-abf719aa2cb5, 42093e2e-e557-fdb6-7193-b13f203c32ec] 3. Delete guest2(42093e2e-e557-fdb6-7193-b13f203c32ec) from ESX host1(44454c4c-4200-1034-8039-b8c04f503258) 2013-01-24 03:27:17,595 [WARNING] @virt-who.py:462 - Listening for events is not available in VDSM, ESX, RHEV-M or Hyper-V mode 2013-01-24 03:27:23,159 [DEBUG] @virt-who.py:475 - Virt-who is running in esx mode 2013-01-24 03:27:23,159 [DEBUG] @virt-who.py:482 - Starting infinite loop with 360 seconds interval and event handling 2013-01-24 03:27:24,496 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4c00-1031-8053-b8c04f4e3258: [42094dad-ed2d-03d4-ed91-b538c886a424, 4209faec-6c96-7bb3-d0f5-e5861a16479a, 4209c2b5-5f70-ac1e-3d72-52ee34fb854a], 44454c4c-4200-1034-8039-b8c04f503258: [42091819-2060-b183-a38f-abf719aa2cb5]} 2013-01-24 03:27:24,904 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [42094dad-ed2d-03d4-ed91-b538c886a424, 4209faec-6c96-7bb3-d0f5-e5861a16479a, 4209c2b5-5f70-ac1e-3d72-52ee34fb854a] 2013-01-24 03:27:24,905 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4200-1034-8039-b8c04f503258 with guests: [42091819-2060-b183-a38f-abf719aa2cb5] 4. Delete guest1(42091819-2060-b183-a38f-abf719aa2cb5) from ESX host1(44454c4c-4200-1034-8039-b8c04f503258) 2013-01-24 03:28:08,000 [WARNING] @virt-who.py:462 - Listening for events is not available in VDSM, ESX, RHEV-M or Hyper-V mode 2013-01-24 03:28:13,477 [DEBUG] @virt-who.py:475 - Virt-who is running in esx mode 2013-01-24 03:28:13,477 [DEBUG] @virt-who.py:482 - Starting infinite loop with 360 seconds interval and event handling 2013-01-24 03:28:14,732 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4c00-1031-8053-b8c04f4e3258: [42094dad-ed2d-03d4-ed91-b538c886a424, 4209faec-6c96-7bb3-d0f5-e5861a16479a, 4209c2b5-5f70-ac1e-3d72-52ee34fb854a], 44454c4c-4200-1034-8039-b8c04f503258: []} 2013-01-24 03:28:15,045 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [42094dad-ed2d-03d4-ed91-b538c886a424, 4209faec-6c96-7bb3-d0f5-e5861a16479a, 4209c2b5-5f70-ac1e-3d72-52ee34fb854a] 2013-01-24 03:28:15,045 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4200-1034-8039-b8c04f503258 with guests: [42091819-2060-b183-a38f-abf719aa2cb5]
Created attachment 686427 [details] candlepin-log
By the way, my test environment as follows: SAM server: 10.66.12.132 virt-who : 10.66.12.125 [root@dhcp12-125 ~]# rpm -qa | grep subscription subscription-manager-1.1.22-1.el6.x86_64 [root@dhcp12-125 ~]# rpm -qa | grep python-rhsm python-rhsm-1.1.8-1.el6.x86_64 [root@dhcp12-125 ~]# rpm -qa | grep virt-who virt-who-0.8-5.el6.noarch [root@samserv tomcat6]# rpm -qa | grep candlepin katello-glue-candlepin-1.2.1-14h.el6_3.noarch katello-candlepin-cert-key-pair-1.0-1.noarch candlepin-0.7.23-1.el6_3.noarch candlepin-tomcat6-0.7.23-1.el6_3.noarch [root@samserv tomcat6]#
Thanks gaoshang ,, that helped. It looks like candlepin is receiving incorrect JSON data in the request, and not only when the last is deleted. for example: { "44454c4c-4200-1034-8039-b8c04f503258":null, "44454c4c-4c00-1031-8053-b8c04f4e3258":["42094dad-ed2d-03d4-ed91-b538c886a424","4209faec-6c96-7bb3-d0f5-e5861a16479a","4209c2b5-5f70-ac1e-3d72-52ee34fb854a"] } When candlepin receives the 'null' above, it ignores the guest ID update, and will return the guest ids that are currently associated with the host. This is not correct. I'd like to know if katello receives the same JSON as candlepin. We can enable debug logging for SAM to accomplish this. In /etc/katello/katello.yml set the following and restart SAM: log_level: debug log_level_sql: debug And re-run the test case. Then run: katello-debug and attach the resulting tar. I'm hoping this will be enough to at least pin-point the component that is producing the 'null' list in the request. Thanks.
(In reply to comment #8) > Thanks gaoshang ,, that helped. > > It looks like candlepin is receiving incorrect JSON data in the request, and > not only when the last is deleted. > > for example: > > { > "44454c4c-4200-1034-8039-b8c04f503258":null, > > "44454c4c-4c00-1031-8053-b8c04f4e3258":["42094dad-ed2d-03d4-ed91- > b538c886a424","4209faec-6c96-7bb3-d0f5-e5861a16479a","4209c2b5-5f70-ac1e- > 3d72-52ee34fb854a"] > } > > When candlepin receives the 'null' above, it ignores the guest ID update, > and will return the guest ids that are currently associated with the host. > This is not correct. > > I'd like to know if katello receives the same JSON as candlepin. We can > enable debug logging for SAM to accomplish this. > > In /etc/katello/katello.yml set the following and restart SAM: > log_level: debug > log_level_sql: debug > > And re-run the test case. > > Then run: katello-debug and attach the resulting tar. > > I'm hoping this will be enough to at least pin-point the component that is > producing the 'null' list in the request. > > Thanks. :), since we got new SAM compose(sam-1.2-20130123.n.0), I retested this bug against it. I runed katello-debug and attached the resulting tar. 1. Add guest1(4209ab4d-5e93-97f1-ec2d-92f404deefce) to ESX host1(44454c4c-4200-1034-8039-b8c04f503258) 2013-01-25 08:05:14,194 [WARNING] @virt-who.py:462 - Listening for events is not available in VDSM, ESX, RHEV-M or Hyper-V mode 2013-01-25 08:05:19,276 [DEBUG] @virt-who.py:475 - Virt-who is running in esx mode 2013-01-25 08:05:19,278 [DEBUG] @virt-who.py:482 - Starting infinite loop with 3600 seconds interval and event handling 2013-01-25 08:05:20,464 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4c00-1031-8053-b8c04f4e3258: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424], 44454c4c-4200-1034-8039-b8c04f503258: [4209ab4d-5e93-97f1-ec2d-92f404deefce]} 2013-01-25 08:05:20,720 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424] 2013-01-25 08:05:20,721 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4200-1034-8039-b8c04f503258 with guests: [4209ab4d-5e93-97f1-ec2d-92f404deefce] 2. Add guest2(4209774a-29ae-ab2c-f244-f477bc390332) to ESX host1(44454c4c-4200-1034-8039-b8c04f503258) 2013-01-25 08:06:22,658 [WARNING] @virt-who.py:462 - Listening for events is not available in VDSM, ESX, RHEV-M or Hyper-V mode 2013-01-25 08:06:27,523 [DEBUG] @virt-who.py:475 - Virt-who is running in esx mode 2013-01-25 08:06:27,523 [DEBUG] @virt-who.py:482 - Starting infinite loop with 3600 seconds interval and event handling 2013-01-25 08:06:28,789 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4c00-1031-8053-b8c04f4e3258: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424], 44454c4c-4200-1034-8039-b8c04f503258: [4209774a-29ae-ab2c-f244-f477bc390332, 4209ab4d-5e93-97f1-ec2d-92f404deefce]} 2013-01-25 08:06:29,137 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424] 2013-01-25 08:06:29,137 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4200-1034-8039-b8c04f503258 with guests: [4209774a-29ae-ab2c-f244-f477bc390332, 4209ab4d-5e93-97f1-ec2d-92f404deefce] 3. Delete guest2(4209774a-29ae-ab2c-f244-f477bc390332) from ESX host1(44454c4c-4200-1034-8039-b8c04f503258) 2013-01-25 08:06:52,014 [WARNING] @virt-who.py:462 - Listening for events is not available in VDSM, ESX, RHEV-M or Hyper-V mode 2013-01-25 08:06:58,749 [DEBUG] @virt-who.py:475 - Virt-who is running in esx mode 2013-01-25 08:06:58,749 [DEBUG] @virt-who.py:482 - Starting infinite loop with 3600 seconds interval and event handling 2013-01-25 08:07:00,141 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4c00-1031-8053-b8c04f4e3258: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424], 44454c4c-4200-1034-8039-b8c04f503258: [4209ab4d-5e93-97f1-ec2d-92f404deefce]} 2013-01-25 08:07:00,461 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424] 2013-01-25 08:07:00,461 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4200-1034-8039-b8c04f503258 with guests: [4209ab4d-5e93-97f1-ec2d-92f404deefce] 4. Delete guest1(4209ab4d-5e93-97f1-ec2d-92f404deefce) from ESX host1(44454c4c-4200-1034-8039-b8c04f503258) 2013-01-25 08:07:28,387 [WARNING] @virt-who.py:462 - Listening for events is not available in VDSM, ESX, RHEV-M or Hyper-V mode 2013-01-25 08:07:33,226 [DEBUG] @virt-who.py:475 - Virt-who is running in esx mode 2013-01-25 08:07:33,227 [DEBUG] @virt-who.py:482 - Starting infinite loop with 3600 seconds interval and event handling 2013-01-25 08:07:34,388 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4c00-1031-8053-b8c04f4e3258: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424], 44454c4c-4200-1034-8039-b8c04f503258: []} 2013-01-25 08:07:34,657 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424] 2013-01-25 08:07:34,658 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4200-1034-8039-b8c04f503258 with guests: [4209ab4d-5e93-97f1-ec2d-92f404deefce]
Created attachment 687218 [details] katello-debug
Since virt-who Errata will end by 2013 Jan 30, hope this bug could be fixed ASAP.
There's another issue which I think have the same root cause with this bug. See following details and hope it can help to reveal problem. [1].If there's no guest in ESX host, when the first time to register ESX host to SAM server by "service virt-who restart", got an ERROR and "Created host:" INFO missed. [root@gg-rhel6 ~]# service virt-who restart 2013-01-25 11:14:06,508 [WARNING] @virt-who.py:462 - Listening for events is not available in VDSM, ESX, RHEV-M or Hyper-V mode 2013-01-25 11:14:11,341 [DEBUG] @virt-who.py:475 - Virt-who is running in esx mode 2013-01-25 11:14:11,342 [DEBUG] @virt-who.py:482 - Starting infinite loop with 3600 seconds interval and event handling 2013-01-25 11:14:12,464 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4c00-1031-8053-b8c04f4e3258: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424], 44454c4c-4200-1034-8039-b8c04f503258: []} 2013-01-25 11:14:14,474 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424] -------------------------------------------------------------------------------- 2013-01-25 11:14:14,474 [ERROR] @virt-who.py:212 - Error in communication with subscription manager, trying to recover: Traceback (most recent call last): File "/usr/share/virt-who/virt-who.py", line 202, in _send guests = [x['guestId'] for x in updated['guestIds']] TypeError: 'NoneType' object is not iterable -------------------------------------------------------------------------------- 2013-01-25 11:14:15,623 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4c00-1031-8053-b8c04f4e3258: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424], 44454c4c-4200-1034-8039-b8c04f503258: []} 2013-01-25 11:14:15,849 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424] 2013-01-25 11:14:15,849 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4200-1034-8039-b8c04f503258 with guests: [] [2].If there's at least 1 guest in ESX host, the first time to register ESX host to SAM server by "service virt-who restart" is correct. Please pay attention to the 2 "Created host:" INFO. [root@gg-rhel6 ~]# service virt-who restart 2013-01-25 11:27:36,041 [WARNING] @virt-who.py:462 - Listening for events is not available in VDSM, ESX, RHEV-M or Hyper-V mode 2013-01-25 11:27:40,853 [DEBUG] @virt-who.py:475 - Virt-who is running in esx mode 2013-01-25 11:27:40,854 [DEBUG] @virt-who.py:482 - Starting infinite loop with 3600 seconds interval and event handling 2013-01-25 11:27:42,027 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4c00-1031-8053-b8c04f4e3258: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424], 44454c4c-4200-1034-8039-b8c04f503258: [420910ef-7ff8-7ada-e89c-0ffc1222004d]} 2013-01-25 11:27:43,611 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424] 2013-01-25 11:27:43,611 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4200-1034-8039-b8c04f503258 with guests: [420910ef-7ff8-7ada-e89c-0ffc1222004d] -------------------------------------------------------------------------------- 2013-01-25 11:27:43,612 [INFO] @virt-who.py:206 - Created host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424] 2013-01-25 11:27:43,612 [INFO] @virt-who.py:206 - Created host: 44454c4c-4200-1034-8039-b8c04f503258 with guests: [420910ef-7ff8-7ada-e89c-0ffc1222004d] --------------------------------------------------------------------------------
The logs I was looking for did not seem to be in the katello-debug/production.log Please set the following config values in katello.yml and retest. Please be sure the restart SAM. katello-service restart # # Development environment configuration # # The following configuration values override ones from the common section # development: debug_rest: true It would also be very useful if I could have access to your test machines. i.e the SAM server and the machine you are running virt-who on. Thanks!
1. set /etc/katello/katello.yml for log in SAM server (10.66.12.203). [root@samserv katello]# cat katello.yml | grep -A 4 "#Allowed log levels" #Allowed log levels: 'debug', 'info', 'warn', 'error', 'fatal' log_level: debug log_level_sql: debug #setup how often you want [root@samserv katello]# cat katello.yml | grep -A 4 "development:" development: debug_rest: true #debug_pulp_proxy: true #debug_cp_proxy: true 2. katello-service restart [root@samserv katello]# katello-service restart Shutting down Katello services... Stopping katello: Stopping elasticsearch: [ OK ] Stopping thumbslug: [ OK ] Stopping httpd: [ OK ] Stopping tomcat6: [ OK ] Done. Starting Katello services... Starting tomcat6: [ OK ] Starting httpd: [ OK ] Starting thumbslug: Jan 28 05:02:20 [main] WARN org.candlepin.thumbslug.Main - Shutting down... [ OK ] Starting elasticsearch: [ OK ] Starting katello: [ OK ] Starting katello-jobs: [ OK ] Done. [root@samserv katello]# 3. Prepare 2 ESX hosts, host1 have no guest, host2 have 2 guests, register ESX to SAM by virt-who (10.66.13.178). [root@gg-rhel6 ~]# subscription-manager register --user=admin --password=admin The system has been registered with id: a1e1d6c3-936d-4d2a-bcec-be927e640180 [root@gg-rhel6 ~]# service virt-who start Starting virt-who: [ OK ] [root@gg-rhel6 sysconfig]# tail -f /var/log/rhsm/rhsm.log 2013-01-28 13:03:19,192 [WARNING] @virt-who.py:462 - Listening for events is not available in VDSM, ESX, RHEV-M or Hyper-V mode 2013-01-28 13:03:24,490 [DEBUG] @virt-who.py:475 - Virt-who is running in esx mode 2013-01-28 13:03:24,491 [DEBUG] @virt-who.py:482 - Starting infinite loop with 3600 seconds interval and event handling 2013-01-28 13:03:25,603 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4c00-1031-8053-b8c04f4e3258: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424], 44454c4c-4200-1034-8039-b8c04f503258: []} 2013-01-28 13:03:27,945 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424] 2013-01-28 13:03:27,945 [ERROR] @virt-who.py:212 - Error in communication with subscription manager, trying to recover: Traceback (most recent call last): File "/usr/share/virt-who/virt-who.py", line 202, in _send guests = [x['guestId'] for x in updated['guestIds']] TypeError: 'NoneType' object is not iterable 2013-01-28 13:03:29,517 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4c00-1031-8053-b8c04f4e3258: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424], 44454c4c-4200-1034-8039-b8c04f503258: []} 2013-01-28 13:03:29,814 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424] 2013-01-28 13:03:29,814 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4200-1034-8039-b8c04f503258 with guests: [] 4. Add guest1 to host1 [root@gg-rhel6 ~]# service virt-who restart Stopping virt-who: [ OK ] Starting virt-who: [ OK ] [root@gg-rhel6 ~]# [root@gg-rhel6 sysconfig]# tail -f /var/log/rhsm/rhsm.log 2013-01-28 13:06:49,529 [WARNING] @virt-who.py:462 - Listening for events is not available in VDSM, ESX, RHEV-M or Hyper-V mode 2013-01-28 13:06:54,980 [DEBUG] @virt-who.py:475 - Virt-who is running in esx mode 2013-01-28 13:06:54,980 [DEBUG] @virt-who.py:482 - Starting infinite loop with 3600 seconds interval and event handling 2013-01-28 13:06:56,193 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4c00-1031-8053-b8c04f4e3258: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424], 44454c4c-4200-1034-8039-b8c04f503258: [4209920a-fab0-1b0c-6c2c-bd3465c33ecd]} 2013-01-28 13:06:56,478 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424] 2013-01-28 13:06:56,479 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4200-1034-8039-b8c04f503258 with guests: [4209920a-fab0-1b0c-6c2c-bd3465c33ecd] 5. Delete guest1 from host1 [root@gg-rhel6 ~]# service virt-who restart Stopping virt-who: [ OK ] Starting virt-who: [ OK ] [root@gg-rhel6 ~]# [root@gg-rhel6 sysconfig]# tail -f /var/log/rhsm/rhsm.log 2013-01-28 13:08:35,101 [WARNING] @virt-who.py:462 - Listening for events is not available in VDSM, ESX, RHEV-M or Hyper-V mode 2013-01-28 13:08:40,339 [DEBUG] @virt-who.py:475 - Virt-who is running in esx mode 2013-01-28 13:08:40,340 [DEBUG] @virt-who.py:482 - Starting infinite loop with 3600 seconds interval and event handling 2013-01-28 13:08:41,620 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4c00-1031-8053-b8c04f4e3258: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424], 44454c4c-4200-1034-8039-b8c04f503258: []} 2013-01-28 13:08:41,827 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424] 2013-01-28 13:08:41,828 [INFO] @virt-who.py:203 - Updated host: 44454c4c-4200-1034-8039-b8c04f503258 with guests: [4209920a-fab0-1b0c-6c2c-bd3465c33ecd] 6. Run katello-debug [root@samserv katello]# katello-debug detected deployment: headpin created directory /tmp/katello-debug-20130128052110 copying over /var/log/audit/audit.log copying over /var/log/httpd copying over /etc/httpd/conf.d copying over /var/log/katello copying over /etc/katello/client.conf copying over /etc/katello/katello.yml copying over /etc/katello/mapping.yml copying over /etc/katello/thin.yml copying over /etc/katello/katello-configure.conf copying over /etc/httpd/conf.d/katello.conf copying over /etc/katello/environment.rb copying over /var/log/elasticsearch copying over /etc/elasticsearch copying over /var/log/tomcat6 copying over /etc/candlepin/candlepin.conf copying over /etc/tomcat6/server.xml copying over /etc/thumbslug copying over /var/log/thumbslug A debug file has been created at /tmp/katello-debug-20130128052110.tar.gz. Make sure it contains no security sensitive data before making it public! [root@samserv katello]#
My test environment as follows: SAM server: 10.66.12.203 virt-who : 10.66.13.178 Log attached in file katello-debug-20130128052110.tar.gz, anything else needed please feel free to let me know, thanks.
Created attachment 688834 [details] katello-debug-20130128052110.tar.gz
Just noticed something interesting in a test case, if I create a new guest id and pass it None, the first time it creates a consumer with guestIds=None, if I do the same call again, then it becomes guestIds=[] For example: def test_hypervisor_double_none(self): timestamp = time.time() response = self.cp.hypervisorCheckIn("admin", "", {'%s-bloop' % timestamp :None, '%s-bloop' % timestamp:None}) pprint.pprint(response) response = self.cp.hypervisorCheckIn("admin", "", {'%s-bloop' % timestamp :None, '%s-bloop' % timestamp:None}) pprint.pprint(response) The first print is guestIds=None, the second guestIds=[] Not sure that's exactly what is wrong here, but it is odd, and might explain some of the difficulty reproducing this. Also, the more I look, I still think the code mentioned in comment #2 is wrong. We end up adding a consumer to result.update that has not been updated. So I'm starting to think this is actually two seperate but related candlepin bugs.
Nothing in comment 20 explains why we ar seeing hypervisor checkins with a guest map with {'host-uuid':None} however. The hypervisorCheckinResult with guestIds=None would explain the Traceback (most recent call last): File "/usr/share/virt-who/virt-who.py", line 202, in _send guests = [x['guestId'] for x in updated['guestIds']] TypeError: 'NoneType' object is not iterable We see in the attached logs once in a while. (aka, updated['guestIds'] is None, and of course, not iterable. πππππl
(In reply to comment #20) > Just noticed something interesting in a test case, if I create a new guest > id and > pass it None, the first time it creates a consumer with guestIds=None, if I > do the same call again, then it becomes guestIds=[] > > For example: > > def test_hypervisor_double_none(self): > timestamp = time.time() > response = self.cp.hypervisorCheckIn("admin", "", {'%s-bloop' % > timestamp :None, '%s-bloop' % timestamp:None}) > pprint.pprint(response) > response = self.cp.hypervisorCheckIn("admin", "", {'%s-bloop' % > timestamp :None, '%s-bloop' % timestamp:None}) > pprint.pprint(response) > > The first print is guestIds=None, the second guestIds=[] > > Not sure that's exactly what is wrong here, but it is odd, and might explain > some of the difficulty reproducing this. > > > Also, the more I look, I still think the code mentioned in comment #2 is > wrong. We end up adding a consumer to result.update that has not been > updated. So I'm starting to think this is actually two seperate but related > candlepin bugs. yes, I think that explains the ERROR in Comment 12 step 1: ------------------------------------------------------------------- 2013-01-25 11:14:14,474 [ERROR] @virt-who.py:212 - Error in communication with subscription manager, trying to recover: Traceback (most recent call last): File "/usr/share/virt-who/virt-who.py", line 202, in _send guests = [x['guestId'] for x in updated['guestIds']] TypeError: 'NoneType' object is not iterable ------------------------------------------------------------------- Due to this ERROR, "Created host" log missed, see the expected log in Comment 12 step2. I wonder whether it also because of this informal creation of guest1 that casued delete guest error.
(In reply to comment #23) > (In reply to comment #20) > > I wonder whether it also because of this informal creation of guest1 that > casued delete guest error. informal?
(In reply to comment #24) > (In reply to comment #23) > > (In reply to comment #20) > > > > > I wonder whether it also because of this informal creation of guest1 that > > casued delete guest error. > > informal? Sorry my mistake, it should be informal creation of host. when first run virt-who, it will register host to SAM server, following INFO should appear 2013-01-25 11:27:43,612 [INFO] @virt-who.py:206 - Created host: 44454c4c-4c00-1031-8053-b8c04f4e3258 with guests: [4209c2b5-5f70-ac1e-3d72-52ee34fb854a, 42094dad-ed2d-03d4-ed91-b538c886a424] But it missed when there's no guest in ESX host, please see Comment 12. By the way, can we discuss it via Xchat in case of any info needed.
We have found that the initial issue in this bug is *not* related to virt-who, or python-rhsm. It is due to an issue in rails (actionpack). The katello team are working to get this fixed. There was an update to rails that would set [] to nil when parsing paramaters from the request JSON. This would in turn be sent to candlepin, who would treat it as 'no updates required' for the host's guest ids. Ref: https://github.com/rails/rails/commit/97b3b68d3a8dc3979e74bec3921aeda69735eb6a As for the issue in comment 21, I believe this is a related but seperate issue and we should be able to fix it in candlepin. I'll leave this BZ as ASSIGNED until it is addressed.
the bugs outlined in comment 21 are fixed in: https://github.com/candlepin/candlepin/pull/171
Please test in the first SAM build after 1.2.1 which has candlepin of at least candlepin-0.7.25-1
(In reply to comment #32) > Please test in the first SAM build after 1.2.1 which has candlepin of at > least > > > candlepin-0.7.25-1 We'll verify it when new SAM compose arrives.
Verified it against RHEL6.4-server-x86_64-20130130.0 and RHEL5.10-Server-20130613.0 + ESX5.1 + SAM-1.3.0-RHEL-6-20130617.0, the bug mentioned in comment 21 does not exist any more, see following test steps: 1. Register rhel to SAM server [root@dhcp12-131 ~]# rpm -qa | grep virt-who virt-who-0.7-9.el5 [root@samserv ~]# rpm -qa | grep candlepin candlepin-scl-runtime-1-5.el6_4.noarch candlepin-scl-quartz-2.1.5-5.el6_4.noarch katello-glue-candlepin-1.4.2-13.el6sam_splice_2.noarch candlepin-0.8.9-1.el6_4.noarch candlepin-tomcat6-0.8.9-1.el6_4.noarch candlepin-scl-1-5.el6_4.noarch candlepin-scl-rhino-1.7R3-1.el6_4.noarch katello-candlepin-cert-key-pair-1.0-1.noarch 2. Configure virt-who in ESX mode and set VIRTWHO_INTERVAL=5. [root@Rhel-virtual2 ~]# grep "INTERVAL" /etc/sysconfig/virt-who VIRTWHO_INTERVAL=5 3. Configure ESX host with no guest installed at all. 4. Start virt-who service, check log file [root@Rhel-virtual2 ~]# service virt-who start, no error appears and "Created host" info generated. Starting virt-who: [root@dhcp12-131 ~]# tail -f /var/log/rhsm/rhsm.log ...... 2013-06-18 02:53:00,776 [WARNING] @virt-who.py:418 - Listening for events is not available in VDSM or ESX mode 2013-06-18 02:53:06,082 [DEBUG] @virt-who.py:431 - Virt-who is running in esx mode 2013-06-18 02:53:06,082 [DEBUG] @virt-who.py:438 - Starting infinite loop with 3 seconds interval and event handling 2013-06-18 02:53:06,773 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4200-1034-8039-b8c04f503258: []} 2013-06-18 02:53:07,535 [INFO] @virt-who.py:200 - Created host: 44454c4c-4200-1034-8039-b8c04f503258 with guests: [] 2013-06-18 02:53:11,214 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4200-1034-8039-b8c04f503258: []} 2013-06-18 02:53:15,104 [DEBUG] @subscriptionmanager.py:89 - Sending update in hosts-to-guests mapping: {44454c4c-4200-1034-8039-b8c04f503258: []} ......