RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1207403 - Subscription-manager makes an unauthorized request after unregistering.
Summary: Subscription-manager makes an unauthorized request after unregistering.
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 6
Classification: Red Hat
Component: subscription-manager
Version: 6.7
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: rc
: 6.5
Assignee: Devan Goodwin
QA Contact: John Sefler
URL:
Whiteboard:
: 1207999 (view as bug list)
Depends On: 997935
Blocks: rhsm-rhel67
TreeView+ depends on / blocked
 
Reported: 2015-03-30 20:49 UTC by John Sefler
Modified: 2015-07-22 06:53 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of: 997935
Environment:
Last Closed: 2015-07-22 06:53:41 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Bugzilla 1207999 0 unspecified CLOSED traceback in rhsm.log after 'subscription-manager clean' 2021-02-22 00:41:40 UTC
Red Hat Product Errata RHBA-2015:1345 0 normal SHIPPED_LIVE subscription-manager and python-rhsm bug fix and enhancement update 2015-07-20 17:59:53 UTC

Internal Links: 1207999

Comment 2 John Sefler 2015-03-30 21:12:14 UTC 
Bug 997935 has re-appeared in version...

[root@jsefler-os6 ~]# subscription-manager version
server type: This system is currently not registered.
subscription management server: 0.9.26.8-1
subscription management rules: 5.12
subscription-manager: 1.14.1-1.el6
python-rhsm: 1.14.1-1.el6


[root@jsefler-os6 ~]# subscription-manager register --username=stage_auto_testuser --serverurl=subscription.rhn.stage.redhat.com:443/subscription --autosubscribe
Password: 
The system has been registered with ID: a8cb9a54-d8bb-4fd6-b0d7-c09a5c760efc 

Installed Product Current Status:
Product Name: Red Hat Enterprise Linux Server
Status:       Subscribed

[root@jsefler-os6 ~]# rm -f /var/log/rhsm/rhsm.log
[root@jsefler-os6 ~]# subscription-manager unregister
System has been unregistered.
[root@jsefler-os6 ~]# grep -A1 "Making request" /var/log/rhsm/rhsm.log
2015-03-30 16:53:55,022 [DEBUG] subscription-manager:2551 @connection.py:471 - Making request: GET /subscription/
2015-03-30 16:53:55,298 [DEBUG] subscription-manager:2551 @connection.py:494 - Response: status=200
--
2015-03-30 16:53:55,301 [DEBUG] subscription-manager:2551 @connection.py:471 - Making request: GET /subscription/status
2015-03-30 16:53:55,592 [DEBUG] subscription-manager:2551 @connection.py:494 - Response: status=200
--
2015-03-30 16:53:55,597 [DEBUG] subscription-manager:2551 @connection.py:471 - Making request: DELETE /subscription/consumers/a8cb9a54-d8bb-4fd6-b0d7-c09a5c760efc
2015-03-30 16:53:56,036 [DEBUG] subscription-manager:2551 @connection.py:494 - Response: status=204
--
2015-03-30 16:53:56,297 [DEBUG] rhsmd:2603 @connection.py:471 - Making request: GET /subscription/consumers/None/compliance
2015-03-30 16:53:56,600 [DEBUG] rhsmd:2603 @connection.py:494 - Response: status=401


BANG! An unauthorized request (401) is being set immediately after the DELETE.


Additional Log Details...

[root@jsefler-os6 ~]# cat /var/log/rhsm/rhsm.log
2015-03-30 16:53:54,954 [DEBUG] subscription-manager:2551 @plugins.py:569 - loaded plugin modules: [<module 'container_content' from '/usr/share/rhsm-plugins/container_content.pyc'>]
2015-03-30 16:53:54,954 [DEBUG] subscription-manager:2551 @plugins.py:570 - loaded plugins: {'container_content.ContainerContentPlugin': <container_content.ContainerContentPlugin object at 0x18b0e50>}
2015-03-30 16:53:54,954 [DEBUG] subscription-manager:2551 @identity.py:131 - Loading consumer info from identity certificates.
2015-03-30 16:53:55,000 [INFO] subscription-manager:2551 @managercli.py:348 - Client Versions: {'python-rhsm': '1.14.1-1.el6', 'subscription-manager': '1.14.1-1.el6'}
2015-03-30 16:53:55,000 [INFO] subscription-manager:2551 @connection.py:684 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = False
2015-03-30 16:53:55,001 [INFO] subscription-manager:2551 @connection.py:695 - Connection Built: host: subscription.rhn.stage.redhat.com, port: 443, handler: /subscription
2015-03-30 16:53:55,001 [INFO] subscription-manager:2551 @connection.py:691 - Using no auth
2015-03-30 16:53:55,001 [INFO] subscription-manager:2551 @connection.py:695 - Connection Built: host: subscription.rhn.stage.redhat.com, port: 443, handler: /subscription
2015-03-30 16:53:55,021 [DEBUG] subscription-manager:2551 @connection.py:422 - Loaded CA certificates from /etc/rhsm/ca/: candlepin-stage.pem, redhat-entitlement-authority.pem, jsefler-f14-7candlepin.pem, jsefler-os-candlepin.pem, jsefler-f14-candlepin.pem, jsefler-os6candlepin.pem, redhat-uep.pem
2015-03-30 16:53:55,022 [DEBUG] subscription-manager:2551 @connection.py:471 - Making request: GET /subscription/
2015-03-30 16:53:55,298 [DEBUG] subscription-manager:2551 @connection.py:494 - Response: status=200
2015-03-30 16:53:55,299 [DEBUG] subscription-manager:2551 @connection.py:711 - Server supports the following resources:
2015-03-30 16:53:55,299 [DEBUG] subscription-manager:2551 @connection.py:712 - {'': '/', 'guestids': '/consumers/{consumer_uuid}/guestids', 'cdn': '/cdn', 'content_overrides': '/consumers/{consumer_uuid}/content_overrides', 'hypervisors': '/hypervisors', 'serials': '/serials', 'deleted_consumers': '/deleted_consumers', 'consumers': '/consumers', 'migrations': '/migrations', 'content': '/content', 'entitlements': '/entitlements', 'events': '/events', 'status': '/status', 'jobs': '/jobs', 'users': '/users', 'subscriptions': '/subscriptions', 'rules': '/rules', 'distributor_versions': '/distributor_versions', 'statistics/generate': '/statistics/generate', 'pools': '/pools', 'atom': '/atom', 'owners': '/owners', 'roles': '/roles', 'admin': '/admin', 'products': '/products', 'activation_keys': '/activation_keys', 'consumertypes': '/consumertypes', 'crl': '/crl'}
2015-03-30 16:53:55,301 [DEBUG] subscription-manager:2551 @connection.py:422 - Loaded CA certificates from /etc/rhsm/ca/: candlepin-stage.pem, redhat-entitlement-authority.pem, jsefler-f14-7candlepin.pem, jsefler-os-candlepin.pem, jsefler-f14-candlepin.pem, jsefler-os6candlepin.pem, redhat-uep.pem
2015-03-30 16:53:55,301 [DEBUG] subscription-manager:2551 @connection.py:471 - Making request: GET /subscription/status
2015-03-30 16:53:55,592 [DEBUG] subscription-manager:2551 @connection.py:494 - Response: status=200
2015-03-30 16:53:55,593 [INFO] subscription-manager:2551 @managercli.py:359 - Server Versions: {'rules-version': '5.12', 'candlepin': '0.9.26.8-1', 'server-type': 'Red Hat Subscription Management'}
2015-03-30 16:53:55,595 [INFO] subscription-manager:2551 @managercli.py:324 - self.identity: <Identity, name=jsefler-os6, uuid=a8cb9a54-d8bb-4fd6-b0d7-c09a5c760efc, consumer=consumer: name="jsefler-os6", uuid=a8cb9a54-d8bb-4fd6-b0d7-c09a5c760efc>
2015-03-30 16:53:55,596 [DEBUG] subscription-manager:2551 @connection.py:422 - Loaded CA certificates from /etc/rhsm/ca/: candlepin-stage.pem, redhat-entitlement-authority.pem, jsefler-f14-7candlepin.pem, jsefler-os-candlepin.pem, jsefler-f14-candlepin.pem, jsefler-os6candlepin.pem, redhat-uep.pem
2015-03-30 16:53:55,597 [DEBUG] subscription-manager:2551 @connection.py:471 - Making request: DELETE /subscription/consumers/a8cb9a54-d8bb-4fd6-b0d7-c09a5c760efc
2015-03-30 16:53:56,036 [DEBUG] subscription-manager:2551 @connection.py:494 - Response: status=204
2015-03-30 16:53:56,037 [INFO] subscription-manager:2551 @managerlib.py:789 - Successfully un-registered.
2015-03-30 16:53:56,045 [DEBUG] subscription-manager:2551 @managerlib.py:835 - Removing identity cert: /etc/pki/consumer/key.pem
2015-03-30 16:53:56,046 [DEBUG] subscription-manager:2551 @managerlib.py:835 - Removing identity cert: /etc/pki/consumer/cert.pem
2015-03-30 16:53:56,046 [DEBUG] subscription-manager:2551 @identity.py:131 - Loading consumer info from identity certificates.
2015-03-30 16:53:56,046 [DEBUG] subscription-manager:2551 @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'
2015-03-30 16:53:56,047 [DEBUG] subscription-manager:2551 @managerlib.py:846 - Removing entitlement cert: /etc/pki/entitlement/4122738948275493036-key.pem
2015-03-30 16:53:56,047 [DEBUG] subscription-manager:2551 @managerlib.py:846 - Removing entitlement cert: /etc/pki/entitlement/4122738948275493036.pem
2015-03-30 16:53:56,048 [INFO] subscription-manager:2551 @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/installed_products.json
2015-03-30 16:53:56,049 [INFO] subscription-manager:2551 @cache.py:86 - Deleting cache: /var/lib/rhsm/facts/facts.json
2015-03-30 16:53:56,049 [INFO] subscription-manager:2551 @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/entitlement_status.json
2015-03-30 16:53:56,049 [INFO] subscription-manager:2551 @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/product_status.json
2015-03-30 16:53:56,049 [INFO] subscription-manager:2551 @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/content_overrides.json
2015-03-30 16:53:56,050 [INFO] subscription-manager:2551 @cache.py:86 - Deleting cache: /var/lib/rhsm/cache/written_overrides.json
2015-03-30 16:53:56,050 [INFO] subscription-manager:2551 @managerlib.py:860 - Cleaned local data
2015-03-30 16:53:56,051 [DEBUG] subscription-manager:2551 @base_action_client.py:85 - running lib: <subscription_manager.entcertlib.EntCertActionInvoker object at 0x1a24450>
2015-03-30 16:53:56,051 [INFO] subscription-manager:2551 @entcertlib.py:131 - certs updated:
Total updates: 0
Found (local) serial# []
Expected (UEP) serial# []
Added (new)
  <NONE>
Deleted (rogue):
  <NONE>
2015-03-30 16:53:56,052 [DEBUG] subscription-manager:2551 @base_action_client.py:85 - running lib: <subscription_manager.content_action_client.ContentActionClient object at 0x1a24510>
2015-03-30 16:53:56,053 [DEBUG] subscription-manager:2551 @base_action_client.py:85 - running lib: <subscription_manager.repolib.RepoActionInvoker object at 0x1a24650>
2015-03-30 16:53:56,054 [DEBUG] subscription-manager:2551 @__init__.py:85 - Searching for content of type: yum
2015-03-30 16:53:56,055 [INFO] subscription-manager:2551 @repolib.py:270 - repos updated: Repo updates

Total repo updates: 0
Updated
    <NONE>
Added (new)
    <NONE>
Deleted
    <NONE>
2015-03-30 16:53:56,056 [DEBUG] subscription-manager:2551 @plugins.py:769 - Running update_content_hook in container_content.ContainerContentPlugin
2015-03-30 16:53:56,056 [DEBUG] subscription-manager:2551 @base_action_client.py:85 - running lib: <subscription_manager.content_action_client.ContentPluginActionInvoker object at 0x1a2c1d0>
2015-03-30 16:53:56,056 [INFO] subscription-manager:2551 @container_content.py:43 - Updating container content.
2015-03-30 16:53:56,056 [INFO] subscription-manager:2551 @container_content.py:45 - registry hostnames = registry.access.redhat.com,cdn.redhat.com,access.redhat.com
2015-03-30 16:53:56,057 [DEBUG] subscription-manager:2551 @__init__.py:85 - Searching for content of type: containerimage
2015-03-30 16:53:56,057 [DEBUG] subscription-manager:2551 @container.py:53 - Got content_sets: []
2015-03-30 16:53:56,057 [DEBUG] subscription-manager:2551 @container.py:138 - Syncing container certificates to /etc/docker/certs.d/registry.access.redhat.com
2015-03-30 16:53:56,058 [DEBUG] subscription-manager:2551 @container.py:138 - Syncing container certificates to /etc/docker/certs.d/cdn.redhat.com
2015-03-30 16:53:56,058 [DEBUG] subscription-manager:2551 @container.py:138 - Syncing container certificates to /etc/docker/certs.d/access.redhat.com
2015-03-30 16:53:56,059 [DEBUG] subscription-manager:2551 @certdirectory.py:216 - Installed product IDs: ['69']
2015-03-30 16:53:56,059 [DEBUG] subscription-manager:2551 @cert_sorter.py:126 - Unregistered, skipping server compliance check.
2015-03-30 16:53:56,066 [DEBUG] subscription-manager:2551 @utils.py:284 - No virt-who pid file, not attempting to restart
2015-03-30 16:53:56,235 [INFO] rhsmd:2603 @rhsmd:276 - rhsmd started
2015-03-30 16:53:56,245 [INFO] rhsmd:2603 @rhsmd:186 - D-Bus interface com.redhat.SubscriptionManager.EntitlementStatus.update_status called with status = 0
2015-03-30 16:53:56,287 [DEBUG] rhsmd:2603 @identity.py:131 - Loading consumer info from identity certificates.
2015-03-30 16:53:56,288 [DEBUG] rhsmd:2603 @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'
2015-03-30 16:53:56,288 [INFO] rhsmd:2603 @rhsmd:154 - D-Bus signal com.redhat.SubscriptionManager.EntitlementStatus.entitlement_status_changed emitted
2015-03-30 16:53:56,288 [INFO] rhsmd:2603 @rhsmd:201 - D-Bus interface com.redhat.SubscriptionManager.EntitlementStatus.emit_status called 
2015-03-30 16:53:56,294 [DEBUG] rhsmd:2603 @certdirectory.py:216 - Installed product IDs: ['69']
2015-03-30 16:53:56,294 [DEBUG] rhsmd:2603 @cert_sorter.py:126 - Unregistered, skipping server compliance check.
2015-03-30 16:53:56,295 [INFO] rhsmd:2603 @connection.py:684 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = False
2015-03-30 16:53:56,295 [INFO] rhsmd:2603 @connection.py:695 - Connection Built: host: subscription.rhn.stage.redhat.com, port: 443, handler: /subscription
2015-03-30 16:53:56,297 [DEBUG] rhsmd:2603 @connection.py:422 - Loaded CA certificates from /etc/rhsm/ca/: candlepin-stage.pem, redhat-entitlement-authority.pem, jsefler-f14-7candlepin.pem, jsefler-os-candlepin.pem, jsefler-f14-candlepin.pem, jsefler-os6candlepin.pem, redhat-uep.pem
2015-03-30 16:53:56,297 [DEBUG] rhsmd:2603 @connection.py:471 - Making request: GET /subscription/consumers/None/compliance
2015-03-30 16:53:56,600 [DEBUG] rhsmd:2603 @connection.py:494 - Response: status=401
Comment 4 John Sefler 2015-04-01 14:01:15 UTC 
Bumping up severity now that others are reporting it too... see bug 1207999
Comment 5 Devan Goodwin 2015-04-07 18:39:29 UTC 
*** Bug 1207999 has been marked as a duplicate of this bug. ***
Comment 6 Adrian Likins 2015-04-07 18:50:48 UTC 
This seems related to the 7.x DBUS changes. After unregistering, rhsmd is getting triggered and and attempt to use the injected injection.IDENTITY
(which is now uuid=None), and then attempts to run CertSorter which makes the request to /subscription/consumers/None/compliance. CertSorter sees the system is unregistered ala the line:

2015-03-30 16:53:56,294 [DEBUG] rhsmd:2603 @cert_sorter.py:126 - Unregistered, skipping server compliance check.

But something after that calls the compliance check.

Looks like it is likely rhsmd_d.py:StatusCheck, but unsure which DBUS method is the culprit. But several things call managerlib.refresh_compliance_status, which does not check if the system still has valid id cert before making the compliance call. 

Options include:

1) Rip out that code again

2) make managerlib.refresh_compliance_status and/or StatusChecker more aware of system registration state.
Comment 7 Adrian Likins 2015-04-07 19:02:28 UTC 
There is minor distinction with https://bugzilla.redhat.com/show_bug.cgi?id=1207999 due to the server responses, but likely the
same fix.

For https://bugzilla.redhat.com/show_bug.cgi?id=1207999 subman/rhsmd is pointed at a SAM server, and the server is responding slightly different. For the bug report here we get a 401 with a JSON body, and client raises a RestlibException. For SAM, there is no response body and client raises an
UnauthorizedException. Both are handled the same, except the UnauthorizedException has it's traceback logged. 

Root cause is the same, and the fix will be the same, so closing https://bugzilla.redhat.com/show_bug.cgi?id=1207999 as DUPLICATE is fine, just wanted to point out why the logs are different.
Comment 9 Adrian Likins 2015-04-07 20:20:43 UTC 
https://bugzilla.redhat.com/show_bug.cgi?id=1207999 mentions it happens
 on 'clean', vs the 'unregister' here. But still more or less the same cause
(subman state change triggering rhsmd, which then fails to connect).
Comment 10 Devan Goodwin 2015-04-09 18:44:37 UTC 
We believe this will be fixed by reverting the dbus code that triggers events on compliance status changes.

subscription-manager.git: cf23450fc1d519a7d0e90611499047ce2e7c3334
Will appear in subscription-manager-1.15.3-1
Comment 11 John Sefler 2015-04-20 16:16:54 UTC 
Verify Version...
[root@jsefler-os6 ~]# subscription-manager version
server type: This system is currently not registered.
subscription management server: 0.9.26.8-1
subscription management rules: 5.12
subscription-manager: 1.14.5-1.el6
python-rhsm: 1.14.2-1.el6


[root@jsefler-os6 ~]# subscription-manager register --username=stage_auto_testuser --serverurl=subscription.rhn.stage.redhat.com:443/subscription --autosubscribe
Password: 
The system has been registered with ID: bb3056a3-2ac8-406e-9150-3e16d997166d 

Installed Product Current Status:
Product Name: Red Hat Enterprise Linux Server
Status:       Subscribed

[root@jsefler-os6 ~]# rm -f /var/log/rhsm/rhsm.log
[root@jsefler-os6 ~]# subscription-manager unregister
System has been unregistered.
[root@jsefler-os6 ~]# grep -A1 "Making request" /var/log/rhsm/rhsm.log
2015-04-20 12:13:33,350 [DEBUG] subscription-manager:29291 @connection.py:494 - Making request: GET /subscription/
2015-04-20 12:13:33,648 [DEBUG] subscription-manager:29291 @connection.py:521 - Response: status=200
--
2015-04-20 12:13:33,653 [DEBUG] subscription-manager:29291 @connection.py:494 - Making request: GET /subscription/status
2015-04-20 12:13:33,948 [DEBUG] subscription-manager:29291 @connection.py:521 - Response: status=200
--
2015-04-20 12:13:33,957 [DEBUG] subscription-manager:29291 @connection.py:494 - Making request: DELETE /subscription/consumers/bb3056a3-2ac8-406e-9150-3e16d997166d
2015-04-20 12:13:34,431 [DEBUG] subscription-manager:29291 @connection.py:521 - Response: status=204
[root@jsefler-os6 ~]# 


VERIFIED: No more unexpected Response: status=401
Comment 12 errata-xmlrpc 2015-07-22 06:53:41 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.

https://rhn.redhat.com/errata/RHBA-2015-1345.html
Note You need to log in before you can comment on or make changes to this bug.