Bug 2076948
Summary: | [kickstart tests failure] 01:22:35,944 INFO rhsm-service:configparser.NoSectionError: No section: 'logging' | ||||||
---|---|---|---|---|---|---|---|
Product: | Red Hat Enterprise Linux 8 | Reporter: | Radek Vykydal <rvykydal> | ||||
Component: | subscription-manager | Assignee: | Jiri Hnidek <jhnidek> | ||||
Status: | CLOSED ERRATA | QA Contact: | Jan Stodola <jstodola> | ||||
Severity: | unspecified | Docs Contact: | |||||
Priority: | unspecified | ||||||
Version: | --- | CC: | jkonecny, jstodola, mkolman, redakkan | ||||
Target Milestone: | rc | Keywords: | Triaged | ||||
Target Release: | 8.9 | ||||||
Hardware: | Unspecified | ||||||
OS: | Unspecified | ||||||
Whiteboard: | |||||||
Fixed In Version: | subscription-manager-1.28.37-1.el8 | Doc Type: | No Doc Update | ||||
Doc Text: | Story Points: | --- | |||||
Clone Of: | |||||||
: | 2093883 (view as bug list) | Environment: | |||||
Last Closed: | 2023-11-14 15:47:57 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: | |||||||
Bug Depends On: | |||||||
Bug Blocks: | 2093883 | ||||||
Attachments: |
|
Description
Radek Vykydal
2022-04-20 09:46:21 UTC
Hi Radku, if this will happen more often or again in the next minor RHEL releases, please comment here in the bug. (In reply to Jiri Konecny from comment #1) > Hi Radku, if this will happen more often or again in the next minor RHEL > releases, please comment here in the bug. Still seen with the same frequency on RHEL 8.6: 1/1351, 3/1351. We have seen it for the first time on RHEL 9.0: https://bugzilla.redhat.com/show_bug.cgi?id=2093883. I'll confirm the situation for RHEL 8.7. Martine, could you please quick look if this should be switched to the rhsm component? The traceback is clearly from their code, question is if this is because of invalid data we are giving them. (In reply to Jiri Konecny from comment #3) > Martine, could you please quick look if this should be switched to the rhsm > component? The traceback is clearly from their code, question is if this is > because of invalid data we are giving them. I think what we do is correct, but is seems like the config access is not atomic and it is possible to hit a time window, likely when the config file is being re/loaded, when RHSM things a given config section does not exist when we try to set a value in it. So reassigning to RHSM. Looks like there is another variant of this traceback in a recent test run (https://github.com/rhinstaller/kickstart-tests/issues/779): 01:29:32,837 WARNING org.fedoraproject.Anaconda.Modules.Subscription:INFO:anaconda.threading:Running Thread: AnaTaskThread-RestoreRHSMDefaultsTask-1 (140314837796608) 01:29:32,844 WARNING org.fedoraproject.Anaconda.Modules.Subscription:DEBUG:anaconda.modules.subscription.installation:subscription: setting RHSM log level back to INFO 01:29:32,844 WARNING org.fedoraproject.Anaconda.Modules.Subscription:DEBUG:anaconda.modules.subscription.installation:subscription: making sure RHSM SSL certificate validation is enabled 01:29:32,953 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:122] Setting new configuration values: {'logging.default_log_level': 'INFO', 'server.insecure': '0'} 01:29:32,958 INFO rhsm-service:DEBUG [rhsmlib.dbus.server:231] Disabling directory watcher: CONFIG_WATCHER 01:29:32,959 INFO rhsm-service:DEBUG [rhsmlib.file_monitor:307] Temporary disabled watcher: /etc/rhsm/rhsm.conf for 5 seconds 01:29:33,005 INFO rhsm-service:DEBUG [rhsmlib.file_monitor:186] Thread Thread-FileSystemWatcher: Some event occurred: /etc/rhsm (/etc/rhsm/tmpzqhtcgix) 01:29:33,006 INFO rhsm-service:DEBUG [rhsmlib.dbus.server:247] Enabling directory watcher: CONFIG_WATCHER 01:29:33,011 INFO rhsm-service:WARNING [rhsm.logutil:170] logging already initialized 01:29:33,120 INFO rhsm-service:ERROR [rhsmlib.dbus.util:41] 'Undefined' object is not iterable 01:29:33,120 INFO rhsm-service:Traceback (most recent call last): 01:29:33,120 INFO rhsm-service: File "/usr/lib64/python3.6/site-packages/rhsmlib/dbus/util.py", line 38, in dbus_handle_exceptions 01:29:33,120 INFO rhsm-service: ret = func(*args, **kwargs) 01:29:33,120 INFO rhsm-service: File "/usr/lib64/python3.6/site-packages/rhsmlib/dbus/objects/config.py", line 151, in SetAll 01:29:33,120 INFO rhsm-service: rhsm.logutil.init_logger(parser) 01:29:33,120 INFO rhsm-service: File "/usr/lib64/python3.6/site-packages/rhsm/logutil.py", line 213, in init_logger 01:29:33,120 INFO rhsm-service: for logger_name, logging_level in config.items('logging'): 01:29:33,120 INFO rhsm-service: File "/usr/lib64/python3.6/site-packages/rhsm/config.py", line 278, in items 01:29:33,120 INFO rhsm-service: super_result = super(RhsmConfigParser, self).options(section) 01:29:33,120 INFO rhsm-service: File "/usr/lib/python3.6/site-packages/iniparse/compat.py", line 78, in options 01:29:33,120 INFO rhsm-service: return list(self.data[section]) 01:29:33,120 INFO rhsm-service:TypeError: 'Undefined' object is not iterable 01:29:33,157 INFO rhsm-service:WARNING [rhsm.logutil:170] logging already initialized 01:29:33,168 WARNING org.fedoraproject.Anaconda.Modules.Subscription:INFO:anaconda.threading:Thread Failed: AnaTaskThread-RestoreRHSMDefaultsTask-1 (140314837796608) 01:29:33,206 WARNING org.fedoraproject.Anaconda.Modules.Subscription:ERROR:anaconda.modules.common.task.task:Thread AnaTaskThread-RestoreRHSMDefaultsTask-1 has failed: Traceback (most recent call last): 01:29:33,206 WARNING org.fedoraproject.Anaconda.Modules.Subscription: File "/usr/lib64/python3.6/site-packages/pyanaconda/threading.py", line 280, in run 01:29:33,206 WARNING org.fedoraproject.Anaconda.Modules.Subscription: threading.Thread.run(self) 01:29:33,206 WARNING org.fedoraproject.Anaconda.Modules.Subscription: File "/usr/lib64/python3.6/threading.py", line 885, in run 01:29:33,206 WARNING org.fedoraproject.Anaconda.Modules.Subscription: self._target(*self._args, **self._kwargs) 01:29:33,206 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:29:33,206 WARNING org.fedoraproject.Anaconda.Modules.Subscription: self._set_result(self.run()) 01:29:33,206 WARNING org.fedoraproject.Anaconda.Modules.Subscription: File "/usr/lib64/python3.6/site-packages/pyanaconda/modules/subscription/installation.py", line 126, in run 01:29:33,206 WARNING org.fedoraproject.Anaconda.Modules.Subscription: self._rhsm_config_proxy.SetAll(config_dict, "") 01:29:33,206 WARNING org.fedoraproject.Anaconda.Modules.Subscription: File "/usr/lib/python3.6/site-packages/dasbus/client/handler.py", line 447, in _call_method 01:29:33,206 WARNING org.fedoraproject.Anaconda.Modules.Subscription: **kwargs, 01:29:33,206 WARNING org.fedoraproject.Anaconda.Modules.Subscription: File "/usr/lib/python3.6/site-packages/dasbus/client/handler.py", line 477, in _get_method_reply 01:29:33,206 WARNING org.fedoraproject.Anaconda.Modules.Subscription: return self._handle_method_error(error) 01:29:33,206 WARNING org.fedoraproject.Anaconda.Modules.Subscription: File "/usr/lib/python3.6/site-packages/dasbus/client/handler.py", line 497, in _handle_method_error 01:29:33,206 WARNING org.fedoraproject.Anaconda.Modules.Subscription: raise exception from None 01:29:33,206 WARNING org.fedoraproject.Anaconda.Modules.Subscription:dasbus.error.DBusError: {"exception": "TypeError", "severity": "error", "message": "'Undefined' object is not iterable"} 01:29:33,209 WARNING org.fedoraproject.Anaconda.Modules.Subscription:INFO:anaconda.threading:Thread Done: AnaTaskThread-RestoreRHSMDefaultsTask-1 (140314837796608) 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription:WARNING:dasbus.server.handler:The call org.fedoraproject.Anaconda.Task.Finish has failed with an exception: 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription:Traceback (most recent call last): 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: File "/usr/lib/python3.6/site-packages/dasbus/server/handler.py", line 421, in _method_callback 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: *unwrap_variant(parameters) 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: File "/usr/lib/python3.6/site-packages/dasbus/server/handler.py", line 234, in _handle_call 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: return handler(*parameters) 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: File "/usr/lib64/python3.6/site-packages/pyanaconda/modules/common/task/task_interface.py", line 114, in Finish 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: self.implementation.finish() 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: File "/usr/lib64/python3.6/site-packages/pyanaconda/modules/common/task/task.py", line 161, in finish 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: threadMgr.raise_if_error(self._thread_name) 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: File "/usr/lib64/python3.6/site-packages/pyanaconda/threading.py", line 171, in raise_if_error 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: raise exc_info[0](exc_info[1]).with_traceback(exc_info[2]) 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: File "/usr/lib64/python3.6/site-packages/pyanaconda/threading.py", line 280, in run 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: threading.Thread.run(self) 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: File "/usr/lib64/python3.6/threading.py", line 885, in run 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: self._target(*self._args, **self._kwargs) 01:29:33,861 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:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: self._set_result(self.run()) 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: File "/usr/lib64/python3.6/site-packages/pyanaconda/modules/subscription/installation.py", line 126, in run 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: self._rhsm_config_proxy.SetAll(config_dict, "") 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: File "/usr/lib/python3.6/site-packages/dasbus/client/handler.py", line 447, in _call_method 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: **kwargs, 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: File "/usr/lib/python3.6/site-packages/dasbus/client/handler.py", line 477, in _get_method_reply 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: return self._handle_method_error(error) 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: File "/usr/lib/python3.6/site-packages/dasbus/client/handler.py", line 497, in _handle_method_error 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription: raise exception from None 01:29:33,861 WARNING org.fedoraproject.Anaconda.Modules.Subscription:dasbus.error.DBusError: {"exception": "TypeError", "severity": "error", "message": "'Undefined' object is not iterable"} 01:29:33,894 INFO anaconda:anaconda: threading: Thread Failed: AnaInstallThread (139966820218624) 01:29:33,895 DEBUG anaconda:anaconda: exception: running handleException 01:29:33,913 CRIT anaconda:anaconda: exception: Traceback (most recent call last):#012#012 File "/usr/lib64/python3.6/site-packages/pyanaconda/threading.py", line 280, in run#012 threading.Thread.run(self)#012#012 File "/usr/lib64/python3.6/threading.py", line 885, in run#012 self._target(*self._args, **self._kwargs)#012#012 File "/usr/lib64/python3.6/site-packages/pyanaconda/installation.py", line 406, in run_installation#012 queue.start()#012#012 File "/usr/lib64/python3.6/site-packages/pyanaconda/installation_tasks.py", line 311, in start#012 item.start()#012#012 File "/usr/lib64/python3.6/site-packages/pyanaconda/installation_tasks.py", line 311, in start#012 item.start()#012#012 File "/usr/lib64/python3.6/site-packages/pyanaconda/installation_tasks.py", line 311, in start#012 item.start()#012#012 File "/usr/lib64/python3.6/site-packages/pyanaconda/installation_tasks.py", line 490, in start#012 self.run_task()#012#012 File "/usr/lib64/python3.6/site-packages/pyanaconda/installation_tasks.py", line 521, in run_task#012 sync_run_task(self._task_proxy)#012#012 File "/usr/lib64/python3.6/site-packages/pyanaconda/modules/common/task/__init__.py", line 46, in sync_run_task#012 task_proxy.Finish()#012#012 File "/usr/lib/python3.6/site-packages/dasbus/client/handler.py", line 447, in _call_method#012 **kwargs,#012#012 File "/usr/lib/python3.6/site-packages/dasbus/client/handler.py", line 477, in _get_method_reply#012 return self._handle_method_error(error)#012#012 File "/usr/lib/python3.6/site-packages/dasbus/client/handler.py", line 497, in _handle_method_error#012 raise exception from None#012#012dasbus.error.DBusError: {"exception": "TypeError", "severity": "error", "message": "'Undefined' object is not iterable"} 01:29:33,940 DEBUG anaconda:anaconda: exception: Gtk running, queuing exception handler to the main loop Note that the test run (that does 160+ installations) did exhibit both the traceback noted above as well as the traceback described in bug description. 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. We have not seen the issue with the latest builds, so the fix seems to work as intended. We are switching our daily kickstart-tests to RHEL 8.9 so we should see the issue disappearing from our regular tests. I'll post an update about the results into this BZ. (In reply to Radek Vykydal from comment #13) > We are switching our daily kickstart-tests to RHEL 8.9 so we should see the > issue disappearing from our regular tests. I'll post an update about the > results into this BZ. We didn't see any occurrence of the issue last week. The week before (with RHEL 8.8) there was 9 instances. @Radek: thanks for the updates, it looks promising! can you please also check the same issue in 9.3, i.e. bug 2093883? (In reply to Pino Toscano from comment #15) > @Radek: > > thanks for the updates, it looks promising! can you please also check the > same issue in 9.3, i.e. bug 2093883? Okay, I'll update a bit later there because for RHEL 9 we used to hit the issue about only a few times per month. (In reply to Radek Vykydal from comment #14) > (In reply to Radek Vykydal from comment #13) > > We are switching our daily kickstart-tests to RHEL 8.9 so we should see the > > issue disappearing from our regular tests. I'll post an update about the > > results into this BZ. > > We didn't see any occurrence of the issue last week. The week before (with > RHEL 8.8) there was 9 instances. Still no occurrence, according to our daily kickstart tests the issue seems to be fixed. Thanks for the confirmation Radek. Based on the confirmation from comment 17, there was no occurrences of this issue during the CTC1 test cycle. We consider this to be a good indicator for the provided patch. So moving the bug to verified. 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-2023:7092 |