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 1774187 - Log level changes don't take effect until the rhsm.service is restarted
Summary: Log level changes don't take effect until the rhsm.service is restarted
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: subscription-manager
Version: 8.2
Hardware: All
OS: Linux
high
medium
Target Milestone: rc
: 8.3
Assignee: Jan Stavel
QA Contact: Red Hat subscription-manager QE Team
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-11-19 19:06 UTC by Martin Kolman
Modified: 2020-11-04 01:39 UTC (History)
6 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-11-04 01:38:42 UTC
Type: Bug
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github candlepin subscription-manager pull 2238 0 None closed 1774187: Reinitialize logger, when necessary; ENT-1960 2020-07-22 11:00:59 UTC
Red Hat Product Errata RHBA-2020:4460 0 None None None 2020-11-04 01:38:57 UTC

Description Martin Kolman 2019-11-19 19:06:26 UTC 
Description of problem:
If the log level is changed via the DBus interface Configuration Set() method, these changes do not take effect until the system service (rhsm.service) which provides the DBus API is restarted.

Example (calling from Python via the pydbus DBus bindings):

self.rhsm_config_proxy.Set("logging.default_log_level", get_variant(Str, "DEBUG"), "")
self.rhsm_config_proxy.Set("logging.subscription_manager", get_variant(Str, "DEBUG"), "")
self.rhsm_config_proxy.Set("logging.subscription_manager.managercli", get_variant(Str, "DEBUG"), "")
self.rhsm_config_proxy.Set("logging.rhsm", get_variant(Str, "DEBUG"), "")
self.rhsm_config_proxy.Set("logging.rhsm.connection", get_variant(Str, "DEBUG"), "")
self.rhsm_config_proxy.Set("logging.rhsm-app", get_variant(Str, "DEBUG") "")
self.rhsm_config_proxy.Set("logging.rhsm-app.rhsmd", get_variant(Str, "DEBUG"), "")


Version-Release number of selected component (if applicable):
subscription-manager-1.26.5-1.el8

How reproducible:
Always.

Steps to Reproduce:
1. set log level via DBus do DEBUG
2. check Journal

Actual results:
There are no additional RHSM log messages, only those for the default log level (IIRC INFO).

Expected results:
A lot more RHSM log messages (corresponding to the DEBUG log level) are visible in the Journal.

Additional info:
The Anaconda RHSM integration code needs to set RHSM log level to mirror the Anaconda log level. This way users can easily turn on debugging not just for Anaconda but to related tools as well via single boot options (inst.debug). We already do this for DNF and other tools).
Comment 3 Jiri Hnidek 2020-04-01 13:34:21 UTC 
Hi,
I can confirm that this still has not been fixed in master branch. You can try to reproduce/verify using following steps:

1) Edit /etc/rhsm/rhsm.conf and set logging.default_log_level to INFO

2) Display content of /var/log/rhsm/rhsm.log using: tail -f /var/log/rhsm/rhsm.log

3) Call this D-Bus method and change logging.default_log_level

busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Config com.redhat.RHSM1.Config Set svs "logging.default_log_level" s "DEBUG" ""

4) Verify that logging.default_log_level was just changed:

busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Config com.redhat.RHSM1.Config Get ss "logging.default_log_level" ""

5) Call some other D-Bus method, e.g.:

busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Entitlement com.redhat.RHSM1.Entitlement GetStatus ss "" ""

Some debug messages should appear in rhsm.log now. Something like this:

DEBUG [subscription_manager.certdirectory:217] Installed product IDs: ['900']
DEBUG [subscription_manager.cert_sorter:141] Unregistered, skipping server compliance check.
DEBUG [rhsmlib.services.entitlement:80] entitlement status: {'status': 'Unknown', 'reasons': {}, 'valid': False}

But master branch does not have this functionality ATM and rhsm.service has to be restarted.
Comment 7 Jan Stavel 2020-06-19 16:44:14 UTC 
[root@localhost ~]# rpm -qa | grep subscription
subscription-manager-rhsm-certificates-1.27.6-1.el8.x86_64
dnf-plugin-subscription-manager-1.27.6-1.el8.x86_64
python3-subscription-manager-rhsm-1.27.6-1.el8.x86_64
subscription-manager-initial-setup-addon-1.27.6-1.el8.x86_64
subscription-manager-1.27.6-1.el8.x86_64
subscription-manager-cockpit-1.27.6-1.el8.noarch


I have tried commands from jhnidek - no debug statements appeared after I set INFO level using dbus call.

[root@localhost ~]# busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Config com.redhat.RHSM1.Config Set svs "logging.default_log_level" s "DEBUG" ""

[root@localhost ~]# busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Entitlement com.redhat.RHSM1.Entitlement GetStatus ss "" ""
s "{\"status\": \"Current\", \"reasons\": {}, \"valid\": true}"

tail /var/log/rhsm/rhsm.log

[root@localhost ~]# tail /var/log/rhsm/rhsm.log 
2020-06-19 18:40:31,123 [DEBUG] rhsm-service:2474:MainThread @cache.py:307 - Started thread to write cache: /var/lib/rhsm/cache/entitlement_status.json
2020-06-19 18:40:31,133 [DEBUG] rhsm-service:2474:WriteCacheEntitlementStatusCacheThread @cache.py:115 - Wrote cache: /var/lib/rhsm/cache/entitlement_status.json
2020-06-19 18:40:31,138 [DEBUG] rhsm-service:2474:MainThread @cert_sorter.py:220 - Product status: valid_products=486 partial_products= expired_products= unentitled_producs= future_products= valid_until=2021-02-10 05:00:00+00:00
2020-06-19 18:40:31,139 [DEBUG] rhsm-service:2474:MainThread @cert_sorter.py:222 - partial stacks: []
2020-06-19 18:40:31,140 [DEBUG] rhsm-service:2474:MainThread @connection.py:676 - Making request: GET /subscription/consumers/146c7d25-ec21-45b3-a503-c93198b629ea
2020-06-19 18:40:31,143 [DEBUG] rhsm-service:2474:MainThread @connection.py:564 - Loaded CA certificates from /etc/rhsm/ca/: redhat-entitlement-authority.pem, redhat-uep.pem
2020-06-19 18:40:33,343 [DEBUG] rhsm-service:2474:MainThread @connection.py:770 - Response time: 1.5851409435272217, Smoothed response time: 1.2719582796096802
2020-06-19 18:40:33,344 [DEBUG] rhsm-service:2474:MainThread @connection.py:747 - Response: status=200, requestUuid=43554660-31d4-431e-b207-5f3b3b351a73, request="GET /subscription/consumers/146c7d25-ec21-45b3-a503-c93198b629ea"
2020-06-19 18:40:33,347 [DEBUG] rhsm-service:2474:MainThread @cache.py:307 - Started thread to write cache: /var/lib/rhsm/cache/product_status.json
2020-06-19 18:40:33,352 [DEBUG] rhsm-service:2474:WriteCacheProductStatusCacheThread @cache.py:115 - Wrote cache: /var/lib/rhsm/cache/product_status.json

[root@localhost ~]# busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Entitlement com.redhat.RHSM1.Entitlement GetStatus ss "" ""
s "{\"status\": \"Current\", \"reasons\": {}, \"valid\": true}"

[root@localhost ~]# tail /var/log/rhsm/rhsm.log 
2020-06-19 18:40:31,138 [DEBUG] rhsm-service:2474:MainThread @cert_sorter.py:220 - Product status: valid_products=486 partial_products= expired_products= unentitled_producs= future_products= valid_until=2021-02-10 05:00:00+00:00
2020-06-19 18:40:31,139 [DEBUG] rhsm-service:2474:MainThread @cert_sorter.py:222 - partial stacks: []
2020-06-19 18:40:31,140 [DEBUG] rhsm-service:2474:MainThread @connection.py:676 - Making request: GET /subscription/consumers/146c7d25-ec21-45b3-a503-c93198b629ea
2020-06-19 18:40:31,143 [DEBUG] rhsm-service:2474:MainThread @connection.py:564 - Loaded CA certificates from /etc/rhsm/ca/: redhat-entitlement-authority.pem, redhat-uep.pem
2020-06-19 18:40:33,343 [DEBUG] rhsm-service:2474:MainThread @connection.py:770 - Response time: 1.5851409435272217, Smoothed response time: 1.2719582796096802
2020-06-19 18:40:33,344 [DEBUG] rhsm-service:2474:MainThread @connection.py:747 - Response: status=200, requestUuid=43554660-31d4-431e-b207-5f3b3b351a73, request="GET /subscription/consumers/146c7d25-ec21-45b3-a503-c93198b629ea"
2020-06-19 18:40:33,347 [DEBUG] rhsm-service:2474:MainThread @cache.py:307 - Started thread to write cache: /var/lib/rhsm/cache/product_status.json
2020-06-19 18:40:33,352 [DEBUG] rhsm-service:2474:WriteCacheProductStatusCacheThread @cache.py:115 - Wrote cache: /var/lib/rhsm/cache/product_status.json
2020-06-19 18:41:06,974 [DEBUG] rhsm-service:2474:MainThread @file_monitor.py:294 - Temporary disabled watcher: /etc/rhsm/rhsm.conf for 5 seconds
2020-06-19 18:41:06,976 [WARNING] rhsm-service:2474:MainThread @logutil.py:154 - logging already initialized

.. there is no new DEBUG statement since 18:41
- I've tried to call dbus GetStatus twice to ensure that no DEBUG statement appears. Yes no DEBUG statement anymore.
Comment 10 errata-xmlrpc 2020-11-04 01:38:42 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 (subscription-manager bug fix and enhancement update), 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-2020:4460
Note You need to log in before you can comment on or make changes to this bug.