Bug 1448313

Created attachment 1276501 [details]
rhsm.log

Moving to RHEL/subscription-manager as this is seemingly related to that component and not Satellite, but I will do some testing and confirmation.

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?

*** Bug 1467837 has been marked as a duplicate of this bug. ***

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!!

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"

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..

*** Bug 1559238 has been marked as a duplicate of this bug. ***

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