Bug 2025825

Summary:	anaconda timeouts waiting on timezone module
Product:	Red Hat Enterprise Linux 9	Reporter:	Sandro Bonazzola <sbonazzo>
Component:	anaconda	Assignee:	Anaconda Maintenance Team <anaconda-maint-list>
Status:	CLOSED WORKSFORME	QA Contact:	Release Test Team <release-test-team-automation>
Severity:	urgent	Docs Contact:
Priority:	urgent
Version:	CentOS Stream	CC:	bstinson, jstodola, jwboyer
Target Milestone:	rc	Keywords:	Regression
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:	2022-02-08 11:01:00 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:	1986335

Description Sandro Bonazzola 2021-11-23 06:47:05 UTC

While building oVirt Node based on CentOS Stream 9, virt-install is now failing with:

00:41:19 23:41:40,819 WARNING org.fedoraproject.Anaconda.Modules.Security:DEBUG:anaconda.modules.common.base.base:Publish the service.
00:41:41 23:41:42,951 WARNING org.fedoraproject.Anaconda.Modules.Security:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Security.
00:41:44 23:41:45,274 WARNING org.fedoraproject.Anaconda.Modules.Security:INFO:anaconda.core.dbus:Connecting to the Anaconda bus at unix:abstract=/tmp/dbus-3FCiESFRrB,guid=64cd48adc739e96a5c63b029619ad724.
00:41:46 23:42:14,042 WARNING org.fedoraproject.Anaconda.Modules.Security:DEBUG:dasbus.connection:Registering a service name org.fedoraproject.Anaconda.Modules.Security.
00:42:15 23:42:16,693 INFO dbus-daemon:Successfully activated service 'org.fedoraproject.Anaconda.Modules.Security'
00:42:19 23:42:16,874 WARNING org.fedoraproject.Anaconda.Modules.Security:DEBUG:anaconda.modules.common.base.base:Start the loop.
00:42:19 23:42:19,521 WARNING org.fedoraproject.Anaconda.Boss:DEBUG:anaconda.modules.boss.module_manager.start_modules:Service org.fedoraproject.Anaconda.Modules.Security started successfully.
00:42:20 23:42:20,720 WARNING org.fedoraproject.Anaconda.Boss:DEBUG:anaconda.modules.boss.module_manager.start_modules:org.fedoraproject.Anaconda.Modules.Security is available.
00:42:21 23:42:26,919 WARNING org.fedoraproject.Anaconda.Addons.OSCAP:DEBUG:anaconda.modules.common.base.base:Publish the service.
00:42:30 23:42:36,354 WARNING org.fedoraproject.Anaconda.Addons.OSCAP:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Addons/OSCAP.
00:42:37 23:42:36,585 WARNING org.fedoraproject.Anaconda.Addons.OSCAP:INFO:anaconda.core.dbus:Connecting to the Anaconda bus at unix:abstract=/tmp/dbus-3FCiESFRrB,guid=64cd48adc739e96a5c63b029619ad724.
00:42:37 23:42:39,280 WARNING org.fedoraproject.Anaconda.Modules.Timezone:INFO:root:reading file=<gzip _io.BufferedReader name='/usr/lib/python3.9/site-packages/langtable/data/keyboards.xml.gz' 0x7f504b094130>
00:42:40 23:42:44,417 WARNING org.fedoraproject.Anaconda.Modules.Timezone:INFO:root:reading file=<gzip _io.BufferedReader name='/usr/lib/python3.9/site-packages/langtable/data/timezones.xml.gz' 0x7f504b79c6d0>
00:42:45 23:42:44,553 WARNING org.fedoraproject.Anaconda.Modules.Timezone:INFO:root:reading file=<gzip _io.BufferedReader name='/usr/lib/python3.9/site-packages/langtable/data/timezoneidparts.xml.gz' 0x7f504b2e4eb0>
00:42:45 23:42:46,905 WARNING org.fedoraproject.Anaconda.Modules.Storage:INFO:program:Running [2] lvm version ...
00:42:47 23:42:50,366 WARNING org.fedoraproject.Anaconda.Modules.Payloads:DEBUG:anaconda.modules.common.base.base:Publish the service.
00:42:51 23:42:50,908 WARNING org.fedoraproject.Anaconda.Modules.Payloads:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Payloads.
00:42:51 23:42:51,227 WARNING org.fedoraproject.Anaconda.Modules.Payloads:INFO:anaconda.core.dbus:Connecting to the Anaconda bus at unix:abstract=/tmp/dbus-3FCiESFRrB,guid=64cd48adc739e96a5c63b029619ad724.
00:42:51 23:42:51,436 WARNING org.fedoraproject.Anaconda.Addons.OSCAP:DEBUG:dasbus.connection:Registering a service name org.fedoraproject.Anaconda.Addons.OSCAP.
00:42:52 23:42:52,843 INFO dbus-daemon:Successfully activated service 'org.fedoraproject.Anaconda.Addons.OSCAP'
00:42:53 23:42:53,284 WARNING org.fedoraproject.Anaconda.Addons.OSCAP:DEBUG:anaconda.modules.common.base.base:Start the loop.
00:42:54 23:42:55,280 WARNING org.fedoraproject.Anaconda.Boss:DEBUG:anaconda.modules.boss.module_manager.start_modules:Service org.fedoraproject.Anaconda.Addons.OSCAP started successfully.
00:42:56 23:42:55,562 WARNING org.fedoraproject.Anaconda.Boss:DEBUG:anaconda.modules.boss.module_manager.start_modules:org.fedoraproject.Anaconda.Addons.OSCAP is available.
00:42:56 23:42:59,099 WARNING org.fedoraproject.Anaconda.Modules.Payloads:DEBUG:dasbus.connection:Registering a service name org.fedoraproject.Anaconda.Modules.Payloads.
00:42:59 23:43:00,492 INFO dbus-daemon:Successfully activated service 'org.fedoraproject.Anaconda.Modules.Payloads'
00:43:01 23:43:00,562 WARNING org.fedoraproject.Anaconda.Modules.Payloads:DEBUG:anaconda.modules.common.base.base:Start the loop.
00:43:01 23:43:00,898 WARNING org.fedoraproject.Anaconda.Boss:DEBUG:anaconda.modules.boss.module_manager.start_modules:Service org.fedoraproject.Anaconda.Modules.Payloads started successfully.
00:43:01 23:43:00,969 WARNING org.fedoraproject.Anaconda.Boss:DEBUG:anaconda.modules.boss.module_manager.start_modules:org.fedoraproject.Anaconda.Modules.Payloads is available.
00:43:01 23:43:13,297 WARNING org.fedoraproject.Anaconda.Modules.Localization:INFO:root:reading file=<gzip _io.BufferedReader name='/usr/lib/python3.9/site-packages/langtable/data/keyboards.xml.gz' 0x7f2f79c580d0>
00:43:14 23:43:19,253 NOTICE dbus-daemon:Failed to activate service 'org.fedoraproject.Anaconda.Modules.Timezone': timed out (service_start_timeout=600000ms)
00:43:19 23:43:20,241 NOTICE dbus-daemon:Failed to activate service 'org.fedoraproject.Anaconda.Modules.Localization': timed out (service_start_timeout=600000ms)
00:43:20 23:43:20,341 NOTICE dbus-daemon:Failed to activate service 'org.fedoraproject.Anaconda.Modules.Users': timed out (service_start_timeout=600000ms)
00:43:20 23:43:21,384 WARNING org.fedoraproject.Anaconda.Modules.Localization:INFO:root:reading file=<gzip _io.BufferedReader name='/usr/lib/python3.9/site-packages/langtable/data/timezones.xml.gz' 0x7f2f79c589d0>
00:43:21 23:43:21,544 WARNING org.fedoraproject.Anaconda.Modules.Localization:INFO:root:reading file=<gzip _io.BufferedReader name='/usr/lib/python3.9/site-packages/langtable/data/timezoneidparts.xml.gz' 0x7f2f79c58040>
00:43:21 23:43:22,651 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.threading:Thread Failed: AnaTaskThread-StartModulesTask-1 (140620689708608)
00:43:23 23:43:23,086 WARNING org.fedoraproject.Anaconda.Modules.Storage:INFO:program:stdout[2]:   LVM version:     2.03.14(2) (2021-10-20)
00:43:23 23:43:23,086 WARNING org.fedoraproject.Anaconda.Modules.Storage:  Library version: 1.02.181 (2021-10-20)
00:43:23 23:43:23,086 WARNING org.fedoraproject.Anaconda.Modules.Storage:  Driver version:  4.45.0
00:43:23 23:43:23,086 WARNING org.fedoraproject.Anaconda.Modules.Storage:  Configuration:   ./configure --build=x86_64-redhat-linux-gnu --host=x86_64-redhat-linux-gnu --program-prefix= --disable-dependency-tracking --prefix=/usr --exec-prefix=/usr --bindir=/usr/bin --sbindir=/usr/sbin --sysconfdir=/etc --datadir=/usr/share --includedir=/usr/include --libdir=/usr/lib64 --libexecdir=/usr/libexec --localstatedir=/var --sharedstatedir=/var/lib --mandir=/usr/share/man --infodir=/usr/share/info --with-default-dm-run-dir=/run --with-default-run-dir=/run/lvm --with-default-pid-dir=/run --with-default-locking-dir=/run/lock/lvm --with-usrlibdir=/usr/lib64 --enable-fsadm --enable-write_install --with-user= --with-group= --with-device-uid=0 --with-device-gid=6 --with-device-mode=0660 --enable-pkgconfig --enable-cmdlib --enable-dmeventd --enable-blkid_wiping --with-cluster=internal --with-udevdir=/usr/lib/udev/rules.d --enable-udev_sync --with-thin=internal --with-cache=internal --enable-lvmpolld --enable-lvmlockd-dlm --enable-lvmlockd-dlmcontrol --enable-lvmlockd-sanlock --enable-dbus-service --enable-notify-dbus --enable-dmfilemapd --with-writecache=internal --with-vdo=internal --with-vdo-format=/usr/bin/vdoformat --with-integrity=internal --disable-silent-rules --enable-app-machineid --enable-editline --disable-readline
00:43:23 23:43:24,065 WARNING org.fedoraproject.Anaconda.Modules.Storage:INFO:program:stderr[2]:
00:43:24 23:43:24,833 WARNING org.fedoraproject.Anaconda.Modules.Storage:INFO:program:...done [2] (exit code: 0)
00:43:25 23:43:25,276 NOTICE dbus-daemon:Failed to activate service 'org.fedoraproject.Anaconda.Modules.Storage': timed out (service_start_timeout=600000ms)
00:43:25 23:43:25,479 NOTICE dbus-daemon:Failed to activate service 'org.fedoraproject.Anaconda.Modules.Services': timed out (service_start_timeout=600000ms)
00:43:25 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:ERROR:anaconda.modules.common.task.task:Thread AnaTaskThread-StartModulesTask-1 has failed: Traceback (most recent call last):
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:  File "/usr/lib64/python3.9/site-packages/pyanaconda/modules/boss/module_manager/start_modules.py", line 136, in _start_service_by_name_handler
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:    returned = call()
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:  File "/usr/lib/python3.9/site-packages/dasbus/client/handler.py", line 460, in <lambda>
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:    lambda: self._get_method_reply(getter),
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:  File "/usr/lib/python3.9/site-packages/dasbus/client/handler.py", line 477, in _get_method_reply
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:    return self._handle_method_error(error)
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:  File "/usr/lib/python3.9/site-packages/dasbus/client/handler.py", line 497, in _handle_method_error
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:    raise exception from None
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:dasbus.error.DBusError: Failed to activate service 'org.fedoraproject.Anaconda.Modules.Timezone': timed out (service_start_timeout=600000ms)
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:The above exception was the direct cause of the following exception:
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:Traceback (most recent call last):
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:  File "/usr/lib64/python3.9/site-packages/pyanaconda/threading.py", line 275, in run
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:    threading.Thread.run(self)
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:  File "/usr/lib64/python3.9/threading.py", line 910, in run
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:    self._target(*self._args, **self._kwargs)
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:  File "/usr/lib64/python3.9/site-packages/pyanaconda/modules/common/task/task.py", line 96, in _thread_run_callback
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:    self._task_run_callback()
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:  File "/usr/lib64/python3.9/site-packages/pyanaconda/modules/common/task/task.py", line 109, in _task_run_callback
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:    self._set_result(self.run())
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:  File "/usr/lib64/python3.9/site-packages/pyanaconda/modules/boss/module_manager/start_modules.py", line 74, in run
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:    self._process_callbacks(self._module_observers)
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:  File "/usr/lib64/python3.9/site-packages/pyanaconda/modules/boss/module_manager/start_modules.py", line 184, in _process_callbacks
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:    is_available = callback(observer)
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:  File "/usr/lib64/python3.9/site-packages/pyanaconda/modules/boss/module_manager/start_modules.py", line 138, in _start_service_by_name_handler
00:43:27 23:43:25,574 WARNING org.fedoraproject.Anaconda.Boss:    raise UnavailableModuleError(
00:43:27 23:43:25,662 WARNING org.fedoraproject.Anaconda.Boss:pyanaconda.modules.common.errors.module.UnavailableModuleError: Service org.fedoraproject.Anaconda.Modules.Timezone has failed to start: Failed to activate service 'org.fedoraproject.Anaconda.Modules.Timezone': timed out (service_start_timeout=600000ms)
00:43:27 23:43:25,700 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.threading:Thread Done: AnaTaskThread-StartModulesTask-1 (140620689708608)
00:43:27 2021-11-21 18:43:26,945: Installation error detected. See logfile for details.
00:43:27 2021-11-21 18:43:26,948: VirtualInstall failed: QEMUInstall failed
00:43:27 2021-11-21 18:43:26,949: unmounting the iso
00:43:27 2021-11-21 18:43:27,421: Install failed: QEMUInstall failed


This started to happen around November 15th. 

The job is running here: https://jenkins.ovirt.org/job/ovirt-node-ng-image_master_build-artifacts-el9stream-x86_64/
you can get both the successfull build logs and the failing build log

Comment 1 Jan Stodola 2021-11-23 09:22:52 UTC

Hello,
such timeouts usually happen on system with poor performance. Could you please check the system you are using to build the images?

Even in case of a successful run (build 70), it took 13 minutes to (re)generate initramfs, which seems to be quite slow:

01:25:35 00:25:34,616 WARNING org.fedoraproject.Anaconda.Modules.Storage:INFO:program:Running in chroot '/mnt/sysroot'... dracut -f /boot/initramfs-5.14.0-12.el9.x86_64.img 5.14.0-12.el9.x86_64
01:38:47 00:38:46,702 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:program:Return code: 0

Comment 2 Sandro Bonazzola 2021-11-23 14:02:56 UTC

The system is a 12 GB ram VM with 2 VCPUs Westmere E56xx/L56xx/X56xx (Nehalem-C) @2GHz 
# dd if=/dev/zero of=/tmp/test1.img bs=1G count=1 oflag=dsync
1+0 records in
1+0 records out
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 27.9559 s, 38.4 MB/s

Comment 3 Jan Stodola 2022-01-14 14:36:02 UTC

Sandro,
can you please confirm this issue is still happening? Unfortunately I could not find any failed jenkins job in the link from comment 0 that would fail due to the problem described in this bug.

Comment 4 Sandro Bonazzola 2022-02-08 11:01:00 UTC

I'm not able to reproduce this anymore, closing this as works for me now.