Bug 2093883

Summary: [kickstart tests failure] 01:22:35,944 INFO rhsm-service:configparser.NoSectionError: No section: 'logging'
Product: Red Hat Enterprise Linux 9 Reporter: Radek Vykydal <rvykydal>
Component: subscription-managerAssignee: Jiri Hnidek <jhnidek>
Status: VERIFIED --- QA Contact: Jan Stodola <jstodola>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 9.0CC: anaconda-maint-list, jkonecny, jstodola, mkolman, redakkan, release-test-team
Target Milestone: rcKeywords: Triaged
Target Release: 9.3   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: subscription-manager-1.29.34-1.el9 Doc Type: No Doc Update
Doc Text:
Story Points: ---
Clone Of: 2076948 Environment:
Last Closed: 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:
Bug Depends On: 2076948    
Bug Blocks:    
Attachments:
Description Flags
virt-install.log from a kickstart test run on RHEL 9.0 none

Description Radek Vykydal 2022-06-06 09:48:52 UTC 
Created attachment 1887050 [details]
virt-install.log from a kickstart test run on RHEL 9.0

+++ This bug was initially created as a clone of Bug #2076948 +++

Description of problem:

In daily kickstart tests we have seen this failure in the logs:

01:22:35,674 WARNING org.fedoraproject.Anaconda.Modules.Subscription:DEBUG:anaconda.modules.subscription.initialization:subscription: setting RHSM log level to DEBUG
01:22:35,675 WARNING org.fedoraproject.Anaconda.Modules.Subscription:INFO:dasbus.connection:Connecting to the system bus.
01:22:35,675 WARNING org.fedoraproject.Anaconda.Modules.Subscription:INFO:dasbus.connection:Connecting to the system bus.
01:22:35,896 INFO rhsm-service:WARNING [rhsm.logutil:170] logging already initialized
01:22:35,911 INFO rhsm-service:DEBUG [rhsmlib.file_monitor:186] Thread Thread-FileSystemWatcher: Some event occurred: /etc/rhsm (/etc/rhsm/rhsm.conf)
01:22:35,944 INFO rhsm-service:ERROR [rhsmlib.dbus.util:41] No section: 'logging'
01:22:35,944 INFO rhsm-service:Traceback (most recent call last):
01:22:35,944 INFO rhsm-service:  File "/usr/lib64/python3.6/site-packages/rhsmlib/dbus/util.py", line 38, in dbus_handle_exceptions
01:22:35,944 INFO rhsm-service:    ret = func(*args, **kwargs)
01:22:35,944 INFO rhsm-service:  File "/usr/lib64/python3.6/site-packages/rhsmlib/dbus/objects/config.py", line 151, in SetAll
01:22:35,944 INFO rhsm-service:    rhsm.logutil.init_logger(parser)
01:22:35,944 INFO rhsm-service:  File "/usr/lib64/python3.6/site-packages/rhsm/logutil.py", line 213, in init_logger
01:22:35,944 INFO rhsm-service:    for logger_name, logging_level in config.items('logging'):
01:22:35,944 INFO rhsm-service:  File "/usr/lib64/python3.6/site-packages/rhsm/config.py", line 278, in items
01:22:35,944 INFO rhsm-service:    super_result = super(RhsmConfigParser, self).options(section)
01:22:35,944 INFO rhsm-service:  File "/usr/lib/python3.6/site-packages/iniparse/compat.py", line 80, in options
01:22:35,944 INFO rhsm-service:    raise NoSectionError(section)
01:22:35,944 INFO rhsm-service:configparser.NoSectionError: No section: 'logging'
01:22:35,959 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:214] files read: ['/etc/rhsm/rhsm.conf']
01:22:35,960 INFO rhsm-service:WARNING [rhsm.logutil:170] logging already initialized
01:22:35,978 WARNING org.fedoraproject.Anaconda.Modules.Subscription:INFO:anaconda.threading:Thread Failed: AnaTaskThread-StartRHSMTask-1 (140677725214464)
01:22:36,000 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:217] Configuration file: /etc/rhsm/rhsm.conf reloaded: {'server': "[('hostname', 'subscription.rhsm.redhat.com'), ('prefix', '/subscription'), ('port', '443'), ('server_timeout', '180'), ('insecure', '0'), ('ssl_verify_depth', '3'), ('proxy_hostname', ''), ('proxy_scheme', 'http'), ('proxy_user', ''), ('proxy_port', ''), ('proxy_password', ''), ('no_proxy', '')]", 'rhsm': "[('baseurl', 'https://cdn.redhat.com'), ('repomd_gpg_url', ''), ('ca_cert_dir', '/etc/rhsm/ca/'), ('repo_ca_cert', '/etc/rhsm/ca/redhat-uep.pem'), ('productcertdir', '/etc/pki/product'), ('entitlementcertdir', '/etc/pki/entitlement'), ('consumercertdir', '/etc/pki/consumer'), ('manage_repos', '1'), ('full_refresh_on_yum', '0'), ('report_package_profile', '1'), ('plugindir', '/usr/share/rhsm-plugins'), ('pluginconfdir', '/etc/rhsm/pluginconf.d'), ('auto_enable_yum_plugins', '1'), ('package_profile_on_trans', '0'), ('inotify', '1')]", 'rhsmcertd': "[('certcheckinterval', '240'), ('autoattachinterval', '1440'), ('splay', '1'), ('disable', '0'), ('auto_registration', '0'), ('auto_registration_interval', '60')]", 'logging': "[('default_log_level', 'DEBUG')]"}
01:22:36,010 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:54] D-Bus signal com.redhat.RHSM1.Config emitted
01:22:36,014 WARNING org.fedoraproject.Anaconda.Modules.Subscription:ERROR:anaconda.modules.common.task.task:Thread AnaTaskThread-StartRHSMTask-1 has failed: Traceback (most recent call last):
01:22:36,014 WARNING org.fedoraproject.Anaconda.Modules.Subscription:  File "/usr/lib64/python3.6/site-packages/pyanaconda/threading.py", line 280, in run
01:22:36,014 WARNING org.fedoraproject.Anaconda.Modules.Subscription:    threading.Thread.run(self)
01:22:36,014 WARNING org.fedoraproject.Anaconda.Modules.Subscription:  File "/usr/lib64/python3.6/threading.py", line 885, in run
01:22:36,014 WARNING org.fedoraproject.Anaconda.Modules.Subscription:    self._target(*self._args, **self._kwargs)
01:22:36,014 WARNING org.fedoraproject.Anaconda.Modules.Subscription:  File "/usr/lib64/python3.6/site-packages/pyanaconda/modules/common/task/task.py", line 97, in _task_run_callback
01:22:36,014 WARNING org.fedoraproject.Anaconda.Modules.Subscription:    self._set_result(self.run())
01:22:36,014 WARNING org.fedoraproject.Anaconda.Modules.Subscription:  File "/usr/lib64/python3.6/site-packages/pyanaconda/modules/subscription/initialization.py", line 94, in run
01:22:36,014 WARNING org.fedoraproject.Anaconda.Modules.Subscription:    rhsm_config_proxy.SetAll(config_dict, "")
01:22:36,014 WARNING org.fedoraproject.Anaconda.Modules.Subscription:  File "/usr/lib/python3.6/site-packages/dasbus/client/handler.py", line 447, in _call_method
01:22:36,014 WARNING org.fedoraproject.Anaconda.Modules.Subscription:    **kwargs,
01:22:36,014 WARNING org.fedoraproject.Anaconda.Modules.Subscription:  File "/usr/lib/python3.6/site-packages/dasbus/client/handler.py", line 477, in _get_method_reply
01:22:36,014 WARNING org.fedoraproject.Anaconda.Modules.Subscription:    return self._handle_method_error(error)
01:22:36,014 WARNING org.fedoraproject.Anaconda.Modules.Subscription:  File "/usr/lib/python3.6/site-packages/dasbus/client/handler.py", line 497, in _handle_method_error
01:22:36,014 WARNING org.fedoraproject.Anaconda.Modules.Subscription:    raise exception from None
01:22:36,014 WARNING org.fedoraproject.Anaconda.Modules.Subscription:dasbus.error.DBusError: {"exception": "NoSectionError", "severity": "error", "message": "No section: 'logging'"}
01:22:36,017 WARNING org.fedoraproject.Anaconda.Modules.Subscription:INFO:anaconda.threading:Thread Done: AnaTaskThread-StartRHSMTask-1 (140677725214464)
01:22:36,440 WARNING org.fedoraproject.Anaconda.Modules.Security:DEBUG:anaconda.modules.common.base.base:Publish the service.
01:22:36,479 WARNING org.fedoraproject.Anaconda.Modules.Security:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Security.

Version-Release number of selected component (if applicable):

RHEL 8.6 development compose
anaconda 33.16.6.7-1.el8

How reproducible:

Happened in 2/1351 tests last week (happened on Saturday, Sunday)

The tests don't seem to be related directly to rhsm module, so probably a race condition. The failed tests:

ntp-nontp-without-chrony (log attached)
http://file.brq.redhat.com/rvykydal/daily_kstest_logs/kstest-ntp-nontp-without-chrony.2022_04_17-01_19_39.wli2o5ol/

url-baseurl
http://file.brq.redhat.com/rvykydal/daily_kstest_logs/kstest-url-baseurl.2022_04_18-01_36_44.b90ep42e/

Steps to Reproduce:
1.
2.
3.

Actual results:
Task AnaTaskThread-StartRHSMTask-1 fails with traceback

Expected results:
No traceback

Additional info:

Seems to be extremely rare.

--- Additional comment from Jiri Konecny on 2022-05-06 08:47:04 UTC ---

Hi Radku, if this will happen more often or again in the next minor RHEL releases, please comment here in the bug.
Comment 1 Radek Vykydal 2022-06-06 09:50:44 UTC 
We've seen the issue for the first time in daily kickstart tests on RHEL 9. So it seems to be occuring much more rarely than on RHEL 8 (original of this clone).
Comment 2 Martin Kolman 2022-08-30 09:39:40 UTC 
RHEL 9 version of bug 2076948.
Comment 3 Radek Vykydal 2022-10-25 15:17:30 UTC 
Note on reproducibility: we hit the issue in our daily kickstart tests (we run ~200 tests each daily)
RHEL 8: ~ 1/700 tests
RHEL 9: ~ 1/6000 tests
We are able to run about 800 tests per day if we use all the resources that we do not use for current CI and daily workflows.
Comment 6 Martin Kolman 2023-03-24 12:51:34 UTC 
We have not seen the issue with the latest builds, so the fix seems to work as intended.
Comment 11 Radek Vykydal 2023-06-13 11:56:04 UTC 
We haven't hit the issue in our daily kickstart tests since the inclusion of this fix so from our POV it seems to be fixed.
Comment 12 Rehana 2023-06-27 10:58:16 UTC 
Based on the confirmation from Radek , moving the bug to verified!!