Description of problem: Expired entitlement certs are getting cleaned off the system by rhsmcertd. However, on the next triggered certFrequency call to rhsmcertd, the expired entitlement certs are returning. They get re-installed to the system's /etc/pki/entitlement. The cycle continues to remove, then install, then remove, then install with each successive certFrequency trigger of rhsmcertd. The behavior seems harmless because the list of consumed entitlements (subscription-manager list --consumed) shows none (since the entitlement is expired). However, I don't believe this is the intended design behavior, and we have an automated test failing on this behavior. Version-Release number of selected component (if applicable): [root@jsefler-f14-candlepin candlepin]# git branch * master [root@jsefler-f14-candlepin candlepin]# git show-ref master ed00db51666e60beeea3a95ea404980f0865d072 refs/heads/master ed00db51666e60beeea3a95ea404980f0865d072 refs/remotes/origin/master [root@jsefler-59server ~]# subscription-manager version registered to: Unknown server type: Unknown subscription-manager: 1.0.17-1.git.0.279356f.el5 python-rhsm: 1.0.7-1.git.0.62a7320.el5 How reproducible: Steps to Reproduce: Using an on-premises candlepin server with the TESTDATA deployed... [root@jsefler-59server ~]# subscription-manager config --rhsmcertd.certfrequency=1 --server.insecure=1 SET THE CERT FREQUENCY TO 1 MINUTE AND SET INSECURE SINCE WE ARE GOING TO ADVANCE THE SYSTEM DATE BEYOND A YEAR FROM NOW [root@jsefler-59server ~]# service rhsmcertd restart Stopping rhsmcertd... [ OK ] Starting rhsmcertd... [ OK ] [root@jsefler-59server ~]# subscription-manager register --username testuser1 --password password --org admin The system has been registered with id: d84190de-d6ed-4d76-bda3-2c5880f0c283 [root@jsefler-59server ~]# subscription-manager list --avail | grep -A1 awesomeos-server-basic-me SKU: awesomeos-server-basic-me Pool Id: 8a90f81d398e9b2501398e9d183c02ae -- SKU: awesomeos-server-basic-me Pool Id: 8a90f81d398e9b2501398e9d17d302a1 [root@jsefler-59server ~]# subscription-manager subscribe --pool 8a90f81d398e9b2501398e9d17d302a1 Successfully consumed a subscription for: Awesome OS Server Basic (multi-entitlement) SUBSCRIBING TO ANY AVAILABLE POOL SHOULD DEMONSTARATE THE PROBLEM [root@jsefler-59server ~]# subscription-manager list --consumed +-------------------------------------------+ Consumed Subscriptions +-------------------------------------------+ Subscription Name: Awesome OS Server Basic (multi-entitlement) Provides: Awesome OS Server Bits SKU: awesomeos-server-basic-me Contract: 18 Account: 12331131231 Serial Number: 3674083809553042572 Active: True Quantity Used: 1 Service Level: None Service Type: Self-Support Starts: 09/02/2012 Ends: 09/02/2013 [root@jsefler-59server ~]# date 010100002014 Wed Jan 1 00:00:00 EST 2014 ADVANCED THE SYSTEM DATE BEYOND THE END OF THE ENTITLEMENT Ends DATE [root@jsefler-59server ~]# subscription-manager list --consumed No consumed subscription pools to list AS EXPECTED, THE EXPIRED ENTITLEMENT DOES NOT SHOW UP AS CONSUMED, BUT STILL EXISTS ON THE FILE SYSTEM... [root@jsefler-59server ~]# watch ls /etc/pki/entitlement/ Every 2.0s: ls /etc/pki/entitlement/ Wed Jan 1 00:00:50 2014 3674083809553042572-key.pem 3674083809553042572.pem After waiting 1 minute (since rhsmcertd.certfrequency=1), we see the watch list of entitlement files go to none, then wait another minute and you will see the watch list of entitlement files restore the original expired entitlement certs. WHY DO THEY COME BACK? THE CYCLE REPEATS EVERY MINUTE. The rhsm.log below shows the entitlements Expired (deleted) and then later Added (new). Expected results: After the rhsmcertd cleans off the expired entitlement certs, they should not return on the next triggered call to rhsmcertd. Additional info: [root@jsefler-59server ~]# tail -f /var/log/rhsm/rhsm.log 2014-01-01 00:01:49,613 [INFO] @connection.py:498 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = True 2014-01-01 00:01:49,614 [INFO] @connection.py:511 - Connection Built: host: jsefler-f14-candlepin.usersys.redhat.com, port: 8443, handler: /candlepin 2014-01-01 00:01:49,838 [DEBUG] @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2014-01-01 05:01:49.838160+00:00 2014-01-01 00:01:49,839 [DEBUG] @cert_sorter.py:160 - Installed product IDs: [] 2014-01-01 00:01:49,861 [DEBUG] @cert_sorter.py:176 - Checking certificate: 3674083809553042572 2014-01-01 00:01:49,861 [DEBUG] @cert_sorter.py:188 - expired: 2013-09-03 00:00:00+00:00 2014-01-01 00:01:49,861 [DEBUG] @cert_sorter.py:113 - valid entitled products: [] 2014-01-01 00:01:49,861 [DEBUG] @cert_sorter.py:114 - expired entitled products: [] 2014-01-01 00:01:49,862 [DEBUG] @cert_sorter.py:115 - partially entitled products: [] 2014-01-01 00:01:49,862 [DEBUG] @cert_sorter.py:116 - unentitled products: [] 2014-01-01 00:01:49,862 [DEBUG] @cert_sorter.py:117 - future products: [] 2014-01-01 00:01:49,862 [DEBUG] @cert_sorter.py:118 - partial stacks: [] 2014-01-01 00:01:49,862 [DEBUG] @cert_sorter.py:119 - valid stacks: [] 2014-01-01 00:01:49,886 [DEBUG] @connection.py:344 - Making request: GET /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283/certificates/serials 2014-01-01 00:01:50,094 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:01:50,096 [INFO] @certlib.py:221 - certs updated: Total updates: 1 Found (local) serial# [3674083809553042572L] Expected (UEP) serial# [3674083809553042572] Added (new) <NONE> Deleted (rogue): <NONE> Expired (deleted): [sn:3674083809553042572 (Awesome OS Server Bits,) @ /etc/pki/entitlement/3674083809553042572.pem] 2014-01-01 00:01:50,103 [DEBUG] @connection.py:344 - Making request: GET /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283 2014-01-01 00:01:50,372 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:01:50,378 [DEBUG] @connection.py:344 - Making request: GET /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283/release 2014-01-01 00:01:50,503 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:01:50,508 [INFO] @repolib.py:156 - repos updated: 0 2014-01-01 00:01:50,605 [DEBUG] @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2014-01-01 05:01:50.605593+00:00 2014-01-01 00:01:50,606 [DEBUG] @cert_sorter.py:160 - Installed product IDs: [] 2014-01-01 00:01:50,607 [DEBUG] @cert_sorter.py:113 - valid entitled products: [] 2014-01-01 00:01:50,607 [DEBUG] @cert_sorter.py:114 - expired entitled products: [] 2014-01-01 00:01:50,607 [DEBUG] @cert_sorter.py:115 - partially entitled products: [] 2014-01-01 00:01:50,607 [DEBUG] @cert_sorter.py:116 - unentitled products: [] 2014-01-01 00:01:50,607 [DEBUG] @cert_sorter.py:117 - future products: [] 2014-01-01 00:01:50,607 [DEBUG] @cert_sorter.py:118 - partial stacks: [] 2014-01-01 00:01:50,608 [DEBUG] @cert_sorter.py:119 - valid stacks: [] 2014-01-01 00:01:50,608 [INFO] @factlib.py:52 - Facts have not changed, skipping upload. 2014-01-01 00:01:50,611 [DEBUG] @connection.py:344 - Making request: GET /candlepin/ 2014-01-01 00:01:50,704 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:01:50,707 [DEBUG] @connection.py:528 - Server supports the following resources: 2014-01-01 00:01:50,707 [DEBUG] @connection.py:529 - {'': '/', 'hypervisors': '/hypervisors', 'serials': '/serials', 'consumers': '/consumers', 'migrations': '/migrations', 'content': '/content', 'entitlements': '/entitlements', 'statistics/generate': '/statistics/generate', 'status': '/status', 'jobs': '/jobs', 'users': '/users', 'subscriptions': '/subscriptions', 'rules': '/rules', 'consumertypes': '/consumertypes', 'activation_keys': '/activation_keys', 'atom': '/atom', 'owners': '/owners', 'roles': '/roles', 'admin': '/admin', 'events': '/events', 'products': '/products', 'pools': '/pools', 'crl': '/crl'} 2014-01-01 00:01:50,707 [INFO] @cache.py:215 - Server does not support packages, skipping profile upload. 2014-01-01 00:01:50,709 [INFO] @cache.py:160 - Checking current system info against cache: /var/lib/rhsm/cache/installed_products.json 2014-01-01 00:01:50,710 [INFO] @cache.py:175 - No changes. 2014-01-01 00:02:49,633 [INFO] @connection.py:498 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = True 2014-01-01 00:02:49,633 [INFO] @connection.py:511 - Connection Built: host: jsefler-f14-candlepin.usersys.redhat.com, port: 8443, handler: /candlepin 2014-01-01 00:02:49,870 [DEBUG] @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2014-01-01 05:02:49.870506+00:00 2014-01-01 00:02:49,871 [DEBUG] @cert_sorter.py:160 - Installed product IDs: [] 2014-01-01 00:02:49,871 [DEBUG] @cert_sorter.py:113 - valid entitled products: [] 2014-01-01 00:02:49,871 [DEBUG] @cert_sorter.py:114 - expired entitled products: [] 2014-01-01 00:02:49,872 [DEBUG] @cert_sorter.py:115 - partially entitled products: [] 2014-01-01 00:02:49,872 [DEBUG] @cert_sorter.py:116 - unentitled products: [] 2014-01-01 00:02:49,872 [DEBUG] @cert_sorter.py:117 - future products: [] 2014-01-01 00:02:49,872 [DEBUG] @cert_sorter.py:118 - partial stacks: [] 2014-01-01 00:02:49,872 [DEBUG] @cert_sorter.py:119 - valid stacks: [] 2014-01-01 00:02:49,876 [DEBUG] @connection.py:344 - Making request: GET /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283/certificates/serials 2014-01-01 00:02:50,054 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:02:50,059 [DEBUG] @connection.py:344 - Making request: GET /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283/certificates?serials=3674083809553042572 2014-01-01 00:02:50,276 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:02:50,317 [INFO] @certlib.py:221 - certs updated: Total updates: 1 Found (local) serial# [] Expected (UEP) serial# [3674083809553042572] Added (new) [sn:3674083809553042572 (Awesome OS Server Bits,) @ /etc/pki/entitlement/3674083809553042572.pem] Deleted (rogue): <NONE> Expired (deleted): <NONE> 2014-01-01 00:02:50,338 [DEBUG] @connection.py:344 - Making request: GET /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283 2014-01-01 00:02:50,554 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:02:50,561 [DEBUG] @connection.py:344 - Making request: GET /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283/release 2014-01-01 00:02:50,691 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:02:50,720 [INFO] @repolib.py:156 - repos updated: 0 2014-01-01 00:02:50,817 [DEBUG] @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2014-01-01 05:02:50.817608+00:00 2014-01-01 00:02:50,819 [DEBUG] @cert_sorter.py:160 - Installed product IDs: [] 2014-01-01 00:02:50,842 [DEBUG] @cert_sorter.py:176 - Checking certificate: 3674083809553042572 2014-01-01 00:02:50,842 [DEBUG] @cert_sorter.py:188 - expired: 2013-09-03 00:00:00+00:00 2014-01-01 00:02:50,842 [DEBUG] @cert_sorter.py:113 - valid entitled products: [] 2014-01-01 00:02:50,843 [DEBUG] @cert_sorter.py:114 - expired entitled products: [] 2014-01-01 00:02:50,843 [DEBUG] @cert_sorter.py:115 - partially entitled products: [] 2014-01-01 00:02:50,843 [DEBUG] @cert_sorter.py:116 - unentitled products: [] 2014-01-01 00:02:50,843 [DEBUG] @cert_sorter.py:117 - future products: [] 2014-01-01 00:02:50,843 [DEBUG] @cert_sorter.py:118 - partial stacks: [] 2014-01-01 00:02:50,843 [DEBUG] @cert_sorter.py:119 - valid stacks: [] 2014-01-01 00:02:50,844 [INFO] @factlib.py:52 - Facts have not changed, skipping upload. 2014-01-01 00:02:50,846 [DEBUG] @connection.py:344 - Making request: GET /candlepin/ 2014-01-01 00:02:50,917 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:02:50,918 [DEBUG] @connection.py:528 - Server supports the following resources: 2014-01-01 00:02:50,919 [DEBUG] @connection.py:529 - {'': '/', 'hypervisors': '/hypervisors', 'serials': '/serials', 'consumers': '/consumers', 'migrations': '/migrations', 'content': '/content', 'entitlements': '/entitlements', 'statistics/generate': '/statistics/generate', 'status': '/status', 'jobs': '/jobs', 'users': '/users', 'subscriptions': '/subscriptions', 'rules': '/rules', 'consumertypes': '/consumertypes', 'activation_keys': '/activation_keys', 'atom': '/atom', 'owners': '/owners', 'roles': '/roles', 'admin': '/admin', 'events': '/events', 'products': '/products', 'pools': '/pools', 'crl': '/crl'} 2014-01-01 00:02:50,919 [INFO] @cache.py:215 - Server does not support packages, skipping profile upload. 2014-01-01 00:02:50,921 [INFO] @cache.py:160 - Checking current system info against cache: /var/lib/rhsm/cache/installed_products.json 2014-01-01 00:02:50,921 [INFO] @cache.py:175 - No changes. 2014-01-01 00:03:49,639 [INFO] @connection.py:498 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = True 2014-01-01 00:03:49,639 [INFO] @connection.py:511 - Connection Built: host: jsefler-f14-candlepin.usersys.redhat.com, port: 8443, handler: /candlepin 2014-01-01 00:03:49,825 [DEBUG] @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2014-01-01 05:03:49.825667+00:00 2014-01-01 00:03:49,826 [DEBUG] @cert_sorter.py:160 - Installed product IDs: [] 2014-01-01 00:03:49,849 [DEBUG] @cert_sorter.py:176 - Checking certificate: 3674083809553042572 2014-01-01 00:03:49,849 [DEBUG] @cert_sorter.py:188 - expired: 2013-09-03 00:00:00+00:00 2014-01-01 00:03:49,849 [DEBUG] @cert_sorter.py:113 - valid entitled products: [] 2014-01-01 00:03:49,850 [DEBUG] @cert_sorter.py:114 - expired entitled products: [] 2014-01-01 00:03:49,850 [DEBUG] @cert_sorter.py:115 - partially entitled products: [] 2014-01-01 00:03:49,850 [DEBUG] @cert_sorter.py:116 - unentitled products: [] 2014-01-01 00:03:49,850 [DEBUG] @cert_sorter.py:117 - future products: [] 2014-01-01 00:03:49,850 [DEBUG] @cert_sorter.py:118 - partial stacks: [] 2014-01-01 00:03:49,850 [DEBUG] @cert_sorter.py:119 - valid stacks: [] 2014-01-01 00:03:49,876 [DEBUG] @connection.py:344 - Making request: GET /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283/certificates/serials 2014-01-01 00:03:50,108 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:03:50,115 [INFO] @certlib.py:221 - certs updated: Total updates: 1 Found (local) serial# [3674083809553042572L] Expected (UEP) serial# [3674083809553042572] Added (new) <NONE> Deleted (rogue): <NONE> Expired (deleted): [sn:3674083809553042572 (Awesome OS Server Bits,) @ /etc/pki/entitlement/3674083809553042572.pem] 2014-01-01 00:03:50,127 [DEBUG] @connection.py:344 - Making request: GET /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283 2014-01-01 00:03:50,404 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:03:50,413 [DEBUG] @connection.py:344 - Making request: GET /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283/release 2014-01-01 00:03:50,560 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:03:50,562 [INFO] @repolib.py:156 - repos updated: 0 2014-01-01 00:03:50,686 [DEBUG] @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2014-01-01 05:03:50.686021+00:00 2014-01-01 00:03:50,687 [DEBUG] @cert_sorter.py:160 - Installed product IDs: [] 2014-01-01 00:03:50,687 [DEBUG] @cert_sorter.py:113 - valid entitled products: [] 2014-01-01 00:03:50,687 [DEBUG] @cert_sorter.py:114 - expired entitled products: [] 2014-01-01 00:03:50,687 [DEBUG] @cert_sorter.py:115 - partially entitled products: [] 2014-01-01 00:03:50,688 [DEBUG] @cert_sorter.py:116 - unentitled products: [] 2014-01-01 00:03:50,688 [DEBUG] @cert_sorter.py:117 - future products: [] 2014-01-01 00:03:50,688 [DEBUG] @cert_sorter.py:118 - partial stacks: [] 2014-01-01 00:03:50,688 [DEBUG] @cert_sorter.py:119 - valid stacks: [] 2014-01-01 00:03:50,690 [INFO] @cache.py:160 - Checking current system info against cache: /var/lib/rhsm/facts/facts.json 2014-01-01 00:03:50,690 [INFO] @cache.py:162 - System data has changed, updating server. 2014-01-01 00:03:50,691 [DEBUG] @facts.py:148 - Updating facts on server 2014-01-01 00:03:50,692 [DEBUG] @connection.py:344 - Making request: PUT /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283 2014-01-01 00:03:50,977 [DEBUG] @connection.py:357 - Response status: 204 2014-01-01 00:03:50,986 [DEBUG] @connection.py:344 - Making request: GET /candlepin/ 2014-01-01 00:03:51,043 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:03:51,046 [DEBUG] @connection.py:528 - Server supports the following resources: 2014-01-01 00:03:51,047 [DEBUG] @connection.py:529 - {'': '/', 'hypervisors': '/hypervisors', 'serials': '/serials', 'consumers': '/consumers', 'migrations': '/migrations', 'content': '/content', 'entitlements': '/entitlements', 'statistics/generate': '/statistics/generate', 'status': '/status', 'jobs': '/jobs', 'users': '/users', 'subscriptions': '/subscriptions', 'rules': '/rules', 'consumertypes': '/consumertypes', 'activation_keys': '/activation_keys', 'atom': '/atom', 'owners': '/owners', 'roles': '/roles', 'admin': '/admin', 'events': '/events', 'products': '/products', 'pools': '/pools', 'crl': '/crl'} 2014-01-01 00:03:51,048 [INFO] @cache.py:215 - Server does not support packages, skipping profile upload. 2014-01-01 00:03:51,050 [INFO] @cache.py:160 - Checking current system info against cache: /var/lib/rhsm/cache/installed_products.json 2014-01-01 00:03:51,050 [INFO] @cache.py:175 - No changes. 2014-01-01 00:04:49,645 [INFO] @connection.py:498 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = True 2014-01-01 00:04:49,645 [INFO] @connection.py:511 - Connection Built: host: jsefler-f14-candlepin.usersys.redhat.com, port: 8443, handler: /candlepin 2014-01-01 00:04:49,912 [DEBUG] @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2014-01-01 05:04:49.912266+00:00 2014-01-01 00:04:49,913 [DEBUG] @cert_sorter.py:160 - Installed product IDs: [] 2014-01-01 00:04:49,913 [DEBUG] @cert_sorter.py:113 - valid entitled products: [] 2014-01-01 00:04:49,913 [DEBUG] @cert_sorter.py:114 - expired entitled products: [] 2014-01-01 00:04:49,913 [DEBUG] @cert_sorter.py:115 - partially entitled products: [] 2014-01-01 00:04:49,913 [DEBUG] @cert_sorter.py:116 - unentitled products: [] 2014-01-01 00:04:49,914 [DEBUG] @cert_sorter.py:117 - future products: [] 2014-01-01 00:04:49,914 [DEBUG] @cert_sorter.py:118 - partial stacks: [] 2014-01-01 00:04:49,914 [DEBUG] @cert_sorter.py:119 - valid stacks: [] 2014-01-01 00:04:49,926 [DEBUG] @connection.py:344 - Making request: GET /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283/certificates/serials 2014-01-01 00:04:50,146 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:04:50,149 [DEBUG] @connection.py:344 - Making request: GET /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283/certificates?serials=3674083809553042572 2014-01-01 00:04:50,324 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:04:50,346 [INFO] @certlib.py:221 - certs updated: Total updates: 1 Found (local) serial# [] Expected (UEP) serial# [3674083809553042572] Added (new) [sn:3674083809553042572 (Awesome OS Server Bits,) @ /etc/pki/entitlement/3674083809553042572.pem] Deleted (rogue): <NONE> Expired (deleted): <NONE> 2014-01-01 00:04:50,351 [DEBUG] @connection.py:344 - Making request: GET /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283 2014-01-01 00:04:50,562 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:04:50,568 [DEBUG] @connection.py:344 - Making request: GET /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283/release 2014-01-01 00:04:50,671 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:04:50,700 [INFO] @repolib.py:156 - repos updated: 0 2014-01-01 00:04:50,787 [DEBUG] @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2014-01-01 05:04:50.786902+00:00 2014-01-01 00:04:50,788 [DEBUG] @cert_sorter.py:160 - Installed product IDs: [] 2014-01-01 00:04:50,810 [DEBUG] @cert_sorter.py:176 - Checking certificate: 3674083809553042572 2014-01-01 00:04:50,810 [DEBUG] @cert_sorter.py:188 - expired: 2013-09-03 00:00:00+00:00 2014-01-01 00:04:50,810 [DEBUG] @cert_sorter.py:113 - valid entitled products: [] 2014-01-01 00:04:50,810 [DEBUG] @cert_sorter.py:114 - expired entitled products: [] 2014-01-01 00:04:50,810 [DEBUG] @cert_sorter.py:115 - partially entitled products: [] 2014-01-01 00:04:50,811 [DEBUG] @cert_sorter.py:116 - unentitled products: [] 2014-01-01 00:04:50,811 [DEBUG] @cert_sorter.py:117 - future products: [] 2014-01-01 00:04:50,811 [DEBUG] @cert_sorter.py:118 - partial stacks: [] 2014-01-01 00:04:50,811 [DEBUG] @cert_sorter.py:119 - valid stacks: [] 2014-01-01 00:04:50,811 [INFO] @factlib.py:52 - Facts have not changed, skipping upload. 2014-01-01 00:04:50,814 [DEBUG] @connection.py:344 - Making request: GET /candlepin/ 2014-01-01 00:04:50,869 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:04:50,872 [DEBUG] @connection.py:528 - Server supports the following resources: 2014-01-01 00:04:50,873 [DEBUG] @connection.py:529 - {'': '/', 'hypervisors': '/hypervisors', 'serials': '/serials', 'consumers': '/consumers', 'migrations': '/migrations', 'content': '/content', 'entitlements': '/entitlements', 'statistics/generate': '/statistics/generate', 'status': '/status', 'jobs': '/jobs', 'users': '/users', 'subscriptions': '/subscriptions', 'rules': '/rules', 'consumertypes': '/consumertypes', 'activation_keys': '/activation_keys', 'atom': '/atom', 'owners': '/owners', 'roles': '/roles', 'admin': '/admin', 'events': '/events', 'products': '/products', 'pools': '/pools', 'crl': '/crl'} 2014-01-01 00:04:50,875 [INFO] @cache.py:215 - Server does not support packages, skipping profile upload. 2014-01-01 00:04:50,878 [INFO] @cache.py:160 - Checking current system info against cache: /var/lib/rhsm/cache/installed_products.json 2014-01-01 00:04:50,878 [INFO] @cache.py:175 - No changes. 2014-01-01 00:05:49,622 [INFO] @connection.py:498 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = True 2014-01-01 00:05:49,622 [INFO] @connection.py:511 - Connection Built: host: jsefler-f14-candlepin.usersys.redhat.com, port: 8443, handler: /candlepin 2014-01-01 00:05:49,851 [DEBUG] @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2014-01-01 05:05:49.851301+00:00 2014-01-01 00:05:49,852 [DEBUG] @cert_sorter.py:160 - Installed product IDs: [] 2014-01-01 00:05:49,883 [DEBUG] @cert_sorter.py:176 - Checking certificate: 3674083809553042572 2014-01-01 00:05:49,883 [DEBUG] @cert_sorter.py:188 - expired: 2013-09-03 00:00:00+00:00 2014-01-01 00:05:49,884 [DEBUG] @cert_sorter.py:113 - valid entitled products: [] 2014-01-01 00:05:49,884 [DEBUG] @cert_sorter.py:114 - expired entitled products: [] 2014-01-01 00:05:49,884 [DEBUG] @cert_sorter.py:115 - partially entitled products: [] 2014-01-01 00:05:49,884 [DEBUG] @cert_sorter.py:116 - unentitled products: [] 2014-01-01 00:05:49,885 [DEBUG] @cert_sorter.py:117 - future products: [] 2014-01-01 00:05:49,885 [DEBUG] @cert_sorter.py:118 - partial stacks: [] 2014-01-01 00:05:49,885 [DEBUG] @cert_sorter.py:119 - valid stacks: [] 2014-01-01 00:05:49,917 [DEBUG] @connection.py:344 - Making request: GET /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283/certificates/serials 2014-01-01 00:05:50,105 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:05:50,108 [INFO] @certlib.py:221 - certs updated: Total updates: 1 Found (local) serial# [3674083809553042572L] Expected (UEP) serial# [3674083809553042572] Added (new) <NONE> Deleted (rogue): <NONE> Expired (deleted): [sn:3674083809553042572 (Awesome OS Server Bits,) @ /etc/pki/entitlement/3674083809553042572.pem] 2014-01-01 00:05:50,113 [DEBUG] @connection.py:344 - Making request: GET /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283 2014-01-01 00:05:50,438 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:05:50,448 [DEBUG] @connection.py:344 - Making request: GET /candlepin/consumers/d84190de-d6ed-4d76-bda3-2c5880f0c283/release 2014-01-01 00:05:50,563 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:05:50,569 [INFO] @repolib.py:156 - repos updated: 0 2014-01-01 00:05:50,689 [DEBUG] @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2014-01-01 05:05:50.688880+00:00 2014-01-01 00:05:50,690 [DEBUG] @cert_sorter.py:160 - Installed product IDs: [] 2014-01-01 00:05:50,690 [DEBUG] @cert_sorter.py:113 - valid entitled products: [] 2014-01-01 00:05:50,690 [DEBUG] @cert_sorter.py:114 - expired entitled products: [] 2014-01-01 00:05:50,691 [DEBUG] @cert_sorter.py:115 - partially entitled products: [] 2014-01-01 00:05:50,691 [DEBUG] @cert_sorter.py:116 - unentitled products: [] 2014-01-01 00:05:50,691 [DEBUG] @cert_sorter.py:117 - future products: [] 2014-01-01 00:05:50,691 [DEBUG] @cert_sorter.py:118 - partial stacks: [] 2014-01-01 00:05:50,691 [DEBUG] @cert_sorter.py:119 - valid stacks: [] 2014-01-01 00:05:50,692 [INFO] @factlib.py:52 - Facts have not changed, skipping upload. 2014-01-01 00:05:50,695 [DEBUG] @connection.py:344 - Making request: GET /candlepin/ 2014-01-01 00:05:50,752 [DEBUG] @connection.py:357 - Response status: 200 2014-01-01 00:05:50,757 [DEBUG] @connection.py:528 - Server supports the following resources: 2014-01-01 00:05:50,757 [DEBUG] @connection.py:529 - {'': '/', 'hypervisors': '/hypervisors', 'serials': '/serials', 'consumers': '/consumers', 'migrations': '/migrations', 'content': '/content', 'entitlements': '/entitlements', 'statistics/generate': '/statistics/generate', 'status': '/status', 'jobs': '/jobs', 'users': '/users', 'subscriptions': '/subscriptions', 'rules': '/rules', 'consumertypes': '/consumertypes', 'activation_keys': '/activation_keys', 'atom': '/atom', 'owners': '/owners', 'roles': '/roles', 'admin': '/admin', 'events': '/events', 'products': '/products', 'pools': '/pools', 'crl': '/crl'} 2014-01-01 00:05:50,757 [INFO] @cache.py:215 - Server does not support packages, skipping profile upload. 2014-01-01 00:05:50,759 [INFO] @cache.py:160 - Checking current system info against cache: /var/lib/rhsm/cache/installed_products.json 2014-01-01 00:05:50,759 [INFO] @cache.py:175 - No changes.
This request was evaluated by Red Hat Product Management for inclusion in a Red Hat Enterprise Linux release. Product Management has requested further review of this request by Red Hat Engineering, for potential inclusion in a Red Hat Enterprise Linux release for currently deployed products. This request is not yet committed for inclusion in a release.
*** Bug 858759 has been marked as a duplicate of this bug. ***
I've verified with jsefler that the server and client are on different machines and that only the client's date was pushed into the future. It appears that this is caused by the fact that the client machines date has been pushed into the future, while the candlepin server is still on today's date. rhsmcertd sees the cert as being expired and deletes it on the first checkin. The next time rhsmcertd checks in, candlepin reports that the entitlement should be on the client system (missing) and the client is told to create it, which it does. On the next checkin, the cycle repeats. There is potential for this to happen if client and server times are out of sync by even a little, and the checkin occurs at the right moment. I guess the question is, since this is due to system setup error, do we want to do anything about it? If so, I'll start looking into solutions.
I agree with mstead's analysis in comment 4. While it is indeed a real world scenario that the server and client times can be out of sync, the cyclic behavior demonstrated in comment 0 is not destructive and will end once the server's time exceeds the expiration of the entitlement (at this point both client and server regard the entitlement as expired). In the case that the server clock is ahead of the client, it is possible for the server to revoke the entitlement before the client expects it to go. In that case, the server wins! For practical purposes, the server and client clocks should always be synchronized within 4 hours (the default rhsm.certFrequency) and therefore never encounter the siuation in comment 0. Having said all of that, it seems appropriate to close this bug. Unfortunately I created the scenario in comment 0 as an easy manual recreate to demonstrate the cyclic behavior of this bug. The original scenario that revealed this bug's cyclic behavior comes from an automated test where the server and client's clock always remain in sync and a subscription is created that will expire a few minutes from now. The automated test then waits a few minutes and verifies that the entitlement expires (which it does) and then waits for the next trigger of the certFrequency to see the entitlement removed from the client (which it does) and then waits for another trigger of the certFrequency to witness the expired cert re-appear (which it shouldn't). Hence there is a little more troubleshooting needed to discover the problem.
To reproduce without having to change dates: 1) stop rhsmcertd sudo service rhsmcertd stop 2) Update the rhsmcertd's certFrequency to run every 1 min. sudo subscription-manager config --rhsmcertd.certfrequency=12 3) Create a new subscription against test data and REFRESH POOLS. Be sure to modify your end date so that the subscription expires soon (4 mins should give you enough time to perform the other steps below as they are time sensitive). # Create the subscription curl --insecure --user admin:admin --request POST --data '{"product":{"id":"awesomeos-server"},"startDate":"Sun, 23 Sep 2012 10:00:00 -0300","accountNumber":1234,"quantity":88,"endDate":"Tue, 25 Sep 2012 14:40:00 -0300","contractNumber":5678,"providedProducts":[]}' --header 'accept: application/json' --header 'content-type: application/json' https://MY_CANDLEPIN_SERVER:8443/candlepin/owners/admin/subscriptions | python -msimplejson/tool # Refresh pools curl --insecure --user admin:admin --request PUT https://MY_CANDLEPIN_SERVER:8443/candlepin/owners/admin/subscriptions 4) Find the new subscription and subscribe to it before it expires. sudo subscription-manager list --avail --all | grep awesomeos-server -A2 | grep 88 -B2 sudo subscription-manager subscribe --pool YOUR_POOL_ID 5) Disable autoheal for the system curl --insecure --user admin:admin --request PUT --data '{"autoheal":false}' --header 'accept: application/json' --header 'content-type: application/json' https://boogady:8443/candlepin/consumers/YOUR_CONSUMER_ID_HERE 6) Verify that you have subscribed sudo subscription-manager list --consumed 7) In a separate terminal, watch the entitlements folder. watch ls /etc/pki/entitlement/ 8) Restart rhsmcertd. sudo service rhsmcertd start EXPECTATIONS: Watching the terminal from step 7, you should see the entitlement appear, disappear, appear, disappear, ... each time rhsmcertd updates the certificate.
Fixed in: master - 3bea31a5e64cacfc3a5f5b2ac1920df67e3f1118 internal - 17e6f61ada96675bb160a0f85f9acb3242e16aa0
Verifying Version... [root@jsefler-rhel59 ~]# rpm -q subscription-manager python-rhsm subscription-manager-1.0.22-1.el5 python-rhsm-1.0.10-1.el5 Our automated test coverage for this bug is now passing. The expired entitlements are no longer removed/restored/removed/restored/etc.. with each trigger of the certFrequency. Now the expired entitlements are only removed. The rhsm.log contains the following DEBUG statements in subsequent certFrequency triggers of rhsmcertd. 2012-10-11 13:47:25,693 [INFO] @certlib.py:324 - Certificate from server was expired, not installing: 6857971666984411474 Moving to VERIFIED
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. http://rhn.redhat.com/errata/RHBA-2013-0033.html