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.