Bug 754427

Summary: Package profiles upload failure upon registration via activation key
Product: Red Hat Enterprise Linux 5 Reporter: Tomas Strachota <tstrachota>
Component: subscription-managerAssignee: William Poteat <wpoteat>
Status: CLOSED CURRENTRELEASE QA Contact: IDM QE LIST <seceng-idm-qe-list>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 5.8CC: jsefler, skallesh, spandey
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-05-29 19:04:48 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Bug Depends On:    
Bug Blocks: 715031    

Description Tomas Strachota 2011-11-16 13:11:40 UTC 
Description of problem:
When registering via an activation key against Katello, the package profile upload after the registration fails. It's caused by a missing consumer certificate in headers of the package profile upload call.

Version-Release number of selected component (if applicable):
subscription-manager-0.98.2-1.el6.x86_64
katello-0.1.104-1.git.57.dab58b8
candlepin-0.4.25-1.el6.noarch
pulp-0.0.237-5.el6.noarch

Steps to Reproduce:
1. prepare an org/provider/product/repo in Katello
2. create an env and promote the product to there
3. create a new activation key, assign the subscription for the product to that activation key
4. using RHSM: 
subscription-manager register --activationkey=ak1 --org=org1 --force

Actual results:
The system registers successfully and then raises an error:
Error updating system data, see /var/log/rhsm/rhsm.log for more details.

Expected results:
The system registers without any error.


Additional info:
There's already a proposed patch on the candlepin-patches mailing list.
Comment 1 Tomas Strachota 2011-11-16 13:12:56 UTC 
relevant part of /var/log/rhsm/rhsm.log

2011-11-15 17:23:29,331 [INFO]  @connection.py:353 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = False
2011-11-15 17:23:29,331 [INFO]  @connection.py:364 - Connection Built: host: dhcp-26-118.brq.redhat.com, port: 3000, handler: /api
2011-11-15 17:23:29,442 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2011-11-15 17:23:29,454 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-local.pem'
2011-11-15 17:23:29,467 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2011-11-15 17:23:29,468 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2011-11-15 17:23:29,469 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-ca.pem'
2011-11-15 17:23:29,470 [DEBUG]  @connection.py:209 - Making request: DELETE /api/consumers/9f6cd3ec-4898-4a4a-854d-f09809cd3f2a
2011-11-15 17:23:31,952 [DEBUG]  @connection.py:221 - Response status: 204
2011-11-15 17:23:31,952 [INFO]  @managerlib.py:783 - Successfully un-registered.
2011-11-15 17:23:31,953 [INFO]  @cache.py:106 - Deleting cache: /var/lib/rhsm/facts/facts.json
2011-11-15 17:23:32,019 [INFO]  @cache.py:106 - Deleting cache: /var/lib/rhsm/cache/installed_products.json
2011-11-15 17:23:32,022 [INFO]  @managercli.py:575 - --force specified, un-registered old consumer: 9f6cd3ec-4898-4a4a-854d-f09809cd3f2a
2011-11-15 17:23:32,023 [INFO]  @connection.py:360 - Using no auth
2011-11-15 17:23:32,023 [INFO]  @connection.py:364 - Connection Built: host: dhcp-26-118.brq.redhat.com, port: 3000, handler: /api
2011-11-15 17:23:32,289 [DEBUG]  @cert_sorter.py:91 - Sorting product and entitlement cert status for: 2011-11-15 16:23:32.289609+00:00
2011-11-15 17:23:32,290 [DEBUG]  @cert_sorter.py:178 - Installed product IDs: []
2011-11-15 17:23:32,290 [DEBUG]  @cert_sorter.py:221 - Scanning stacked entitlements.
2011-11-15 17:23:32,290 [DEBUG]  @cert_sorter.py:249 - Checking stack compliance:
2011-11-15 17:23:32,290 [DEBUG]  @cert_sorter.py:95 - valid entitled products: []
2011-11-15 17:23:32,290 [DEBUG]  @cert_sorter.py:96 - expired entitled products: []
2011-11-15 17:23:32,290 [DEBUG]  @cert_sorter.py:97 - partially entitled products: []
2011-11-15 17:23:32,290 [DEBUG]  @cert_sorter.py:98 - unentitled products: []
2011-11-15 17:23:32,291 [DEBUG]  @cert_sorter.py:99 - future products: []
2011-11-15 17:23:32,291 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2011-11-15 17:23:32,291 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-local.pem'
2011-11-15 17:23:32,292 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2011-11-15 17:23:32,292 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2011-11-15 17:23:32,292 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-ca.pem'
2011-11-15 17:23:32,293 [DEBUG]  @connection.py:209 - Making request: POST /api/consumers?owner=ACME_Corporation&activation_keys=ak1
2011-11-15 17:23:34,721 [DEBUG]  @connection.py:221 - Response status: 200
2011-11-15 17:23:34,725 [INFO]  @managerlib.py:72 - Consumer created: {'consumer_name': 'dhcp-26-118.brq.redhat.com', 'uuid': '75267967-c185-44bb-9040-4fb59951e81d'}
2011-11-15 17:23:34,728 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2011-11-15 17:23:34,728 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-local.pem'
2011-11-15 17:23:34,728 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2011-11-15 17:23:34,729 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2011-11-15 17:23:34,729 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-ca.pem'
2011-11-15 17:23:34,729 [DEBUG]  @connection.py:209 - Making request: GET /api/
2011-11-15 17:23:35,236 [DEBUG]  @connection.py:221 - Response status: 200
2011-11-15 17:23:35,237 [DEBUG]  @connection.py:380 - Server supports the following resources:
2011-11-15 17:23:35,237 [DEBUG]  @connection.py:381 - {'templates': '/api/templates/', 'organizations': '/api/organizations/', 'tasks': '/api/tasks/', 'users': '/api/users/', 'consumers': '/api/consumers/', 'changesets': '/api/changesets/', 'providers': '/api/providers/', 'repositories': '/api/repositories/', 'environments': '/api/environments/', 'entitlements': '/api/entitlements/', 'products': '/api/products/', 'systems': '/api/systems/', 'activation_keys': '/api/activation_keys/', 'packages': '/api/packages/', 'distributions': '/api/distributions/', 'errata': '/api/errata/'}
2011-11-15 17:23:35,238 [INFO]  @cache.py:154 - Checking current system info against cache: /var/lib/rhsm/packages/packages.json
2011-11-15 17:23:35,238 [INFO]  @cache.py:216 - Cache does not exist
2011-11-15 17:23:35,238 [INFO]  @cache.py:156 - System data has changed, updating server.
2011-11-15 17:23:35,239 [DEBUG]  @profile.py:94 - Loading current RPM profile.
2011-11-15 17:23:35,424 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2011-11-15 17:23:35,425 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-local.pem'
2011-11-15 17:23:35,425 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2011-11-15 17:23:35,425 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2011-11-15 17:23:35,425 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-ca.pem'
2011-11-15 17:23:35,431 [DEBUG]  @connection.py:209 - Making request: PUT /api/consumers/75267967-c185-44bb-9040-4fb59951e81d/packages
2011-11-15 17:23:36,536 [DEBUG]  @connection.py:221 - Response status: 401
2011-11-15 17:23:36,536 [ERROR]  @connection.py:233 - No JSON object could be decoded: line 1 column 1 (char 1)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/rhsm/connection.py", line 231, in validateResponse
    parsed = json.loads(response['content'])
  File "/usr/lib64/python2.7/site-packages/simplejson/__init__.py", line 385, in loads
    return _default_decoder.decode(s)
  File "/usr/lib64/python2.7/site-packages/simplejson/decoder.py", line 402, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/lib64/python2.7/site-packages/simplejson/decoder.py", line 420, in raw_decode
    raise JSONDecodeError("No JSON object could be decoded", s, idx)
JSONDecodeError: No JSON object could be decoded: line 1 column 1 (char 1)
2011-11-15 17:23:36,569 [ERROR]  @connection.py:234 - Response: {'content': ' ', 'status': 401}
2011-11-15 17:23:36,569 [ERROR]  @cache.py:164 - Error updating system data
2011-11-15 17:23:36,569 [ERROR]  @cache.py:165 - 
Traceback (most recent call last):
  File "/usr/share/rhsm/subscription_manager/cache.py", line 158, in update_check
    self._update_server(uep, consumer_uuid)
  File "/usr/share/rhsm/subscription_manager/cache.py", line 224, in _update_server
    self.current_profile.collect())
  File "/usr/lib/python2.7/site-packages/rhsm/connection.py", line 465, in updatePackageProfile
    ret = self.conn.request_put(method, pkg_dicts)
  File "/usr/lib/python2.7/site-packages/rhsm/connection.py", line 264, in request_put
    return self._request("PUT", method, params)
  File "/usr/lib/python2.7/site-packages/rhsm/connection.py", line 222, in _request
    self.validateResponse(result)
  File "/usr/lib/python2.7/site-packages/rhsm/connection.py", line 239, in validateResponse
    raise NetworkException(response['status'])
NetworkException
2011-11-15 17:23:36,581 [ERROR]  @managercli.py:65 - exception caught in subscription-manager
2011-11-15 17:23:36,582 [ERROR]  @managercli.py:66 - Error updating system data, see /var/log/rhsm/rhsm.log for more details.
Traceback (most recent call last):
  File "/usr/sbin/subscription-manager", line 78, in <module>
    sys.exit(abs(main() or 0))
  File "/usr/sbin/subscription-manager", line 69, in main
    return managercli.CLI().main()
  File "/usr/share/rhsm/subscription_manager/managercli.py", line 1391, in main
    cmd.main()
  File "/usr/share/rhsm/subscription_manager/managercli.py", line 233, in main
    self._do_command()
  File "/usr/share/rhsm/subscription_manager/managercli.py", line 629, in _do_command
    profile_mgr.update_check(admin_cp, consumer['uuid'])
  File "/usr/share/rhsm/subscription_manager/cache.py", line 212, in update_check
    return CacheManager.update_check(self, uep, consumer_uuid)
  File "/usr/share/rhsm/subscription_manager/cache.py", line 166, in update_check
    raise Exception(_("Error updating system data, see /var/log/rhsm/rhsm.log "
Exception: Error updating system data, see /var/log/rhsm/rhsm.log for more details.
Comment 3 Bryan Kearney 2011-11-16 16:25:36 UTC 
fixed in ccf246a94db5aa2c45ff06e6dbc0066dff6a2cb5.
Comment 4 spandey 2011-12-28 09:41:21 UTC 
while my testing i am getting following message 

[root@dhcp193-163 ~]#  subscription-manager register --org ACME_Corporation --env test --activationkey test2
Invalid credentials
[root@dhcp193-163 ~]#  subscription-manager register --org ACME_Corporation  --activationkey test2
Multi-entitlement not supported for pool with id '8ac14945347a4c0701347a5a1baa0009'.
[root@dhcp193-163 ~]# rpm -qa | grep subscription
subscription-manager-gnome-0.98.8-1.el5
subscription-manager-0.98.8-1.el5
subscription-manager-firstboot-0.98.8-1.el5

Katello Version: 0.1.155-1.el6
Comment 5 Shwetha Kallesh 2011-12-30 09:53:39 UTC 
[root@dhcp193-29 pki]# subscription-manager register --org ACME_Corporation --activationkey test1 --env test
Invalid credentials

[root@dhcp193-29 ~]# rpm -qa | grep subscription-manager 
subscription-manager-migration-0.98.9-1.el5
subscription-manager-gnome-0.98.9-1.el5
subscription-manager-migration-data-1.7-1.el5
subscription-manager-debuginfo-0.98.9-1.el5
subscription-manager-firstboot-0.98.9-1.el5
subscription-manager-0.98.9-1.el5
Comment 6 Tomas Strachota 2012-01-04 15:19:13 UTC 
I tested the scenario with fresh katello installation and everything seems to work.
Comment 7 John Sefler 2012-01-04 15:52:31 UTC 
Moving to VERIFIED based on comment 6.
Based on comment 3 and git, this fix first appeared in subscription-manager-0.98.3-1
Comment 8 Tomas Strachota 2012-01-05 09:17:02 UTC 
In comment 6 tested with:
subscription-manager-0.98.3-1
katello-0.1.161-1
pulp-0.0.255-1
candlepin-0.5.8-1