Bug 1448313 - rhsmd error shows when the first time register to satellite6.2.9
Summary: rhsmd error shows when the first time register to satellite6.2.9
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: subscription-manager
Version: 7.4
Hardware: x86_64
OS: Linux
medium
low
Target Milestone: pre-dev-freeze
: ---
Assignee: Jiri Hnidek
QA Contact: John Sefler
URL:
Whiteboard:
: 1467837 1559238 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-05-05 07:40 UTC by yuefliu
Modified: 2018-04-10 09:49 UTC (History)
10 users (show)

Fixed In Version: subscription-manager-1.20.10-1
Doc Type: No Doc Update
Doc Text:
undefined
Clone Of:
Environment:
Last Closed: 2018-04-10 09:49:05 UTC


Attachments (Terms of Use)
rhsm.log (23.14 KB, text/plain)
2017-05-05 07:46 UTC, yuefliu
no flags Details


Links
System ID Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2018:0681 None None None 2018-04-10 09:49:28 UTC
Github candlepin subscription-manager pull 1713 None None None 2017-10-06 08:15:52 UTC
Github candlepin subscription-manager pull 1741 None None None 2017-12-11 09:28:42 UTC

Comment 1 yuefliu 2017-05-05 07:46:37 UTC
Created attachment 1276501 [details]
rhsm.log

Comment 2 Craig Donnelly 2017-09-22 15:26:55 UTC
Moving to RHEL/subscription-manager as this is seemingly related to that component and not Satellite, but I will do some testing and confirmation.

Comment 4 Craig Donnelly 2017-09-22 18:03:56 UTC
Confirmed that this is non-specific to Satellite, the same occurs against SAM (I know, not that different.. per say), but as well against the Customer portal / Prod candlepin.

This is simply due to rhsm_icon.json not existing prior to us trying to do something with it. It gets created immediately after, and therefore you do not see the error again.

Its contents appear to always be '1'.

Can we handle this issue differently to steer people away from the "false" error?

Comment 5 Craig Donnelly 2017-09-22 18:04:57 UTC
*** Bug 1467837 has been marked as a duplicate of this bug. ***

Comment 8 Rehana 2017-11-13 10:59:28 UTC
Reproducing the failure on RHEL74 with the following build:
======================================================

# subscription-manager version
server type: Red Hat Subscription Management
subscription management server: 3.4.5.25-Unknown
subscription management rules: 5.26
subscription-manager: 1.19.21-1.el7
python-rhsm: 1.19.9-1.el7

Register system against satellite 6 server and watch the rhsm.log

Make sure rhsm_icon.json doesnt exist

# ll /var/lib/rhsm/cache/rhsm_icon.json 
ls: cannot access /var/lib/rhsm/cache/rhsm_icon.json: No such file or directory
[root@dhcp35-157 ~]# 

# subscription-manager register --username=username --password=password --org=Default_Organization --environment=Dev/rhel7_cv
Registering to: qeblade36.rhq.lab.eng.bos.redhat.com:443/rhsm
The system has been registered with ID: 3c292a80-35f9-4273-a920-281907dc0305

rhsm.log
===========
2017-11-13 16:01:07,061 [INFO] subscription-manager:11626:MainThread @connection.py:552 - Response: status=200, request="GET /rhsm/consumers/3c292a80-35f9-4273-a920-281907dc0305/compliance"
2017-11-13 16:01:07,063 [INFO] subscription-manager:11626:MainThread @cert_sorter.py:204 - Product status: valid_products= partial_products= expired_products= unentitled_producs=69 future_products= valid_until=None
2017-11-13 16:01:07,152 [INFO] rhsmd:11465:MainThread @connection.py:822 - Connection built: host=subscription.rhsm.stage.redhat.com port=443 handler=/subscription auth=identity_cert ca_dir=/etc/rhsm/ca/ insecure=False
2017-11-13 16:01:08,611 [INFO] rhsmd:11465:MainThread @connection.py:552 - Response: status=401, requestUuid=d8497379-e999-449e-908c-5628f74e8c52, request="GET /subscription/consumers/3c292a80-35f9-4273-a920-281907dc0305/compliance"
2017-11-13 16:01:08,612 [ERROR] rhsmd:11465:MainThread @cache.py:221 - Invalid credentials.
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/subscription_manager/cache.py", line 209, in load_status
    self._sync_with_server(uep, uuid)
  File "/usr/lib/python2.7/site-packages/subscription_manager/cache.py", line 318, in _sync_with_server
    self.server_status = uep.getCompliance(uuid)
  File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 1076, in getCompliance
    return self.conn.request_get(method)
  File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 646, in request_get
    return self._request("GET", method, headers=headers)
  File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 672, in _request
    info=info, headers=headers)
  File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 561, in _request
    self.validateResponse(result, request_type, handler)
  File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 610, in validateResponse
    raise RestlibException(response['status'], error_msg, response.get('headers'))
RestlibException: Invalid credentials.
2017-11-13 16:01:08,615 [ERROR] rhsmd:11465:MainThread @cache.py:128 - Unable to read cache: /var/lib/rhsm/cache/rhsm_icon.json
2017-11-13 16:01:08,615 [ERROR] rhsmd:11465:MainThread @cache.py:129 - [Errno 2] No such file or directory: '/var/lib/rhsm/cache/rhsm_icon.json'
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/subscription_manager/cache.py", line 123, in _read_cache
    f = open(self.CACHE_FILE)
IOError: [Errno 2] No such file or directory: '/var/lib/rhsm/cache/rhsm_icon.json'


Verification steps on rhel75:
=============================

Install the Satellite6 server's certificate on the system

With new fix ,the following DEBUG message should appear in log file: "Cache file: /var/lib/rhsm/cache/rhsm_icon.json does not exist yet " to view this Debug message set the log level to "Debug" 

ex: default_log_level = DEBUG

Make sure rhsm_icon.json doesn't exist

# ll /var/lib/rhsm/cache/rhsm_icon.json 
ls: cannot access /var/lib/rhsm/cache/rhsm_icon.json: No such file or directory
[root@dhcp35-157 ~]# 

2017-11-13 16:14:57,622 [DEBUG] rhsmd:32253:MainThread @cert_sorter.py:207 - partial stacks: []
2017-11-13 16:14:57,622 [DEBUG] rhsmd:32253:MainThread @cache.py:168 - Checking current system info against cache: /var/lib/rhsm/cache/installed_products.json
2017-11-13 16:14:57,627 [DEBUG] rhsmd:32253:MainThread @cache.py:185 - No changes.
2017-11-13 16:14:57,627 [DEBUG] rhsmd:32253:MainThread @identity.py:137 - Loading consumer info from identity certificates.
2017-11-13 16:14:57,628 [DEBUG] rhsmd:32253:MainThread @rhsmd:238 - Cache file: /var/lib/rhsm/cache/rhsm_icon.json does not exist yet
2017-11-13 16:14:57,629 [DEBUG] rhsmd:32253:MainThread @cache.py:114 - Wrote cache: /var/lib/rhsm/cache/rhsm_icon.json

^^ observed that a DEBUG message is now displayed in rhsm.log stating " rhsm_icon.json doesnt exist" and a new file was written.

Based on the above observations , marking the bug as verified!!

Comment 9 Rehana 2017-11-16 11:21:17 UTC
Moving the bug to "New"  based on the following observation :

1) Deploy a fresh RHEL75 machine , OR make sure that "/var/lib/rhsm/cache/rhsm_icon.json" file does not exist 

2) WITHOUT registering the sysstem , execute `service rhsmcertd restart" 

observed following error message on the rhsm.log

2017-11-16 12:39:01,884 [ERROR] rhsmd:13540:MainThread @cache.py:130 - Unable to read cache: /var/lib/rhsm/cache/rhsm_icon.json
2017-11-16 12:39:01,884 [ERROR] rhsmd:13540:MainThread @cache.py:131 - [Errno 2] No such file or directory: '/var/lib/rhsm/cache/rhsm_icon.json'
Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/subscription_manager/cache.py", line 125, in _read_cache
    f = open(self.CACHE_FILE)
IOError: [Errno 2] No such file or directory: '/var/lib/rhsm/cache/rhsm_icon.json'
2017-11-16 12:39:01,900 [DEBUG] rhsmd:13540:MainThread @rhsmd:196 - D-Bus signal com.redhat.SubscriptionManager.EntitlementStatus.entitlement_status_changed emitted
2017-11-16 12:39:01,902 [DEBUG] rhsmd:13540:MainThread @cache.py:114 - Wrote cache: /var/lib/rhsm/cache/rhsm_icon.json
^C

Similar to the fix made to this bug , (and as verified in comment 8 ) , request you  to have the same Debug messages displayed in the rhsm.log instead of the traceback error.

Based on the discussion with Jiri , moving this bug to "New"

Comment 12 Rehana 2018-02-08 11:41:44 UTC
Verifying on :
=============
subscription-manager-plugin-container-1.20.10-1.el7.x86_64
subscription-manager-rhsm-1.20.10-1.el7.x86_64
subscription-manager-plugin-ostree-1.20.10-1.el7.x86_64
subscription-manager-initial-setup-addon-1.20.10-1.el7.x86_64
subscription-manager-migration-data-2.0.37-1.el7.noarch
subscription-manager-debuginfo-1.20.10-1.el7.x86_64
subscription-manager-rhsm-certificates-1.20.10-1.el7.x86_64


Make sure the file "/var/lib/rhsm/cache/rhsm_icon.json" file does not exist 
and 

Restart rhsmcertd service ( make sure rhsmd service is running) 

2018-02-08 05:56:23,532 [DEBUG] rhsmd:31662:MainThread @connection.py:543 - Making request: GET /rhsm/consumers/5ddb16cb-5ff5-4c9c-8a4d-016a9719af79/compliance
2018-02-08 05:56:23,632 [INFO] rhsmd:31662:MainThread @connection.py:586 - Response: status=200, request="GET /rhsm/consumers/5ddb16cb-5ff5-4c9c-8a4d-016a9719af79/compliance"
2018-02-08 05:56:23,634 [DEBUG] rhsmd:31662:WriteCacheEntitlementStatusCacheThread @cache.py:114 - Wrote cache: /var/lib/rhsm/cache/entitlement_status.json
2018-02-08 05:56:23,634 [DEBUG] rhsmd:31662:MainThread @cache.py:302 - Started thread to write cache: /var/lib/rhsm/cache/entitlement_status.json
2018-02-08 05:56:23,635 [INFO] rhsmd:31662:MainThread @cert_sorter.py:205 - Product status: valid_products= partial_products= expired_products= unentitled_producs=69 and 230 future_products= valid_until=None
2018-02-08 05:56:23,635 [DEBUG] rhsmd:31662:MainThread @cert_sorter.py:207 - partial stacks: []
2018-02-08 05:56:23,635 [DEBUG] rhsmd:31662:MainThread @cache.py:169 - Checking current system info against cache: /var/lib/rhsm/cache/installed_products.json
2018-02-08 05:56:23,637 [DEBUG] rhsmd:31662:MainThread @cache.py:186 - No changes.
2018-02-08 05:56:23,637 [DEBUG] rhsmd:31662:MainThread @identity.py:137 - Loading consumer info from identity certificates.
2018-02-08 05:56:23,638 [DEBUG] rhsmd:31662:MainThread @cache.py:146 - Cache file /var/lib/rhsm/cache/rhsm_icon.json does not exist
2018-02-08 05:56:23,638 [DEBUG] rhsmd:31662:MainThread @cache.py:114 - Wrote cache: /var/lib/rhsm/cache/rhsm_icon.json


Observed that rhsm_icon.json file was created and no IO errors were observed.

Based on the observation , moving the bug as Verified..

Comment 14 Kevin Howell 2018-03-22 14:23:56 UTC
*** Bug 1559238 has been marked as a duplicate of this bug. ***

Comment 16 errata-xmlrpc 2018-04-10 09:49:05 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://access.redhat.com/errata/RHBA-2018:0681


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