Bug 804228

Summary:	GET /subscription/consumers/UUID/release fails when restarting rhsmcertd against old candlepin
Product:	Red Hat Enterprise Linux 6	Reporter:	John Sefler <jsefler>
Component:	subscription-manager	Assignee:	Adrian Likins <alikins>
Status:	CLOSED ERRATA	QA Contact:	Entitlement Bugs <entitlement-bugs>
Severity:	high	Docs Contact:
Priority:	unspecified
Version:	6.3	CC:	bkearney, mstead, skallesh, spandey
Target Milestone:	rc	Keywords:	Regression
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:	804227	Environment:
Last Closed:	2012-06-20 13:07:53 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:	804227
Bug Blocks:	738066

Description John Sefler 2012-03-16 22:46:59 UTC

Description of problem:
After registering a new consumer, restarting rhsmcertd fails against an old version of candlepin (0.5.25 ish?)

Based on Sprint40 planning, subscription-manager needs to be backward compatible with older releases of candlepin.


Version-Release number of selected component (if applicable):
[root@ibm-ls22-04 ~]# rpm -q subscription-manager
subscription-manager-0.99.10-1.el6.x86_64
[root@ibm-ls22-04 ~]# rpm -q python-rhsm
python-rhsm-0.99.6-1.el6.noarch



How reproducible:

Steps to Reproduce:
[root@ibm-ls22-04 ~]# subscription-manager register --username stage_test_12
Password: 
The system has been registered with id: 5b61ae51-623d-4bfc-8b34-c3533a176370 
[root@ibm-ls22-04 ~]# service rhsmcertd restart
Stopping rhsmcertd[  OK  ]
Starting rhsmcertd 240 1440[  OK  ]
[root@ibm-ls22-04 ~]# 

  

[root@jsefler-r63-server ~]# tail -f /var/log/rhsm/rhsmcertd.log

Fri Mar 16 18:39:01 2012: healing check started: interval = 1440
Fri Mar 16 18:39:01 2012: cert check started: interval = 240
Fri Mar 16 18:39:12 2012: certificates updated
Fri Mar 16 18:39:17 2012: update failed (255), retry will occur on next run
                          ^^^^^^^^^^^^^
                          EXPECTED certificates updated



[root@jsefler-r63-server ~]# tail -f /var/log/rhsm/rhsm.log

2012-03-16 18:39:01,530 [INFO]  @connection.py:487 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = True
2012-03-16 18:39:01,530 [INFO]  @connection.py:498 - Connection Built: host: subscription.rhn.stage.redhat.com, port: 443, handler: /subscription
2012-03-16 18:39:01,730 [DEBUG]  @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2012-03-16 22:39:01.730039+00:00
2012-03-16 18:39:01,731 [DEBUG]  @cert_sorter.py:159 - Installed product IDs: ['69']
2012-03-16 18:39:01,732 [DEBUG]  @cert_sorter.py:112 - valid entitled products: []
2012-03-16 18:39:01,732 [DEBUG]  @cert_sorter.py:113 - expired entitled products: []
2012-03-16 18:39:01,732 [DEBUG]  @cert_sorter.py:114 - partially entitled products: []
2012-03-16 18:39:01,732 [DEBUG]  @cert_sorter.py:115 - unentitled products: ['69']
2012-03-16 18:39:01,732 [DEBUG]  @cert_sorter.py:116 - future products: []
2012-03-16 18:39:01,732 [DEBUG]  @cert_sorter.py:117 - partial stacks: []
2012-03-16 18:39:01,732 [DEBUG]  @cert_sorter.py:118 - valid stacks: []
2012-03-16 18:39:01,735 [DEBUG]  @connection.py:328 - Making request: GET /subscription/consumers/5b61ae51-623d-4bfc-8b34-c3533a176370/certificates/serials
2012-03-16 18:39:03,051 [DEBUG]  @connection.py:342 - Response status: 200
2012-03-16 18:39:03,052 [INFO]  @certlib.py:194 - certs updated:
Total updates: 0
Found (local) serial# []
Expected (UEP) serial# []
Added (new)
  <NONE>
Deleted (rogue):
  <NONE>
Expired (not deleted):
  <NONE>
Expired (deleted):
  <NONE>
2012-03-16 18:39:03,061 [DEBUG]  @connection.py:328 - Making request: GET /subscription/consumers/5b61ae51-623d-4bfc-8b34-c3533a176370
2012-03-16 18:39:04,398 [DEBUG]  @connection.py:342 - Response status: 200
2012-03-16 18:39:04,400 [INFO]  @certlib.py:108 - Checking if system requires healing.
2012-03-16 18:39:04,400 [DEBUG]  @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2012-03-16 22:39:04.400456+00:00
2012-03-16 18:39:04,405 [DEBUG]  @cert_sorter.py:159 - Installed product IDs: ['69']
2012-03-16 18:39:04,405 [DEBUG]  @cert_sorter.py:112 - valid entitled products: []
2012-03-16 18:39:04,405 [DEBUG]  @cert_sorter.py:113 - expired entitled products: []
2012-03-16 18:39:04,406 [DEBUG]  @cert_sorter.py:114 - partially entitled products: []
2012-03-16 18:39:04,406 [DEBUG]  @cert_sorter.py:115 - unentitled products: ['69']
2012-03-16 18:39:04,407 [DEBUG]  @cert_sorter.py:116 - future products: []
2012-03-16 18:39:04,407 [DEBUG]  @cert_sorter.py:117 - partial stacks: []
2012-03-16 18:39:04,407 [DEBUG]  @cert_sorter.py:118 - valid stacks: []
2012-03-16 18:39:04,408 [WARNING]  @certlib.py:124 - Found invalid entitlements for today: 2012-03-16 22:39:04.400456+00:00
2012-03-16 18:39:04,410 [DEBUG]  @connection.py:328 - Making request: POST /subscription/consumers/5b61ae51-623d-4bfc-8b34-c3533a176370/entitlements?entitle_date=2012-03-16T22%3A39%3A04.400456%2B00%3A00
2012-03-16 18:39:08,580 [DEBUG]  @connection.py:342 - Response status: 200
2012-03-16 18:39:08,582 [DEBUG]  @connection.py:328 - Making request: GET /subscription/consumers/5b61ae51-623d-4bfc-8b34-c3533a176370/certificates/serials
2012-03-16 18:39:10,193 [DEBUG]  @connection.py:342 - Response status: 200
2012-03-16 18:39:10,197 [DEBUG]  @connection.py:328 - Making request: GET /subscription/consumers/5b61ae51-623d-4bfc-8b34-c3533a176370/certificates?serials=437451824350955298
2012-03-16 18:39:12,694 [DEBUG]  @connection.py:342 - Response status: 200
2012-03-16 18:39:12,773 [INFO]  @certlib.py:194 - certs updated:
Total updates: 1
Found (local) serial# []
Expected (UEP) serial# [437451824350955298]
Added (new)
  [sn:437451824350955298 (Red Hat Enterprise Linux Server,) @ /etc/pki/entitlement/437451824350955298.pem]
Deleted (rogue):
  <NONE>
Expired (not deleted):
  <NONE>
Expired (deleted):
  <NONE>
2012-03-16 18:39:12,824 [INFO]  @certlib.py:147 - Auto-heal check complete.
2012-03-16 18:39:12,974 [INFO]  @connection.py:487 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = True
2012-03-16 18:39:12,974 [INFO]  @connection.py:498 - Connection Built: host: subscription.rhn.stage.redhat.com, port: 443, handler: /subscription
2012-03-16 18:39:13,173 [DEBUG]  @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2012-03-16 22:39:13.173522+00:00
2012-03-16 18:39:13,175 [DEBUG]  @cert_sorter.py:159 - Installed product IDs: ['69']
2012-03-16 18:39:13,207 [DEBUG]  @cert_sorter.py:175 - Checking certificate: 437451824350955298
2012-03-16 18:39:13,212 [DEBUG]  @cert_sorter.py:286 -   system has 2 sockets, 8 covered by entitlement
2012-03-16 18:39:13,227 [DEBUG]  @cert_sorter.py:112 - valid entitled products: ['69']
2012-03-16 18:39:13,228 [DEBUG]  @cert_sorter.py:113 - expired entitled products: []
2012-03-16 18:39:13,228 [DEBUG]  @cert_sorter.py:114 - partially entitled products: []
2012-03-16 18:39:13,228 [DEBUG]  @cert_sorter.py:115 - unentitled products: []
2012-03-16 18:39:13,228 [DEBUG]  @cert_sorter.py:116 - future products: []
2012-03-16 18:39:13,228 [DEBUG]  @cert_sorter.py:117 - partial stacks: []
2012-03-16 18:39:13,228 [DEBUG]  @cert_sorter.py:118 - valid stacks: []
2012-03-16 18:39:13,258 [DEBUG]  @connection.py:328 - Making request: GET /subscription/consumers/5b61ae51-623d-4bfc-8b34-c3533a176370/certificates/serials
2012-03-16 18:39:15,787 [DEBUG]  @connection.py:342 - Response status: 200
2012-03-16 18:39:15,829 [INFO]  @certlib.py:194 - certs updated:
Total updates: 0
Found (local) serial# [437451824350955298L]
Expected (UEP) serial# [437451824350955298]
Added (new)
  <NONE>
Deleted (rogue):
  <NONE>
Expired (not deleted):
  <NONE>
Expired (deleted):
  <NONE>
2012-03-16 18:39:15,833 [DEBUG]  @connection.py:328 - Making request: GET /subscription/consumers/5b61ae51-623d-4bfc-8b34-c3533a176370/release
2012-03-16 18:39:17,868 [DEBUG]  @connection.py:342 - Response status: 404
2012-03-16 18:39:17,868 [ERROR]  @connection.py:359 - No JSON object could be decoded
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/rhsm/connection.py", line 357, in validateResponse
    parsed = json.loads(response['content'])
  File "/usr/lib64/python2.6/site-packages/simplejson/__init__.py", line 307, in loads
    return _default_decoder.decode(s)
  File "/usr/lib64/python2.6/site-packages/simplejson/decoder.py", line 335, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/lib64/python2.6/site-packages/simplejson/decoder.py", line 353, in raw_decode
    raise ValueError("No JSON object could be decoded")
ValueError: No JSON object could be decoded
2012-03-16 18:39:17,870 [ERROR]  @connection.py:360 - Response: {'content': '<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"\n       "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">\n<html xmlns="http://www.w3.org/1999/xhtml" xml:lang="en" lang="en">\n<head>\n  <meta http-equiv="content-type" content="text/html;charset=UTF-8" />\n  <title>404 Not Found</title>\n  <link href="/clonepin/stylesheets/scaffold.css?1322764663" media="screen" rel="stylesheet" type="text/css" />\n  <link href="/clonepin/stylesheets/errorpage.css?1322764663" media="screen" rel="stylesheet" type="text/css" />\n</head>\n<body>\n\n  <div class="dialog">\n    <h1>The page you were looking for doesn\'t exist.</h1>\n    <p>You may have mistyped the address or the page may have moved.</p>\n  </div>\n\n\n</body>\n</html>\n', 'status': 404, 'candlepin_version': None}
2012-03-16 18:39:17,871 [ERROR]  @connection.py:362 - remote server status code: 404
2012-03-16 18:39:17,871 [ERROR]  @rhsmcertd-worker:75 - Error while updating certificates using daemon
2012-03-16 18:39:17,871 [ERROR]  @rhsmcertd-worker:77 - 
Traceback (most recent call last):
  File "/usr/libexec/rhsmcertd-worker", line 68, in <module>
    main(options, log)
  File "/usr/libexec/rhsmcertd-worker", line 44, in main
    updates = mgr.update(options.autoheal)
  File "/usr/share/rhsm/subscription_manager/certmgr.py", line 85, in update
    updates += lib.update()
  File "/usr/share/rhsm/subscription_manager/certlib.py", line 61, in update
    return self._do_update()
  File "/usr/share/rhsm/subscription_manager/repolib.py", line 40, in _do_update
    action = UpdateAction(uep=self.uep)
  File "/usr/share/rhsm/subscription_manager/repolib.py", line 96, in __init__
    self.release = self.uep.getRelease(self.consumer_uuid)
  File "/usr/lib/python2.6/site-packages/rhsm/connection.py", line 769, in getRelease
    results = self.conn.request_get(method)
  File "/usr/lib/python2.6/site-packages/rhsm/connection.py", line 386, in request_get
    return self._request("GET", method)
  File "/usr/lib/python2.6/site-packages/rhsm/connection.py", line 347, in _request
    self.validateResponse(result)
  File "/usr/lib/python2.6/site-packages/rhsm/connection.py", line 363, in validateResponse
    raise RemoteServerException(response['status'])
RemoteServerException

Comment 2 Adrian Likins 2012-03-21 16:43:30 UTC

commit 9d4307173b2fe17289066533d939ecdd2a1196d3
Author: Adrian Likins <alikins>
Date:   Tue Mar 20 16:38:00 2012 -0400

    804227,804076,804228: Handle 404's from old candlepin servers without /release
    
    The release/ystream support requires new candlepin api. If
    we get a 404 on that api, fail gracefully.

Comment 3 John Sefler 2012-03-22 14:27:28 UTC

Verifying Version....
[root@jsefler-r63-server ~]# rpm -q subscription-manager
subscription-manager-0.99.10-1.git.95.35b8500.el6.x86_64

candlepin-jboss-0.5.5.2-1.el6  <- was told this is currently deployed in stage 


[root@jsefler-r63-server ~]# subscription-manager register --username stage_test_12
Password: 
The system has been registered with id: 94963ab4-8e79-4bfe-ad2f-8a345893a1b3 
[root@jsefler-r63-server ~]# service rhsmcertd restart
Stopping rhsmcertd                                         [  OK  ]
Starting rhsmcertd 240 1440                                [  OK  ]



[root@jsefler-r63-server ~]# tail -f /var/log/rhsm/rhsmcertd.log
Thu Mar 22 10:14:00 2012: healing check started: interval = 1440
Thu Mar 22 10:14:00 2012: cert check started: interval = 240
Thu Mar 22 10:14:08 2012: certificates updated
Thu Mar 22 10:14:12 2012: certificates updated
                          ^^^^^^^^^^^^^^^^^^^^
                          VERIFIED!

[root@jsefler-r63-server tmp]# tail -f /var/log/rhsm/rhsm.log
2012-03-22 10:14:00,212 [INFO]  @connection.py:488 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = False
2012-03-22 10:14:00,213 [INFO]  @connection.py:499 - Connection Built: host: subscription.rhn.stage.redhat.com, port: 443, handler: /subscription
2012-03-22 10:14:00,410 [DEBUG]  @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2012-03-22 14:14:00.410331+00:00
2012-03-22 10:14:00,453 [DEBUG]  @cert_sorter.py:159 - Installed product IDs: ['100000000000060', '1000000000000023', '1144', '100000000000011', '100000000000010', '100000000000013', '100000000000012', '100000000000015', '27060', '69', '917571', '1', '37069', '37068', '37080', '37065', '37067', '37060', '37062', '100000000000006', '100000000000007', '100000000000004', '100000000000005', '100000000000002', '100000000000003', '100000000000000', '100000000000001', '100000000000020', '100000000000022', '100000000000009', '100000000000008', '37090', '37070']
2012-03-22 10:14:00,453 [DEBUG]  @cert_sorter.py:112 - valid entitled products: []
2012-03-22 10:14:00,453 [DEBUG]  @cert_sorter.py:113 - expired entitled products: []
2012-03-22 10:14:00,453 [DEBUG]  @cert_sorter.py:114 - partially entitled products: []
2012-03-22 10:14:00,454 [DEBUG]  @cert_sorter.py:115 - unentitled products: ['100000000000006', '1000000000000023', '1144', '100000000000011', '100000000000010', '100000000000013', '100000000000012', '100000000000015', '27060', '69', '37090', '1', '37069', '37068', '37080', '37065', '37067', '37060', '37062', '100000000000060', '100000000000007', '100000000000004', '100000000000005', '100000000000002', '100000000000003', '100000000000000', '100000000000001', '100000000000020', '100000000000022', '100000000000009', '100000000000008', '917571', '37070']
2012-03-22 10:14:00,454 [DEBUG]  @cert_sorter.py:116 - future products: []
2012-03-22 10:14:00,454 [DEBUG]  @cert_sorter.py:117 - partial stacks: []
2012-03-22 10:14:00,455 [DEBUG]  @cert_sorter.py:118 - valid stacks: []
2012-03-22 10:14:00,459 [DEBUG]  @connection.py:308 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-03-22 10:14:00,459 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/jsefler-f14-candlepin.pem'
2012-03-22 10:14:00,460 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-03-22 10:14:00,461 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-03-22 10:14:00,461 [DEBUG]  @connection.py:329 - Making request: GET /subscription/consumers/94963ab4-8e79-4bfe-ad2f-8a345893a1b3/certificates/serials
2012-03-22 10:14:01,441 [DEBUG]  @connection.py:343 - Response status: 200
2012-03-22 10:14:01,445 [INFO]  @certlib.py:194 - certs updated:
Total updates: 0
Found (local) serial# []
Expected (UEP) serial# []
Added (new)
  <NONE>
Deleted (rogue):
  <NONE>
Expired (not deleted):
  <NONE>
Expired (deleted):
  <NONE>
2012-03-22 10:14:01,454 [DEBUG]  @connection.py:308 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-03-22 10:14:01,455 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/jsefler-f14-candlepin.pem'
2012-03-22 10:14:01,455 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-03-22 10:14:01,456 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-03-22 10:14:01,456 [DEBUG]  @connection.py:329 - Making request: GET /subscription/consumers/94963ab4-8e79-4bfe-ad2f-8a345893a1b3
2012-03-22 10:14:02,484 [DEBUG]  @connection.py:343 - Response status: 200
2012-03-22 10:14:02,486 [INFO]  @certlib.py:108 - Checking if system requires healing.
2012-03-22 10:14:02,486 [DEBUG]  @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2012-03-22 14:14:02.486640+00:00
2012-03-22 10:14:02,525 [DEBUG]  @cert_sorter.py:159 - Installed product IDs: ['100000000000060', '1000000000000023', '1144', '100000000000011', '100000000000010', '100000000000013', '100000000000012', '100000000000015', '27060', '69', '917571', '1', '37069', '37068', '37080', '37065', '37067', '37060', '37062', '100000000000006', '100000000000007', '100000000000004', '100000000000005', '100000000000002', '100000000000003', '100000000000000', '100000000000001', '100000000000020', '100000000000022', '100000000000009', '100000000000008', '37090', '37070']
2012-03-22 10:14:02,525 [DEBUG]  @cert_sorter.py:112 - valid entitled products: []
2012-03-22 10:14:02,525 [DEBUG]  @cert_sorter.py:113 - expired entitled products: []
2012-03-22 10:14:02,526 [DEBUG]  @cert_sorter.py:114 - partially entitled products: []
2012-03-22 10:14:02,526 [DEBUG]  @cert_sorter.py:115 - unentitled products: ['100000000000006', '1000000000000023', '1144', '100000000000011', '100000000000010', '100000000000013', '100000000000012', '100000000000015', '27060', '69', '37090', '1', '37069', '37068', '37080', '37065', '37067', '37060', '37062', '100000000000060', '100000000000007', '100000000000004', '100000000000005', '100000000000002', '100000000000003', '100000000000000', '100000000000001', '100000000000020', '100000000000022', '100000000000009', '100000000000008', '917571', '37070']
2012-03-22 10:14:02,526 [DEBUG]  @cert_sorter.py:116 - future products: []
2012-03-22 10:14:02,526 [DEBUG]  @cert_sorter.py:117 - partial stacks: []
2012-03-22 10:14:02,526 [DEBUG]  @cert_sorter.py:118 - valid stacks: []
2012-03-22 10:14:02,526 [WARNING]  @certlib.py:124 - Found invalid entitlements for today: 2012-03-22 14:14:02.486640+00:00
2012-03-22 10:14:02,527 [DEBUG]  @connection.py:308 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-03-22 10:14:02,528 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/jsefler-f14-candlepin.pem'
2012-03-22 10:14:02,528 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-03-22 10:14:02,529 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-03-22 10:14:02,529 [DEBUG]  @connection.py:329 - Making request: POST /subscription/consumers/94963ab4-8e79-4bfe-ad2f-8a345893a1b3/entitlements?entitle_date=2012-03-22T14%3A14%3A02.486640%2B00%3A00
2012-03-22 10:14:06,236 [DEBUG]  @connection.py:343 - Response status: 200
2012-03-22 10:14:06,244 [DEBUG]  @connection.py:308 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-03-22 10:14:06,244 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/jsefler-f14-candlepin.pem'
2012-03-22 10:14:06,244 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-03-22 10:14:06,245 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-03-22 10:14:06,246 [DEBUG]  @connection.py:329 - Making request: GET /subscription/consumers/94963ab4-8e79-4bfe-ad2f-8a345893a1b3/certificates/serials
2012-03-22 10:14:07,257 [DEBUG]  @connection.py:343 - Response status: 200
2012-03-22 10:14:07,260 [DEBUG]  @connection.py:308 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-03-22 10:14:07,261 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/jsefler-f14-candlepin.pem'
2012-03-22 10:14:07,264 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-03-22 10:14:07,267 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-03-22 10:14:07,270 [DEBUG]  @connection.py:329 - Making request: GET /subscription/consumers/94963ab4-8e79-4bfe-ad2f-8a345893a1b3/certificates?serials=6773403394166215861
2012-03-22 10:14:08,274 [DEBUG]  @connection.py:343 - Response status: 200
2012-03-22 10:14:08,374 [INFO]  @certlib.py:194 - certs updated:
Total updates: 1
Found (local) serial# []
Expected (UEP) serial# [6773403394166215861]
Added (new)
  [sn:6773403394166215861 (Red Hat Enterprise Linux Server,) @ /etc/pki/entitlement/6773403394166215861.pem]
Deleted (rogue):
  <NONE>
Expired (not deleted):
  <NONE>
Expired (deleted):
  <NONE>
2012-03-22 10:14:08,452 [INFO]  @certlib.py:147 - Auto-heal check complete.
2012-03-22 10:14:08,694 [INFO]  @connection.py:488 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = False
2012-03-22 10:14:08,695 [INFO]  @connection.py:499 - Connection Built: host: subscription.rhn.stage.redhat.com, port: 443, handler: /subscription
2012-03-22 10:14:08,950 [DEBUG]  @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2012-03-22 14:14:08.949907+00:00
2012-03-22 10:14:08,987 [DEBUG]  @cert_sorter.py:159 - Installed product IDs: ['100000000000060', '1000000000000023', '1144', '100000000000011', '100000000000010', '100000000000013', '100000000000012', '100000000000015', '27060', '69', '917571', '1', '37069', '37068', '37080', '37065', '37067', '37060', '37062', '100000000000006', '100000000000007', '100000000000004', '100000000000005', '100000000000002', '100000000000003', '100000000000000', '100000000000001', '100000000000020', '100000000000022', '100000000000009', '100000000000008', '37090', '37070']
2012-03-22 10:14:09,031 [DEBUG]  @cert_sorter.py:175 - Checking certificate: 6773403394166215861
2012-03-22 10:14:09,038 [DEBUG]  @cert_sorter.py:286 -   system has 2 sockets, 8 covered by entitlement
2012-03-22 10:14:09,059 [DEBUG]  @cert_sorter.py:112 - valid entitled products: ['69']
2012-03-22 10:14:09,059 [DEBUG]  @cert_sorter.py:113 - expired entitled products: []
2012-03-22 10:14:09,059 [DEBUG]  @cert_sorter.py:114 - partially entitled products: []
2012-03-22 10:14:09,059 [DEBUG]  @cert_sorter.py:115 - unentitled products: ['100000000000006', '1000000000000023', '1144', '100000000000011', '100000000000010', '100000000000013', '100000000000012', '100000000000015', '27060', '37090', '1', '37069', '37068', '37080', '37065', '37067', '37060', '37062', '100000000000060', '100000000000007', '100000000000004', '100000000000005', '100000000000002', '100000000000003', '100000000000000', '100000000000001', '100000000000020', '100000000000022', '100000000000009', '100000000000008', '917571', '37070']
2012-03-22 10:14:09,060 [DEBUG]  @cert_sorter.py:116 - future products: []
2012-03-22 10:14:09,060 [DEBUG]  @cert_sorter.py:117 - partial stacks: []
2012-03-22 10:14:09,060 [DEBUG]  @cert_sorter.py:118 - valid stacks: []
2012-03-22 10:14:09,105 [DEBUG]  @connection.py:308 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-03-22 10:14:09,105 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/jsefler-f14-candlepin.pem'
2012-03-22 10:14:09,106 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-03-22 10:14:09,106 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-03-22 10:14:09,107 [DEBUG]  @connection.py:329 - Making request: GET /subscription/consumers/94963ab4-8e79-4bfe-ad2f-8a345893a1b3/certificates/serials
2012-03-22 10:14:10,050 [DEBUG]  @connection.py:343 - Response status: 200
2012-03-22 10:14:10,096 [INFO]  @certlib.py:194 - certs updated:
Total updates: 0
Found (local) serial# [6773403394166215861L]
Expected (UEP) serial# [6773403394166215861]
Added (new)
  <NONE>
Deleted (rogue):
  <NONE>
Expired (not deleted):
  <NONE>
Expired (deleted):
  <NONE>
2012-03-22 10:14:10,102 [DEBUG]  @connection.py:308 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-03-22 10:14:10,102 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/jsefler-f14-candlepin.pem'
2012-03-22 10:14:10,102 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-03-22 10:14:10,103 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-03-22 10:14:10,104 [DEBUG]  @connection.py:329 - Making request: GET /subscription/consumers/94963ab4-8e79-4bfe-ad2f-8a345893a1b3/release
2012-03-22 10:14:10,523 [DEBUG]  @connection.py:343 - Response status: 404
2012-03-22 10:14:10,523 [ERROR]  @connection.py:360 - No JSON object could be decoded
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/rhsm/connection.py", line 358, in validateResponse
    parsed = json.loads(response['content'])
  File "/usr/lib64/python2.6/site-packages/simplejson/__init__.py", line 307, in loads
    return _default_decoder.decode(s)
  File "/usr/lib64/python2.6/site-packages/simplejson/decoder.py", line 335, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/lib64/python2.6/site-packages/simplejson/decoder.py", line 353, in raw_decode
    raise ValueError("No JSON object could be decoded")
ValueError: No JSON object could be decoded
2012-03-22 10:14:10,526 [ERROR]  @connection.py:361 - Response: {'content': '<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"\n       "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">\n<html xmlns="http://www.w3.org/1999/xhtml" xml:lang="en" lang="en">\n<head>\n  <meta http-equiv="content-type" content="text/html;charset=UTF-8" />\n  <title>404 Not Found</title>\n  <link href="/clonepin/stylesheets/scaffold.css?1332359686" media="screen" rel="stylesheet" type="text/css" />\n  <link href="/clonepin/stylesheets/errorpage.css?1332359686" media="screen" rel="stylesheet" type="text/css" />\n</head>\n<body>\n\n  <div class="dialog">\n    <h1>The page you were looking for doesn\'t exist.</h1>\n    <p>You may have mistyped the address or the page may have moved.</p>\n  </div>\n\n\n</body>\n</html>\n', 'status': 404, 'candlepin_version': None}
2012-03-22 10:14:10,526 [ERROR]  @connection.py:363 - remote server status code: 404
2012-03-22 10:14:10,526 [DEBUG]  @repolib.py:101 - Release API not supported by the server. Using default.
2012-03-22 10:14:11,297 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-productivity-debug-rpms
2012-03-22 10:14:11,298 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-cf-tools-1-source-rpms
2012-03-22 10:14:11,299 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-vt-debug-rpms
2012-03-22 10:14:11,299 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-beta-debug-rpms
2012-03-22 10:14:11,300 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-vt-beta-source-rpms
2012-03-22 10:14:11,300 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-source-rpms
2012-03-22 10:14:11,300 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-debug-rpms
2012-03-22 10:14:11,301 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-productivity-rpms
2012-03-22 10:14:11,302 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-supplementary-beta-src
2012-03-22 10:14:11,302 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-vt-source-rpms
2012-03-22 10:14:11,303 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-supplementary
2012-03-22 10:14:11,304 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-supplementary-src
2012-03-22 10:14:11,304 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-vt-rpms
2012-03-22 10:14:11,304 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-productivity-source-rpms
2012-03-22 10:14:11,305 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-supplementary-debuginfo
2012-03-22 10:14:11,306 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-beta-source-rpms
2012-03-22 10:14:11,306 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-rpms
2012-03-22 10:14:11,306 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-cf-tools-1-rpms
2012-03-22 10:14:11,307 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-supplementary-beta-debuginfo
2012-03-22 10:14:11,308 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-vt-beta-debug-rpms
2012-03-22 10:14:11,308 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-vt-beta-rpms
2012-03-22 10:14:11,308 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-supplementary-beta
2012-03-22 10:14:11,309 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-cf-tools-1-beta-rpms
2012-03-22 10:14:11,310 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-cf-tools-1-beta-source-rpms
2012-03-22 10:14:11,310 [DEBUG]  @repolib.py:184 - Missing required tag 'rhel-5-server', skipping content: rhel-5-server-beta-rpms
2012-03-22 10:14:11,328 [INFO]  @repolib.py:148 - repos updated: 27
2012-03-22 10:14:11,452 [DEBUG]  @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2012-03-22 14:14:11.451693+00:00
2012-03-22 10:14:11,523 [DEBUG]  @cert_sorter.py:159 - Installed product IDs: ['100000000000060', '1000000000000023', '1144', '100000000000011', '100000000000010', '100000000000013', '100000000000012', '100000000000015', '27060', '69', '917571', '1', '37069', '37068', '37080', '37065', '37067', '37060', '37062', '100000000000006', '100000000000007', '100000000000004', '100000000000005', '100000000000002', '100000000000003', '100000000000000', '100000000000001', '100000000000020', '100000000000022', '100000000000009', '100000000000008', '37090', '37070']
2012-03-22 10:14:11,567 [DEBUG]  @cert_sorter.py:175 - Checking certificate: 6773403394166215861
2012-03-22 10:14:11,569 [DEBUG]  @cert_sorter.py:286 -   system has 2 sockets, 8 covered by entitlement
2012-03-22 10:14:11,592 [DEBUG]  @cert_sorter.py:112 - valid entitled products: ['69']
2012-03-22 10:14:11,592 [DEBUG]  @cert_sorter.py:113 - expired entitled products: []
2012-03-22 10:14:11,593 [DEBUG]  @cert_sorter.py:114 - partially entitled products: []
2012-03-22 10:14:11,593 [DEBUG]  @cert_sorter.py:115 - unentitled products: ['100000000000006', '1000000000000023', '1144', '100000000000011', '100000000000010', '100000000000013', '100000000000012', '100000000000015', '27060', '37090', '1', '37069', '37068', '37080', '37065', '37067', '37060', '37062', '100000000000060', '100000000000007', '100000000000004', '100000000000005', '100000000000002', '100000000000003', '100000000000000', '100000000000001', '100000000000020', '100000000000022', '100000000000009', '100000000000008', '917571', '37070']
2012-03-22 10:14:11,593 [DEBUG]  @cert_sorter.py:116 - future products: []
2012-03-22 10:14:11,594 [DEBUG]  @cert_sorter.py:117 - partial stacks: []
2012-03-22 10:14:11,594 [DEBUG]  @cert_sorter.py:118 - valid stacks: []
2012-03-22 10:14:11,597 [INFO]  @factlib.py:52 - Facts have not changed, skipping upload.
2012-03-22 10:14:11,601 [DEBUG]  @connection.py:308 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-03-22 10:14:11,601 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/jsefler-f14-candlepin.pem'
2012-03-22 10:14:11,602 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-03-22 10:14:11,603 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-03-22 10:14:11,604 [DEBUG]  @connection.py:329 - Making request: GET /subscription/
2012-03-22 10:14:12,016 [DEBUG]  @connection.py:343 - Response status: 200
2012-03-22 10:14:12,019 [DEBUG]  @connection.py:515 - Server supports the following resources:
2012-03-22 10:14:12,020 [DEBUG]  @connection.py:516 - {'owners': '/owners', 'jobs': '/jobs', 'users': '/users', 'consumers': '/consumers', 'subscriptions': '/subscriptions', 'pools': '/pools', 'products': '/products', 'entitlements': '/entitlements'}
2012-03-22 10:14:12,020 [INFO]  @cache.py:215 - Server does not support packages, skipping profile upload.
2012-03-22 10:14:12,061 [INFO]  @cache.py:160 - Checking current system info against cache: /var/lib/rhsm/cache/installed_products.json
2012-03-22 10:14:12,062 [INFO]  @cache.py:175 - No changes.

^^^^ VERIFIED
Notice the Response status: 404 after calling the /release api and the logging:
Release API not supported by the server. Using default.



Waiting on resolution to bug 804227 before moving to VERIFIED

Comment 6 John Sefler 2012-03-29 19:35:44 UTC

bug 804227 is now verified https://bugzilla.redhat.com/show_bug.cgi?id=804227#c9
let's re-verify this one again...

candlepin-jboss-0.5.5.2-1.el6  <- was told this still deployed in stage


[root@beast ~]# rpm -q subscription-manager
subscription-manager-0.99.12-1.el6.x86_64


[root@beast ~]# subscription-manager config --server.hostname=subscription.rhn.stage.redhat.com
[root@beast ~]# subscription-manager register --username stage_test_12 --autosubscribe
Password: 
The system has been registered with id: f8890d23-5f60-4a18-99e6-8e95dae6e779 
Installed Product Current Status:
Product Name:         	Red Hat Enterprise Linux Server
Status:               	Subscribed               

[root@beast ~]# service rhsmcertd restart
Stopping rhsmcertd[  OK  ]
Starting rhsmcertd 240 1440[  OK  ]
[root@beast ~]# tail -4 /var/log/rhsm/rhsmcertd.log
Thu Mar 29 15:31:51 2012: healing check started: interval = 1440
Thu Mar 29 15:31:51 2012: cert check started: interval = 240
Thu Mar 29 15:31:54 2012: certificates updated
Thu Mar 29 15:32:00 2012: certificates updated
[root@beast ~]# 
                          ^^^^^^^^^^^^^^^^^^^^
                          VERIFIED

Moving to Verified

Comment 8 errata-xmlrpc 2012-06-20 13:07:53 UTC

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-2012-0804.html