1128061 – subscription-manager shows exception and error message when unregister from SAM server

Bug 1128061 - subscription-manager shows exception and error message when unregister from SAM server

Summary: subscription-manager shows exception and error message when unregister from S...

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Enterprise Linux 6
Classification:	Red Hat
Component:	subscription-manager
Sub Component:
Version:	6.6
Hardware:	x86_64
OS:	Linux
Priority:	unspecified
Severity:	high
Target Milestone:	rc
Target Release:	---
Assignee:	Adrian Likins
QA Contact:	John Sefler
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:	rhsm-rhel66
TreeView+	depends on / blocked

Reported:	2014-08-08 08:01 UTC by Liushihui
Modified:	2014-10-14 07:48 UTC (History)
CC List:	8 users (show)
Fixed In Version:	715459
Doc Type:	Bug Fix
Doc Text:	no documentation required
Clone Of:
Environment:
Last Closed:	2014-10-14 07:48:11 UTC
Target Upstream Version:

Attachments	(Terms of Use)
Add an attachment (proposed patch, testcase, etc.)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Product Errata	RHBA-2014:1384	0	normal	SHIPPED_LIVE	subscription-manager bug fix and enhancement update	2014-10-14 01:27:50 UTC

Description Liushihui 2014-08-08 08:01:01 UTC

Description of problem:
Unregistered system, check the virt-who log, it will appear error message "IOError: [Errno 2] No such file or directory: '/etc/pki/consumer/key.pem"
and exception message like "Exception caught while running <subscription_manager.entcertlib.EntCertActionInvoker object at 0x31e9490> update"

Version-Release number of selected component (if applicable):
subscription-manager-1.12.10-1.el6.x86_64
python-rhsm-1.12.5-1.el6.x86_64
virt-who-0.10-4.el6.noarch
katello-headpin-1.4.3.26-1.el6sam_splice.noarch
candlepin-0.9.6.5-1.el6sam.noarch

How reproducible:
Always

Steps to Reproduce:
1.Register system to SAM server
# subscription-manager register --username=admin --password=admin
2. Configure virt-who run at libvirtd mode
# vim /etc/sysconfig/virt-who
VIRTWHO_BACKGROUND=1
VIRTWHO_DEBUG=1
VIRTWHO_INTERVAL=5
3. Restart virt-who service, virt-who send host/guest associate to SAM server
# service virt-who restart
4. Unregister the system
#  subscription-manager unregister

Actual results:
System has been unregistered successfully, but it will generate error message and exception as the following: 


2014-08-08 15:38:11,482 [INFO] subscription-manager @managerlib.py:807 - Successfully un-registered.
2014-08-08 15:38:11,483 [DEBUG] subscription-manager @managerlib.py:853 - Removing identity cert: /etc/pki/consumer/key.pem
2014-08-08 15:38:11,483 [DEBUG] subscription-manager @managerlib.py:853 - Removing identity cert: /etc/pki/consumer/cert.pem
2014-08-08 15:38:11,483 [DEBUG] subscription-manager @identity.py:131 - Loading consumer info from identity certificates.
2014-08-08 15:38:11,483 [ERROR] subscription-manager @identity.py:143 - [Errno 2] No such file or directory: '/etc/pki/consumer/key.pem'
Traceback (most recent call last):
  File "/usr/share/rhsm/subscription_manager/identity.py", line 135, in reload
    self.consumer = self._get_consumer_identity()
  File "/usr/share/rhsm/subscription_manager/identity.py", line 151, in _get_consumer_identity
    return ConsumerIdentity.read()
  File "/usr/share/rhsm/subscription_manager/identity.py", line 48, in read
    f = open(cls.keypath())
IOError: [Errno 2] No such file or directory: '/etc/pki/consumer/key.pem'
2014-08-08 15:38:11,484 [INFO] subscription-manager @identity.py:144 - Error reading consumer identity cert
2014-08-08 15:38:11,484 [DEBUG] subscription-manager @managerlib.py:864 - Removing entitlement cert: /etc/pki/entitlement/2320711087070785282-key.pem
2014-08-08 15:38:11,484 [DEBUG] subscription-manager @managerlib.py:864 - Removing entitlement cert: /etc/pki/entitlement/2320711087070785282.pem
2014-08-08 15:38:11,484 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/installed_products.json
2014-08-08 15:38:11,484 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/facts/facts.json
2014-08-08 15:38:11,485 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/entitlement_status.json
2014-08-08 15:38:11,485 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/content_overrides.json
2014-08-08 15:38:11,485 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/written_overrides.json
2014-08-08 15:38:11,485 [INFO] subscription-manager @managerlib.py:878 - Cleaned local data
2014-08-08 15:38:11,485 [DEBUG] subscription-manager @base_action_client.py:85 - running lib: <subscription_manager.entcertlib.EntCertActionInvoker object at 0x152c690>
2014-08-08 15:38:11,486 [WARNING] subscription-manager @base_action_client.py:72 - Exception caught while running <subscription_manager.entcertlib.EntCertActionInvoker object at 0x152c690> update
2014-08-08 15:38:11,486 [ERROR] subscription-manager @base_action_client.py:73 - 
Traceback (most recent call last):
  File "/usr/share/rhsm/subscription_manager/base_action_client.py", line 63, in _run_update
    update_report = lib.update()
  File "/usr/share/rhsm/subscription_manager/certlib.py", line 31, in update
    self.report = self.locker.run(self._do_update)
  File "/usr/share/rhsm/subscription_manager/certlib.py", line 17, in run
    return action()
  File "/usr/share/rhsm/subscription_manager/entcertlib.py", line 43, in _do_update
    return action.perform()
  File "/usr/share/rhsm/subscription_manager/entcertlib.py", line 119, in perform
    expected = self._get_expected_serials()
  File "/usr/share/rhsm/subscription_manager/entcertlib.py", line 251, in _get_expected_serials
    exp = self.get_certificate_serials_list()
  File "/usr/share/rhsm/subscription_manager/entcertlib.py", line 229, in get_certificate_serials_list
    raise Disconnected()
Disconnected
2014-08-08 15:38:11,486 [DEBUG] subscription-manager @base_action_client.py:85 - running lib: <subscription_manager.content_action_client.ContentActionClient object at 0x152c710>
2014-08-08 15:38:11,487 [DEBUG] subscription-manager @base_action_client.py:85 - running lib: <subscription_manager.repolib.RepoActionInvoker object at 0x152c910>
2014-08-08 15:38:11,487 [DEBUG] subscription-manager @connection.py:414 - Loaded CA certificates from /etc/rhsm/ca/: candlepin-stage.pem, redhat-uep.pem, candlepin-local.pem

Expected results:
system unregistered successfully, and it won't generate any error message and exception. 

Additional info:
It isn't exist on RHEL5.11

Comment 2 Radek Novacek 2014-08-08 08:12:13 UTC

This is bug in subscription-manager, there is no mention about virt-who in the traceback.

Comment 3 Liushihui 2014-08-08 08:18:14 UTC

BTW, this error log generated on /var/log/rhsm/rhsm.log

Comment 4 Adrian Likins 2014-08-14 17:07:52 UTC

pr at https://github.com/candlepin/subscription-manager/pull/1005

Comment 6 Liushihui 2014-08-28 08:27:30 UTC

Verified on RHEL6.6-Server-x64-20140826.0

Version:
virt-who-0.10-6.el6.noarch
subscription-manager-1.12.13-1.el6.x86_64
python-rhsm-1.12.5-1.el6.x86_64

Comment 7 Liushihui 2014-08-28 08:47:23 UTC

Sorry, Please ignore the comment 6,it still exist on RHEL6.6-Server-x64-20140826.0. 
In the latest build, it will pop up the following error message and exceptions:

Version:
virt-who-0.10-6.el6.noarch
subscription-manager-1.12.13-1.el6.x86_64
python-rhsm-1.12.5-1.el6.x86_64

2014-08-28 03:24:59,188 [WARNING] subscription-manager @connection.py:473 - Clock skew detected, please check your system time
2014-08-28 03:24:59,188 [INFO] subscription-manager @managerlib.py:807 - Successfully un-registered.
2014-08-28 03:24:59,190 [DEBUG] subscription-manager @managerlib.py:853 - Removing identity cert: /etc/pki/consumer/key.pem
2014-08-28 03:24:59,191 [DEBUG] subscription-manager @managerlib.py:853 - Removing identity cert: /etc/pki/consumer/cert.pem
2014-08-28 03:24:59,191 [DEBUG] subscription-manager @identity.py:131 - Loading consumer info from identity certificates.
2014-08-28 03:24:59,191 [DEBUG] subscription-manager @identity.py:143 - Reload of consumer identity cert /etc/pki/consumer/cert.pem raised an exception with msg: [Errno 2] No such file or directory: '/etc/pki/consumer/key.pem'
2014-08-28 03:24:59,192 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/installed_products.json
2014-08-28 03:24:59,192 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/facts/facts.json
2014-08-28 03:24:59,192 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/entitlement_status.json
2014-08-28 03:24:59,193 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/written_overrides.json
2014-08-28 03:24:59,193 [INFO] subscription-manager @managerlib.py:878 - Cleaned local data
2014-08-28 03:24:59,194 [DEBUG] subscription-manager @base_action_client.py:85 - running lib: <subscription_manager.entcertlib.EntCertActionInvoker object at 0x1f7d390>
2014-08-28 03:24:59,194 [WARNING] subscription-manager @base_action_client.py:72 - Exception caught while running <subscription_manager.entcertlib.EntCertActionInvoker object at 0x1f7d390> update
2014-08-28 03:24:59,194 [ERROR] subscription-manager @base_action_client.py:73 - 
Traceback (most recent call last):
  File "/usr/share/rhsm/subscription_manager/base_action_client.py", line 63, in _run_update
    update_report = lib.update()
  File "/usr/share/rhsm/subscription_manager/certlib.py", line 31, in update
    self.report = self.locker.run(self._do_update)
  File "/usr/share/rhsm/subscription_manager/certlib.py", line 17, in run
    return action()
  File "/usr/share/rhsm/subscription_manager/entcertlib.py", line 43, in _do_update
    return action.perform()
  File "/usr/share/rhsm/subscription_manager/entcertlib.py", line 119, in perform
    expected = self._get_expected_serials()
  File "/usr/share/rhsm/subscription_manager/entcertlib.py", line 251, in _get_expected_serials
    exp = self.get_certificate_serials_list()
  File "/usr/share/rhsm/subscription_manager/entcertlib.py", line 229, in get_certificate_serials_list
    raise Disconnected()
Disconnected
2014-08-28 03:24:59,195 [DEBUG] subscription-manager @base_action_client.py:85 - running lib: <subscription_manager.content_action_client.ContentActionClient object at 0x1f7d650>
2014-08-28 03:24:59,195 [DEBUG] subscription-manager @base_action_client.py:85 - running lib: <subscription_manager.repolib.RepoActionInvoker object at 0x1f7d850>
2014-08-28 03:24:59,196 [DEBUG] subscription-manager @connection.py:414 - Loaded CA certificates from /etc/rhsm/ca/: candlepin-local.pem, candlepin-stage.pem, redhat-uep.pem

Comment 8 Adrian Likins 2014-09-03 19:42:25 UTC

on master:
commit 18eeb867dc7d13958a999efb23c88258d5c0c34a
Author: Adrian Likins <alikins@redhat.com>
Date:   Thu Aug 14 13:02:26 2014 -0400

    1128061: Stop logging expected exceptions on unreg
    
    This log.exception() is information, but also unneeded.
    On a reload, a missing cert is a valid case, so stop
    cluttering the logs.

Comment 10 Liushihui 2014-09-04 09:34:19 UTC

Check it on latest rhel6.6-20140903.0-Server, the same problem still exist. please see the detail log as the following:

Version:
virt-who-0.10-7.el6.noarch
subscription-manager-1.12.14-2.el6.x86_64
python-rhsm-1.12.5-2.el6.x86_64

2014-09-04 01:44:32,681 [INFO] subscription-manager @managerlib.py:807 - Successfully un-registered.
2014-09-04 01:44:32,692 [DEBUG] subscription-manager @managerlib.py:853 - Removing identity cert: /etc/pki/consumer/key.pem
2014-09-04 01:44:32,693 [DEBUG] subscription-manager @managerlib.py:853 - Removing identity cert: /etc/pki/consumer/cert.pem
2014-09-04 01:44:32,693 [DEBUG] subscription-manager @identity.py:131 - Loading consumer info from identity certificates.
2014-09-04 01:44:32,693 [DEBUG] subscription-manager @identity.py:143 - Reload of consumer identity cert /etc/pki/consumer/cert.pem raised an exception with msg: [Errno 2] No such file or directory: '/etc/pki/consumer/key.pem'
2014-09-04 01:44:32,699 [DEBUG] subscription-manager @managerlib.py:864 - Removing entitlement cert: /etc/pki/entitlement/2726542161217885472-key.pem
2014-09-04 01:44:32,699 [DEBUG] subscription-manager @managerlib.py:864 - Removing entitlement cert: /etc/pki/entitlement/2726542161217885472.pem
2014-09-04 01:44:32,701 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/installed_products.json
2014-09-04 01:44:32,701 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/facts/facts.json
2014-09-04 01:44:32,702 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/entitlement_status.json
2014-09-04 01:44:32,702 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/product_status.json
2014-09-04 01:44:32,702 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/content_overrides.json
2014-09-04 01:44:32,715 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/written_overrides.json
2014-09-04 01:44:32,716 [INFO] subscription-manager @managerlib.py:878 - Cleaned local data
2014-09-04 01:44:32,716 [DEBUG] subscription-manager @base_action_client.py:85 - running lib: <subscription_manager.entcertlib.EntCertActionInvoker object at 0x31e9750>
2014-09-04 01:44:32,716 [WARNING] subscription-manager @base_action_client.py:72 - Exception caught while running <subscription_manager.entcertlib.EntCertActionInvoker object at 0x31e9750> update
2014-09-04 01:44:32,716 [ERROR] subscription-manager @base_action_client.py:73 -
Traceback (most recent call last):
  File "/usr/share/rhsm/subscription_manager/base_action_client.py", line 63, in _run_update
    update_report = lib.update()
  File "/usr/share/rhsm/subscription_manager/certlib.py", line 31, in update
    self.report = self.locker.run(self._do_update)
  File "/usr/share/rhsm/subscription_manager/certlib.py", line 17, in run
    return action()
  File "/usr/share/rhsm/subscription_manager/entcertlib.py", line 43, in _do_update
    return action.perform()
  File "/usr/share/rhsm/subscription_manager/entcertlib.py", line 119, in perform
    expected = self._get_expected_serials()
  File "/usr/share/rhsm/subscription_manager/entcertlib.py", line 251, in _get_expected_serials
    exp = self.get_certificate_serials_list()
  File "/usr/share/rhsm/subscription_manager/entcertlib.py", line 229, in get_certificate_serials_list
    raise Disconnected()
Disconnected
2014-09-04 01:44:32,738 [DEBUG] subscription-manager @base_action_client.py:85 - running lib: <subscription_manager.content_action_client.ContentActionClient object at 0x31e9210>
2014-09-04 01:44:32,738 [DEBUG] subscription-manager @base_action_client.py:85 - running lib: <subscription_manager.repolib.RepoActionInvoker object at 0x31e9b90>

Comment 11 Adrian Likins 2014-09-05 13:45:31 UTC

Yup, still there. 18eeb867dc7d13958a999efb23c88258d5c0c34a was a fix for a related and similar bug, but not this one. I got them confused.

Afaict, this should only result in a logged exception, and not any functional changes.

Liushihui: Are you seeing any functional problems or crashes? Is it just the logged exception?

Comment 12 Adrian Likins 2014-09-05 15:02:08 UTC

new pr at https://github.com/candlepin/subscription-manager/pull/1019

It avoids raising the exception that is logged

Comment 14 Adrian Likins 2014-09-05 19:10:57 UTC

commit 9b8708421f02c5cf8515bde1fa6c9895a87de377
Author: Adrian Likins <alikins@redhat.com>
Date:   Fri Sep 5 10:50:06 2014 -0400

    1128061: Don't raise logged Disconnected on unreg
    
    BaseActionInvoker handles and logs any exceptions
    raise from *certlib actions. For unregister, when we
    run the UnregisterAction, we have already deleted
    id cert, ent certs, repos, so we would always raise
    Disconnected, and then it would get logged.
    
    In either cause, entcertlib's actions don't do much,
    so just return empty results instead of raising an
    exception that gets logged.

Comment 15 Liushihui 2014-09-06 15:13:04 UTC

Hi,Adrian

   I haven't seen any functional problems , it's just the logged exception. Thanks.
 
(In reply to Adrian Likins from comment #11)
> Yup, still there. 18eeb867dc7d13958a999efb23c88258d5c0c34a was a fix for a
> related and similar bug, but not this one. I got them confused.
> 
> Afaict, this should only result in a logged exception, and not any
> functional changes.
> 
> Liushihui: Are you seeing any functional problems or crashes? Is it just the
> logged exception?

Comment 16 Liushihui 2014-09-11 06:42:08 UTC

Check it on subscription-manager-1.12.14-5.el6.x86_64. it won't show [error] message when unregister system to SAM server. Please see the log as the following:
Therefore, Verify it on subscription-manager-1.12.14-5.el6.x86_64.

2014-09-11 01:26:24,917 [INFO] subscription-manager @managerlib.py:807 - Successfully un-registered.
2014-09-11 01:26:24,923 [DEBUG] subscription-manager @managerlib.py:853 - Removing identity cert: /etc/pki/consumer/key.pem
2014-09-11 01:26:24,923 [DEBUG] subscription-manager @managerlib.py:853 - Removing identity cert: /etc/pki/consumer/cert.pem
2014-09-11 01:26:24,924 [DEBUG] subscription-manager @identity.py:131 - Loading consumer info from identity certificates.
2014-09-11 01:26:24,924 [DEBUG] subscription-manager @identity.py:143 - Reload of consumer identity cert /etc/pki/consumer/cert.pem raised an exception with msg: [Errno 2] No such file or directory: '/etc/pki/consumer/key.pem'
2014-09-11 01:26:24,925 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/installed_products.json
2014-09-11 01:26:24,925 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/facts/facts.json
2014-09-11 01:26:24,925 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/entitlement_status.json
2014-09-11 01:26:24,926 [INFO] subscription-manager @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/written_overrides.json
2014-09-11 01:26:24,926 [INFO] subscription-manager @managerlib.py:878 - Cleaned local data
2014-09-11 01:26:24,927 [DEBUG] subscription-manager @base_action_client.py:85 - running lib: <subscription_manager.entcertlib.EntCertActionInvoker object at 0x33007d0>
2014-09-11 01:26:24,928 [INFO] subscription-manager @entcertlib.py:131 - certs updated:
Total updates: 0
Found (local) serial# []
Expected (UEP) serial# []
Added (new)
  <NONE>
Deleted (rogue):
  <NONE>
2014-09-11 01:26:24,929 [DEBUG] subscription-manager @base_action_client.py:85 - running lib: <subscription_manager.content_action_client.ContentActionClient object at 0x3300290>
2014-09-11 01:26:24,929 [DEBUG] subscription-manager @base_action_client.py:85 - running lib: <subscription_manager.repolib.RepoActionInvoker object at 0x3300c10>
2014-09-11 01:26:24,930 [INFO] subscription-manager @repolib.py:207 - repos updated: Repo updates

Total repo updates: 0
Updated
    <NONE>
Added (new)
    <NONE>
Deleted
    <NONE>
2014-09-11 01:26:24,932 [DEBUG] subscription-manager @certdirectory.py:216 - Installed product IDs: ['69']
2014-09-11 01:26:24,932 [DEBUG] subscription-manager @cert_sorter.py:126 - Unregistered, skipping server compliance check.
2014-09-11 01:26:25,080 [INFO] rhsmd @rhsmd:194 - rhsmd started
2014-09-11 01:26:25,099 [INFO] rhsmd @rhsmd:149 - D-Bus interface com.redhat.SubscriptionManager.EntitlementStatus.update_status called with status = 0
2014-09-11 01:26:25,129 [DEBUG] rhsmd @identity.py:131 - Loading consumer info from identity certificates.
2014-09-11 01:26:25,130 [DEBUG] rhsmd @identity.py:143 - Reload of consumer identity cert /etc/pki/consumer/cert.pem raised an exception with msg: [Errno 2] No such file or directory: '/etc/pki/consumer/key.pem'
2014-09-11 01:26:25,130 [INFO] rhsmd @rhsmd:117 - D-Bus signal com.redhat.SubscriptionManager.EntitlementStatus.entitlement_status_changed emitted

Comment 17 errata-xmlrpc 2014-10-14 07:48:11 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-2014-1384.html

Note You need to log in before you can comment on or make changes to this bug.