Bug 1389559

Summary: logging to /var/log/rhsm/rhsm.log ceases after upgrade from rhel6.8 to rhel6.9
Product: Red Hat Enterprise Linux 6 Reporter: John Sefler <jsefler>
Component: subscription-managerAssignee: Kevin Howell <khowell>
Status: CLOSED ERRATA QA Contact: John Sefler <jsefler>
Severity: high Docs Contact:
Priority: high    
Version: 6.9CC: csnyder, redakkan, skallesh, vrjain
Target Milestone: rcKeywords: Regression, Triaged
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-03-21 10:56:33 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description John Sefler 2016-10-27 21:23:46 UTC 
Description of problem:
Logging to /var/log/rhsm/rhsm.log works fine with subscription-manager-1.16.8-8.el6 which was released on rhel6.8, but after yum updating to the   subscription-manager-1.18 targeted for rhel6.9, the logging to /var/log/rhsm/rhsm.log ceases.

Not sure why where the problem is, but I know the work done on bug 1334916 to benefit rhel7.3 is likely a factor.


Version-Release number of selected component (if applicable):
[root@jsefler-rhel6 ~]# rpm -q subscription-manager python-rhsm
subscription-manager-1.18.3-1.el6.x86_64
python-rhsm-1.18.4-1.el6.x86_64

How reproducible:


Steps to Reproduce:
Begin with the release rhsm packages from rhel68...
[root@jsefler-rhel6 ~]# subscription-manager versionserver type: This system is currently not registered.
subscription management server: 2.0.16-1
subscription management rules: 5.20
subscription-manager: 1.16.8-8.el6
python-rhsm: 1.16.6-1.el6
[root@jsefler-rhel6 ~]# yum update subscription* python-rhsm* --enablerepo=latest*Loaded plugins: product-id, refresh-packagekit, search-disabled-repos, security,
              : subscription-manager
This system is not registered to Red Hat Subscription Management. You can use subscription-manager to register.
Setting up Update Process
Resolving Dependencies
--> Running transaction check
---> Package python-rhsm.x86_64 0:1.16.6-1.el6 will be updated
---> Package python-rhsm.x86_64 0:1.18.4-1.el6 will be an update
---> Package subscription-manager.x86_64 0:1.16.8-8.el6 will be updated
---> Package subscription-manager.x86_64 0:1.18.3-1.el6 will be an update
--> Finished Dependency Resolution

Dependencies Resolved

====================================================================================
 Package                  Arch       Version          Repository               Size
====================================================================================
Updating:
 python-rhsm              x86_64     1.18.4-1.el6     latest-rhel6-server     116 k
 subscription-manager     x86_64     1.18.3-1.el6     latest-rhel6-server     904 k

Transaction Summary
====================================================================================
Upgrade       2 Package(s)

Total download size: 1.0 M
Is this ok [y/N]: y
Downloading Packages:
(1/2): python-rhsm-1.18.4-1.el6.x86_64.rpm                   | 116 kB     00:00     
(2/2): subscription-manager-1.18.3-1.el6.x86_64.rpm          | 904 kB     00:00     
------------------------------------------------------------------------------------
Total                                               5.6 MB/s | 1.0 MB     00:00     
Running rpm_check_debug
Running Transaction Test
Transaction Test Succeeded
Running Transaction
  Updating   : python-rhsm-1.18.4-1.el6.x86_64                                  1/4 
  Updating   : subscription-manager-1.18.3-1.el6.x86_64                         2/4 
warning: /etc/rhsm/rhsm.conf created as /etc/rhsm/rhsm.conf.rpmnew
  Cleanup    : subscription-manager-1.16.8-8.el6.x86_64                         3/4 
  Cleanup    : python-rhsm-1.16.6-1.el6.x86_64                                  4/4 
  Verifying  : subscription-manager-1.18.3-1.el6.x86_64                         1/4 
  Verifying  : python-rhsm-1.18.4-1.el6.x86_64                                  2/4 
  Verifying  : python-rhsm-1.16.6-1.el6.x86_64                                  3/4 
  Verifying  : subscription-manager-1.16.8-8.el6.x86_64                         4/4 

Updated:
  python-rhsm.x86_64 0:1.18.4-1.el6    subscription-manager.x86_64 0:1.18.3-1.el6   

Complete!
[root@jsefler-rhel6 ~]# subscription-manager version
server type: This system is currently not registered.
subscription management server: 2.0.16-1
subscription management rules: 5.20
subscription-manager: 1.18.3-1.el6
python-rhsm: 1.18.4-1.el6



 
Actual results:
 above you see three calls
   1. subscription-manager version
   2. yum update
   3. subscription-manager version
 below in Additional info you see a tail -f during the 3 calls, but nothing is appended to rhsm.log after the yum update completes.

Expected results:
 logging to /var/log/rhsm/rhsm.log should continue


Additional info:

[root@jsefler-rhel6 ~]# tail -f /var/log/rhsm/rhsm.log
2016-10-27 17:16:25,944 [DEBUG] subscription-manager:3141 @ga_loader.py:89 - ga_loader GaImporterGtk2
2016-10-27 17:16:25,949 [DEBUG] subscription-manager:3141 @plugins.py:569 - loaded plugin modules: []
2016-10-27 17:16:25,949 [DEBUG] subscription-manager:3141 @plugins.py:570 - loaded plugins: {}
2016-10-27 17:16:25,949 [DEBUG] subscription-manager:3141 @identity.py:131 - Loading consumer info from identity certificates.
2016-10-27 17:16:25,949 [DEBUG] subscription-manager:3141 @identity.py:146 - 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'
2016-10-27 17:16:25,996 [INFO] subscription-manager:3141 @managercli.py:367 - Client Versions: {'python-rhsm': '1.16.6-1.el6', 'subscription-manager': '1.16.8-8.el6'}
2016-10-27 17:16:25,996 [INFO] subscription-manager:3141 @connection.py:815 - Connection built: host=jsefler-candlepin.usersys.redhat.com port=8443 handler=/candlepin auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False
2016-10-27 17:16:25,997 [INFO] subscription-manager:3141 @connection.py:815 - Connection built: host=jsefler-candlepin.usersys.redhat.com port=8443 handler=/candlepin auth=none
2016-10-27 17:16:26,014 [DEBUG] subscription-manager:3141 @connection.py:509 - Loaded CA certificates from /etc/rhsm/ca/: jsefler-candlepin.pem, redhat-uep.pem, timeout_listener.pem
2016-10-27 17:16:26,014 [DEBUG] subscription-manager:3141 @connection.py:557 - Making request: GET /candlepin/
2016-10-27 17:16:26,166 [DEBUG] subscription-manager:3141 @connection.py:589 - Response: status=200, requestUuid=270485ed-e32c-4328-9ba0-0db73f5ee135
2016-10-27 17:16:26,168 [DEBUG] subscription-manager:3141 @connection.py:832 - Server supports the following resources: {'': '/', 'guestids': '/consumers/{consumer_uuid}/guestids', 'cdn': '/cdn', 'content_overrides': '/consumers/{consumer_uuid}/content_overrides', 'hypervisors': '/hypervisors', 'serials': '/serials', 'deleted_consumers': '/deleted_consumers', 'consumers': '/consumers', 'content': '/content', 'entitlements': '/entitlements', 'events': '/events', 'status': '/status', 'jobs': '/jobs', 'users': '/users', 'subscriptions': '/subscriptions', 'rules': '/rules', 'distributor_versions': '/distributor_versions', 'consumertypes': '/consumertypes', 'activation_keys': '/activation_keys', 'atom': '/atom', 'owners': '/owners', 'roles': '/roles', 'admin': '/admin', 'products': '/products', 'pools': '/pools', 'crl': '/crl'}
2016-10-27 17:16:26,169 [DEBUG] subscription-manager:3141 @connection.py:509 - Loaded CA certificates from /etc/rhsm/ca/: jsefler-candlepin.pem, redhat-uep.pem, timeout_listener.pem
2016-10-27 17:16:26,169 [DEBUG] subscription-manager:3141 @connection.py:557 - Making request: GET /candlepin/status
2016-10-27 17:16:26,216 [DEBUG] subscription-manager:3141 @connection.py:589 - Response: status=200, requestUuid=7bdc8cad-4f2f-43fb-82e9-07fd253a7785
2016-10-27 17:16:26,217 [INFO] subscription-manager:3141 @managercli.py:378 - Server Versions: {'rules-version': '5.20', 'candlepin': '2.0.16-1', 'server-type': 'This system is currently not registered.'}
2016-10-27 17:16:53,429 [DEBUG] yum:3143 @identity.py:131 - Loading consumer info from identity certificates.
2016-10-27 17:16:53,429 [DEBUG] yum:3143 @identity.py:146 - 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'
2016-10-27 17:16:53,467 [INFO] yum:3143 @connection.py:815 - Connection built: host=jsefler-candlepin.usersys.redhat.com port=8443 handler=/candlepin auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False
2016-10-27 17:16:53,467 [DEBUG] yum:3143 @__init__.py:85 - Searching for content of type: yum
2016-10-27 17:16:53,469 [INFO] yum:3143 @repolib.py:303 - repos updated: Repo updates

Total repo updates: 0
Updated
    <NONE>
Added (new)
    <NONE>
Deleted
    <NONE>
Comment 2 Kevin Howell 2016-11-02 20:37:11 UTC 
Fix works in both 2.6 and 2.7 (RHEL6 and RHEL7). Issue was that setLevel in 2.7 handles strings specially, but 2.6 does not.
Comment 3 Chris Snyder 2016-11-04 15:42:19 UTC 
Moving to POST as the fix has been merged to upstream master.
Comment 5 Shwetha Kallesh 2016-11-08 10:12:57 UTC 
With RHSM version :
[root@hp-ml350egen8-01 ~]# subscription-manager  version
server type: Red Hat Subscription Management
subscription management server: 0.9.51.20-1
subscription management rules: 5.15.1
subscription-manager: 1.18.3-1.el6
python-rhsm: 1.18.4-1.el6

[root@hp-ml350egen8-01 ~]# subscription-manager register 

Registering to: subscription.rhn.stage.redhat.com:443/subscription
Username: qa
Password: 
The system has been registered with ID: 5042cc50-9f67-43f7-8956-be5561d7192f 

[root@hp-ml350egen8-01 ~]# tail -f /var/log/rhsm/rhsm.log 


with version logging is fine:
[root@hp-ml350egen8-01 ~]# subscription-manager version
server type: Red Hat Subscription Management
subscription management server: 0.9.51.20-1
subscription management rules: 5.15.1
subscription-manager: 1.18.4-1.el6
python-rhsm: 1.18.4-1.el6


[root@hp-ml350egen8-01 ~]# subscription-manager register --force
The system with UUID 5042cc50-9f67-43f7-8956-be5561d7192f has been unregistered
Registering to: subscription.rhn.stage.redhat.com:443/subscription
Username: qa
Password: 
The system has been registered with ID: 59e08d4b-09de-4b0f-b5af-e731cbcf557


[root@hp-ml350egen8-01 ~]# tail -f /var/log/rhsm/rhsm.log 


2016-11-08 05:11:10,856 [INFO] subscription-manager:10918:MainThread @managercli.py:388 - Client Versions: {'python-rhsm': '1.18.4-1.el6', 'subscription-manager': '1.18.4-1.el6'}
2016-11-08 05:11:10,857 [INFO] subscription-manager:10918:MainThread @connection.py:843 - Connection built: host=subscription.rhn.stage.redhat.com port=443 handler=/subscription auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False
2016-11-08 05:11:10,858 [INFO] subscription-manager:10918:MainThread @connection.py:843 - Connection built: host=subscription.rhn.stage.redhat.com port=443 handler=/subscription auth=none
2016-11-08 05:11:12,469 [INFO] subscription-manager:10918:MainThread @managercli.py:399 - Server Versions: {'rules-version': '5.15.1', 'candlepin': '0.9.51.20-1', 'server-type': 'Red Hat Subscription Management'}
2016-11-08 05:11:27,925 [INFO] subscription-manager:10919:MainThread @managercli.py:388 - Client Versions: {'python-rhsm': '1.18.4-1.el6', 'subscription-manager': '1.18.4-1.el6'}
2016-11-08 05:11:27,926 [INFO] subscription-manager:10919:MainThread @connection.py:843 - Connection built: host=subscription.rhn.stage.redhat.com port=443 handler=/subscription auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False
2016-11-08 05:11:27,926 [INFO] subscription-manager:10919:MainThread @connection.py:843 - Connection built: host=subscription.rhn.stage.redhat.com port=443 handler=/subscription auth=none
2016-11-08 05:11:27,927 [INFO] subscription-manager:10919:MainThread @managercli.py:388 - Client Versions: {'python-rhsm': '1.18.4-1.el6', 'subscription-manager': '1.18.4-1.el6'}
2016-11-08 05:11:27,939 [INFO] subscription-manager:10919:MainThread @managercli.py:363 - Consumer Identity name=hp-ml350egen8-01.rhts.eng.bos.redhat.com uuid=5042cc50-9f67-43f7-8956-be5561d7192f
2016-11-08 05:11:27,940 [INFO] subscription-manager:10919:MainThread @managercli.py:363 - Consumer Identity name=hp-ml350egen8-01.rhts.eng.bos.redhat.com uuid=5042cc50-9f67-43f7-8956-be5561d7192f
2016-11-08 05:11:28,496 [INFO] subscription-manager:10919:MainThread @managerlib.py:793 - Successfully un-registered.
2016-11-08 05:11:28,520 [INFO] subscription-manager:10919:MainThread @managerlib.py:879 - Cleaned local data
2016-11-08 05:11:28,521 [INFO] subscription-manager:10919:MainThread @managercli.py:1098 - --force specified, unregistered old consumer: 5042cc50-9f67-43f7-8956-be5561d7192f
2016-11-08 05:11:35,723 [INFO] subscription-manager:10919:MainThread @connection.py:843 - Connection built: host=subscription.rhn.stage.redhat.com port=443 handler=/subscription auth=basic username=qa
2016-11-08 05:11:36,025 [INFO] subscription-manager:10919:MainThread @hwprobe.py:918 - collected virt facts: virt.is_guest=False, virt.host_type=Not Applicable, virt.uuid=Not Set
2016-11-08 05:11:45,178 [INFO] subscription-manager:10919:MainThread @managerlib.py:77 - Consumer created: {'consumer_name': 'hp-ml350egen8-01.rhts.eng.bos.redhat.com', 'uuid': '59e08d4b-09de-4b0f-b5af-e731cbcf557c'}
2016-11-08 05:11:45,179 [INFO] subscription-manager:10919:MainThread @connection.py:843 - Connection built: host=subscription.rhn.stage.redhat.com port=443 handler=/subscription auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False
2016-11-08 05:11:46,361 [INFO] subscription-manager:10919:MainThread @managercli.py:399 - Server Versions: {'rules-version': '5.15.1', 'candlepin': '0.9.51.20-1', 'server-type': 'Red Hat Subscription Management'}
2016-11-08 05:11:46,833 [INFO] rhsmcertd-worker:10964:MainThread @connection.py:843 - Connection built: host=subscription.rhn.stage.redhat.com port=443 handler=/subscription auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False
2016-11-08 05:11:46,949 [INFO] subscription-manager:10919:MainThread @cache.py:398 - Server does not support packages, skipping profile upload.
2016-11-08 05:11:47,623 [INFO] subscription-manager:10919:MainThread @cert_sorter.py:205 - Product status: valid_products= partial_products= expired_products= unentitled_producs=69 future_products= valid_until=None
2016-11-08 05:11:54,518 [INFO] rhsmcertd-worker:10964:MainThread @cert_sorter.py:205 - Product status: valid_products= partial_products= expired_products= unentitled_producs=69 future_products= valid_until=None
2016-11-08 05:11:54,523 [WARNING] rhsmcertd-worker:10964:MainThread @healinglib.py:97 - Found invalid entitlements for today: 2016-11-08 10:11:47.998455+00:00
2016-11-08 05:12:00,367 [INFO] rhsmcertd-worker:10964:MainThread @connection.py:843 - Connection built:
Comment 7 errata-xmlrpc 2017-03-21 10:56:33 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/RHSA-2017-0698.html