Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.

Bug 2203446

Summary: blivet-gui takes much longer to start in anaconda since Fedora-Rawhide-20230512.n.0
Product: [Fedora] Fedora Reporter: Adam Williamson <awilliam>
Component: blivet-guiAssignee: Vojtech Trefny <vtrefny>
Status: CLOSED DUPLICATE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: rawhideCC: mkolman, vtrefny
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard: openqa
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2023-05-12 21:29:40 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Adam Williamson 2023-05-12 19:59:37 UTC 
In openQA testing of today's Rawhide, several tests failed because blivet-gui took an unusually long time to start up after pressing the Done button on the INSTALLATION DESTINATION spoke with "Advanced Custom" selected. In previous runs of the same tests, blivet-gui took about 5-6 seconds to start up; it now takes more than 30 seconds.

All the tests that failed were ones where we start with a populated existing disk - e.g. the tests of reusing an existing /home partition, or resizing partitions on a disk that looks like an existing installed OS to create space for the new install. However, the startup does seem to be slower even on tests which use a completely blank disk - those tests passed, but looking at the logs, blivet-gui took nearly 30 seconds to start up even on those tests (so they *nearly* failed), whereas previously it took 3-4 seconds.

Neither anaconda nor blivet changed in the compose where this started happening, but I can't immediately see what other package would be responsible so I'm filing against blivet-gui for initial investigation. I haven't reproduced manually yet but this does seem to have happened for every blivet-gui test that ran in openQA, so it should be easy to reproduce - just grab an installer image from today's compose (e.g. https://openqa.stg.fedoraproject.org/tests/2871314/asset/iso/Fedora-Server-dvd-x86_64-Rawhide-20230512.n.0.iso ), boot it, go to INSTALLATION DESTINATION, select Advanced Custom and click Done. It will be some time before blivet-gui appears. You can compare with a Rawhide image from yesterday, or an F38 image, and see that it was much faster before.

Reproducible: Always
Comment 1 Adam Williamson 2023-05-12 20:04:34 UTC 
Here's the relevant log extract, though I can't immediately see a smoking gun. This the first message with 'blivet' in it:

09:16:45,908 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:blivet:registered device format class DeviceFormat as None

then there are several blivet-y messages over the next few seconds, until here:

09:16:49,165 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:blivet:lvm filter: clearing the lvm devices list
09:16:49,166 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:blivet:lvm filter: clearing the lvm devices list
09:16:49,166 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:blivet:trying to set new default fstype to 'xfs'
09:16:49,181 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:blivet:                XFS.supported: supported: True ;
09:16:49,188 WARNING org.fedoraproject.Anaconda.Modules.Storage:INFO:program:Running... modprobe --dry-run xfs
09:16:49,201 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:program:Return code: 0
09:16:49,202 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:blivet:get_format('xfs') returning XFS instance with object id 2
09:16:49,212 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:blivet:             XFS.supported: supported: True ;
09:16:49,213 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:anaconda.storage:trying to set new default luks version to 'luks2'
09:16:49,220 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:blivet:              LUKS.__init__: luks_version: luks2 ;
09:16:49,221 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:blivet:get_format('luks') returning LUKS instance with object id 3
09:16:49,221 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:anaconda.modules.storage.storage:The storage model has changed.
09:16:49,221 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:anaconda.modules.common.base.base:Publish the service.

and then there are no blivet-y messages for the next ~30 seconds:

09:16:49,223 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Storage/Checker.
09:16:49,223 WARNING org.fedoraproject.Anaconda.Modules.Storage:INFO:anaconda.core.dbus:Connecting to the Anaconda bus at unix:path=/tmp/dbus-ife5XrAtdQ,guid=533270ea1fd7dd91d49882b1645e03fb.
09:16:49,228 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Storage/DeviceTree.
09:16:49,229 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Storage/DiskInitialization.
09:16:49,230 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Storage/DiskSelection.
09:16:49,230 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Storage/Snapshot.
09:16:49,231 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Storage/Bootloader.
09:16:49,232 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Storage/FCoE.
09:16:49,233 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Storage/iSCSI.
09:16:49,233 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Storage/NVDIMM.
09:16:49,234 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Storage/DASD.
09:16:49,235 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Storage/zFCP.
09:16:49,235 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Storage.
09:16:49,236 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:dasbus.connection:Registering a service name org.fedoraproject.Anaconda.Modules.Storage.
09:16:49,238 INFO dbus-daemon:Successfully activated service 'org.fedoraproject.Anaconda.Modules.Storage'
09:16:49,239 WARNING org.fedoraproject.Anaconda.Boss:DEBUG:anaconda.modules.boss.module_manager.start_modules:Service org.fedoraproject.Anaconda.Modules.Storage started successfully.
09:16:49,239 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:anaconda.modules.common.base.base:Start the loop.
09:16:49,240 WARNING org.fedoraproject.Anaconda.Boss:DEBUG:anaconda.modules.boss.module_manager.start_modules:org.fedoraproject.Anaconda.Modules.Storage is available.
09:16:49,242 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.core.threads:Thread Done: AnaTaskThread-StartModulesTask-1 (140399461004992)
09:16:49,356 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.boss:Reading a kickstart file at /usr/share/anaconda/interactive-defaults.ks.
09:16:49,383 WARNING org.fedoraproject.Anaconda.Boss:WARNING:py.warnings:/usr/lib/python3.11/site-packages/pykickstart/commands/realm.py:26: DeprecationWarning: 'pipes' is deprecated and slated for removal in Python 3.13
09:16:49,383 WARNING org.fedoraproject.Anaconda.Boss:  import pipes
09:16:49,462 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.kickstart_manager.kickstart_manager:org.fedoraproject.Anaconda.Modules.Services handles commands ['firstboot', 'services', 'skipx', 'xconfig'] sections [] addons [].
09:16:49,463 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.kickstart_manager.kickstart_manager:There are no kickstart data for org.fedoraproject.Anaconda.Modules.Services.
09:16:49,467 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.kickstart_manager.kickstart_manager:org.fedoraproject.Anaconda.Modules.Network handles commands ['network', 'firewall'] sections [] addons [].
09:16:49,467 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.kickstart_manager.kickstart_manager:There are no kickstart data for org.fedoraproject.Anaconda.Modules.Network.
09:16:49,475 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.kickstart_manager.kickstart_manager:org.fedoraproject.Anaconda.Modules.Storage handles commands ['autopart', 'bootloader', 'btrfs', 'clearpart', 'fcoe', 'ignoredisk', 'iscsi', 'iscsiname', 'logvol', 'mount', 'nvdimm', 'part', 'partition', 'raid', 'reqpart', 'snapshot', 'volgroup', 'zerombr', 'zfcp', 'zipl'] sections [] addons [].
09:16:49,475 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.kickstart_manager.kickstart_manager:There are no kickstart data for org.fedoraproject.Anaconda.Modules.Storage.
09:16:49,482 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.kickstart_manager.kickstart_manager:org.fedoraproject.Anaconda.Modules.Users handles commands ['rootpw', 'user', 'group', 'sshkey'] sections [] addons [].
09:16:49,482 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.kickstart_manager.kickstart_manager:There are no kickstart data for org.fedoraproject.Anaconda.Modules.Users.
09:16:49,488 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.kickstart_manager.kickstart_manager:org.fedoraproject.Anaconda.Modules.Security handles commands ['authselect', 'selinux', 'realm'] sections [] addons [].
09:16:49,488 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.kickstart_manager.kickstart_manager:There are no kickstart data for org.fedoraproject.Anaconda.Modules.Security.
09:16:49,493 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.kickstart_manager.kickstart_manager:org.fedoraproject.Anaconda.Modules.Timezone handles commands ['timezone', 'timesource'] sections [] addons [].
09:16:49,493 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.kickstart_manager.kickstart_manager:There are no kickstart data for org.fedoraproject.Anaconda.Modules.Timezone.
09:16:49,499 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.kickstart_manager.kickstart_manager:org.fedoraproject.Anaconda.Modules.Payloads handles commands ['cdrom', 'harddrive', 'hmc', 'liveimg', 'module', 'nfs', 'ostreecontainer', 'ostreesetup', 'repo', 'url'] sections ['packages'] addons [].
09:16:49,499 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.kickstart_manager.kickstart_manager:There are no kickstart data for org.fedoraproject.Anaconda.Modules.Payloads.
09:16:49,505 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.kickstart_manager.kickstart_manager:org.fedoraproject.Anaconda.Modules.Localization handles commands ['keyboard', 'lang'] sections [] addons [].
09:16:49,505 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.kickstart_manager.kickstart_manager:There are no kickstart data for org.fedoraproject.Anaconda.Modules.Localization.
09:16:50,411 WARNING org.fedoraproject.Anaconda.Modules.Payloads:INFO:root:reading file=<gzip _io.BufferedReader name='/usr/lib/python3.11/site-packages/langtable/data/territories.xml.gz' 0x7f2e377fce80>
09:16:50,773 WARNING org.fedoraproject.Anaconda.Modules.Payloads:INFO:root:reading file=<gzip _io.BufferedReader name='/usr/lib/python3.11/site-packages/langtable/data/languages.xml.gz' 0x7f2e377fddb0>
09:16:51,107 WARNING org.fedoraproject.Anaconda.Modules.Payloads:INFO:root:reading file=<gzip _io.BufferedReader name='/usr/lib/python3.11/site-packages/langtable/data/keyboards.xml.gz' 0x7f2e377ffaf0>
09:16:51,114 WARNING org.fedoraproject.Anaconda.Modules.Payloads:INFO:root:reading file=<gzip _io.BufferedReader name='/usr/lib/python3.11/site-packages/langtable/data/timezones.xml.gz' 0x7f2e377fdf60>
09:16:51,115 WARNING org.fedoraproject.Anaconda.Modules.Payloads:INFO:root:reading file=<gzip _io.BufferedReader name='/usr/lib/python3.11/site-packages/langtable/data/timezoneidparts.xml.gz' 0x7f2e377ffbe0>
09:16:51,295 INFO systemd:NetworkManager-dispatcher.service: Deactivated successfully.
09:16:51,386 WARNING org.fedoraproject.Anaconda.Modules.Payloads:INFO:librepo:Librepo version: 1.15.1 with CURL_GLOBAL_ACK_EINTR support (libcurl/8.0.1 OpenSSL/3.0.8 zlib/1.2.13 brotli/1.0.9 libidn2/2.3.4 libpsl/0.21.2 (+libidn2/2.3.4) libssh/0.10.5/openssl/zlib nghttp2/1.53.0)
09:16:51,387 WARNING org.fedoraproject.Anaconda.Modules.Payloads:DEBUG:anaconda.modules.payloads.payloads:Created the payload PayloadType.DNF.
09:16:51,387 WARNING org.fedoraproject.Anaconda.Modules.Payloads:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Payloads/Payload/1.
09:16:51,390 WARNING org.fedoraproject.Anaconda.Modules.Payloads:DEBUG:anaconda.modules.payloads.payloads:Activated the payload PayloadType.DNF.
09:16:51,408 WARNING org.fedoraproject.Anaconda.Modules.Payloads:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Payloads/Source/1.
09:16:51,411 WARNING org.fedoraproject.Anaconda.Modules.Payloads:DEBUG:anaconda.modules.payloads.source.repo_path.repo_path:Repository path is set to: '/run/install/repo'
09:16:51,413 WARNING org.fedoraproject.Anaconda.Modules.Payloads:DEBUG:anaconda.modules.payloads.payload.payload_base:New sources [Source(type='REPO_PATH', path='/run/install/repo')] were added.
09:16:51,431 WARNING org.fedoraproject.Anaconda.Modules.Security:DEBUG:anaconda.modules.security.security:Fingerprint authentication enabled is set to True.
09:16:51,445 WARNING org.fedoraproject.Anaconda.Modules.Localization:DEBUG:anaconda.modules.localization.localization:Language is set to en_US.UTF-8.
09:16:51,450 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.boss:Setting locale of all modules to en_US.UTF-8.
09:16:51,450 WARNING org.fedoraproject.Anaconda.Boss:DEBUG:anaconda.modules.common.base.base:Locale is set to en_US.UTF-8.
09:16:51,450 WARNING org.fedoraproject.Anaconda.Boss:INFO:anaconda.modules.boss.module_manager.module_manager:Setting locale of all modules to en_US.UTF-8.
09:16:51,451 WARNING org.fedoraproject.Anaconda.Modules.Services:DEBUG:anaconda.modules.common.base.base:Locale is set to en_US.UTF-8.
09:16:51,453 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.common.base.base:Locale is set to en_US.UTF-8.
09:16:51,455 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:anaconda.modules.common.base.base:Locale is set to en_US.UTF-8.
09:16:51,457 WARNING org.fedoraproject.Anaconda.Modules.Users:DEBUG:anaconda.modules.common.base.base:Locale is set to en_US.UTF-8.
09:16:51,458 WARNING org.fedoraproject.Anaconda.Modules.Security:DEBUG:anaconda.modules.common.base.base:Locale is set to en_US.UTF-8.
09:16:51,460 WARNING org.fedoraproject.Anaconda.Modules.Timezone:DEBUG:anaconda.modules.common.base.base:Locale is set to en_US.UTF-8.
09:16:51,462 WARNING org.fedoraproject.Anaconda.Modules.Payloads:DEBUG:anaconda.modules.common.base.base:Locale is set to en_US.UTF-8.
09:16:51,463 WARNING org.fedoraproject.Anaconda.Modules.Localization:DEBUG:anaconda.modules.common.base.base:Locale is set to en_US.UTF-8.
09:16:51,467 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:Dumping configuration state - Initialization started.
09:16:51,470 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:{'connection': {'autoconnect': <false>, 'id': <'lo'>, 'interface-name': <'lo'>, 'permissions': <@as []>, 'timestamp': <uint64 1683882998>, 'type': <'loopback'>, 'uuid': <'04fc5111-9e75-45d4-aeee-29069e08b5a0'>}, 'loopback': {}, 'ipv4': {'address-data': <[{'address': <'127.0.0.1'>, 'prefix': <uint32 8>}]>, 'dns-search': <@as []>, 'method': <'manual'>, 'route-data': <@aa{sv} []>}, 'ipv6': {'address-data': <[{'address': <'::1'>, 'prefix': <uint32 128>}]>, 'dns-search': <@as []>, 'method': <'manual'>, 'route-data': <@aa{sv} []>}, 'proxy': {}}
09:16:51,470 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:{'connection': {'autoconnect-priority': <-999>, 'id': <'Wired connection 1'>, 'interface-name': <'ens4'>, 'permissions': <@as []>, 'timestamp': <uint64 1683882998>, 'type': <'802-3-ethernet'>, 'uuid': <'1d201c9d-b2e9-36fe-87d8-24e2a3b3dd6a'>}, '802-3-ethernet': {'auto-negotiate': <false>, 'mac-address-blacklist': <@as []>, 's390-options': <@a{ss} {}>}, 'ipv4': {'address-data': <@aa{sv} []>, 'dns-search': <@as []>, 'method': <'auto'>, 'route-data': <@aa{sv} []>}, 'ipv6': {'address-data': <@aa{sv} []>, 'dns-search': <@as []>, 'method': <'auto'>, 'route-data': <@aa{sv} []>}, 'proxy': {}}
09:16:51,475 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Network/Task/1.
09:16:51,480 WARNING org.fedoraproject.Anaconda.Modules.Network:INFO:anaconda.core.threads:Running Thread: AnaTaskThread-ApplyKickstartTask-1 (140527758370496)
09:16:51,480 WARNING org.fedoraproject.Anaconda.Modules.Network:INFO:anaconda.modules.common.task.task:Apply kickstart
09:16:51,488 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.nm_client:get new NM Client succeeded.
09:16:51,488 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.initialization:Apply kickstart: No kickstart data.
09:16:51,488 WARNING org.fedoraproject.Anaconda.Modules.Network:INFO:anaconda.core.threads:Thread Done: AnaTaskThread-ApplyKickstartTask-1 (140527758370496)
09:16:51,489 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:Apply kickstart result: []
09:16:51,606 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:dasbus.connection:Publishing an object at /org/fedoraproject/Anaconda/Modules/Network/Task/2.
09:16:51,615 WARNING org.fedoraproject.Anaconda.Modules.Network:INFO:anaconda.core.threads:Running Thread: AnaTaskThread-DumpMissingConfigFilesTask-1 (140527758370496)
09:16:51,615 WARNING org.fedoraproject.Anaconda.Modules.Network:INFO:anaconda.modules.common.task.task:Dump missing config files
09:16:51,630 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.nm_client:get new NM Client succeeded.
09:16:51,631 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.nm_client:Config file for ens4 not found
09:16:51,631 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.initialization:Dump missing config files: ['1d201c9d-b2e9-36fe-87d8-24e2a3b3dd6a'] connections found for device ens4
09:16:51,632 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.initialization:Dump missing config files: updating id and binding (interface-name) of connection 1d201c9d-b2e9-36fe-87d8-24e2a3b3dd6a for ens4
09:16:51,633 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.initialization:Dump missing config files: updating addr-gen-mode of connection 1d201c9d-b2e9-36fe-87d8-24e2a3b3dd6a for ens4
09:16:51,634 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.initialization:Dump missing config files: dumping connection 1d201c9d-b2e9-36fe-87d8-24e2a3b3dd6a to config file for ens4
09:16:51,636 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.core.glib:sync_call_glib[nm_remote_connection_update2]: call
09:16:51,638 DEBUG NetworkManager:<debug> [1683883011.6387] create NMAuditManager singleton (9e911c372cba1467)
09:16:51,641 DEBUG NetworkManager:<debug> [1683883011.6401] settings-connection[eef3f96c5f5025e0,1d201c9d-b2e9-36fe-87d8-24e2a3b3dd6a]: autoconnect: set blocked reason: user-request (now user-request)
09:16:51,642 DEBUG NetworkManager:<debug> [1683883011.6404] ++ connection 'update connection' (0x56480b1ecb70/NMSimpleConnection/"802-3-ethernet" < 0x56480b1b39d0/NMSimpleConnection/"802-3-ethernet") [/org/freedesktop/NetworkManager/Settings/2]:
09:16:51,642 DEBUG NetworkManager:<debug> [1683883011.6404] ++ connection                [ 0x56480b1ecce0 < 0x56480b1b3b40 ]
09:16:51,642 DEBUG NetworkManager:<debug> [1683883011.6404] ++ connection.id             = 'ens4' < 'Wired connection 1'
09:16:51,642 DEBUG NetworkManager:<debug> [1683883011.6404] ++ ipv6                      [ 0x56480b1ecea0 < 0x56480b1b41a0 ]
09:16:51,642 DEBUG NetworkManager:<debug> [1683883011.6405] ++ ipv6.addr-gen-mode        = 0
09:16:51,642 DEBUG NetworkManager:<debug> [1683883011.6409] Saving secrets for connection /org/freedesktop/NetworkManager/Settings/2 (ens4)
09:16:51,642 INFO NetworkManager:<info>  [1683883011.6410] audit: op="connection-update" uuid="1d201c9d-b2e9-36fe-87d8-24e2a3b3dd6a" name="ens4" args="ipv6.addr-gen-mode,connection.id" pid=2061 uid=0 result="success"
09:16:51,642 DEBUG NetworkManager:<debug> [1683883011.6412] device[58544ee1952c3715] (lo): add_pending_action (1): 'autoactivate'
09:16:51,642 DEBUG NetworkManager:<debug> [1683883011.6413] device[58544ee1952c3715] (lo): remove_pending_action (0): 'autoactivate'
09:16:51,646 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.core.glib:sync_call_glib[nm_remote_connection_update2]: call nm_remote_connection_update2_finish
09:16:51,647 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.core.glib:sync_call_glib[nm_remote_connection_update2]: quit
09:16:51,648 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.core.glib:sync_call_glib[nm_remote_connection_update2]: quit
09:16:51,648 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:Dump missing config files result: ['ens4']
09:16:51,648 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:Dumping configuration state - Dump missing config files
09:16:51,649 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:/etc/NetworkManager/system-connections/ens4.nmconnection:
09:16:51,649 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:[connection]
09:16:51,649 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:id=ens4
09:16:51,649 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:uuid=1d201c9d-b2e9-36fe-87d8-24e2a3b3dd6a
09:16:51,649 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:type=ethernet
09:16:51,649 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:autoconnect-priority=-999
09:16:51,650 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:interface-name=ens4
09:16:51,650 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:timestamp=1683882998
09:16:51,650 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:
09:16:51,650 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:[ethernet]
09:16:51,650 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:
09:16:51,650 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:[ipv4]
09:16:51,650 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:method=auto
09:16:51,651 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:
09:16:51,651 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:[ipv6]
09:16:51,651 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:addr-gen-mode=eui64
09:16:51,651 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:method=auto
09:16:51,651 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:
09:16:51,651 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:[proxy]
09:16:51,652 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:{'connection': {'autoconnect': <false>, 'id': <'lo'>, 'interface-name': <'lo'>, 'permissions': <@as []>, 'timestamp': <uint64 1683882998>, 'type': <'loopback'>, 'uuid': <'04fc5111-9e75-45d4-aeee-29069e08b5a0'>}, 'loopback': {}, 'ipv4': {'address-data': <[{'address': <'127.0.0.1'>, 'prefix': <uint32 8>}]>, 'dns-search': <@as []>, 'method': <'manual'>, 'route-data': <@aa{sv} []>}, 'ipv6': {'address-data': <[{'address': <'::1'>, 'prefix': <uint32 128>}]>, 'dns-search': <@as []>, 'method': <'manual'>, 'route-data': <@aa{sv} []>}, 'proxy': {}}
09:16:51,652 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:{'connection': {'autoconnect-priority': <-999>, 'id': <'ens4'>, 'interface-name': <'ens4'>, 'permissions': <@as []>, 'timestamp': <uint64 1683882998>, 'type': <'802-3-ethernet'>, 'uuid': <'1d201c9d-b2e9-36fe-87d8-24e2a3b3dd6a'>}, '802-3-ethernet': {'auto-negotiate': <false>, 'mac-address-blacklist': <@as []>, 's390-options': <@a{ss} {}>}, 'ipv4': {'address-data': <@aa{sv} []>, 'dns-search': <@as []>, 'method': <'auto'>, 'route-data': <@aa{sv} []>}, 'ipv6': {'addr-gen-mode': <0>, 'address-data': <@aa{sv} []>, 'dns-search': <@as []>, 'method': <'auto'>, 'route-data': <@aa{sv} []>}, 'proxy': {}}
09:16:51,653 WARNING org.fedoraproject.Anaconda.Modules.Network:INFO:anaconda.core.threads:Thread Done: AnaTaskThread-DumpMissingConfigFilesTask-1 (140527758370496)
09:16:51,729 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.device_configuration:add_device: not adding lo: unsupported type
09:16:51,730 WARNING org.fedoraproject.Anaconda.Modules.Network:WARNING:py.warnings:/usr/lib64/python3.11/site-packages/pyanaconda/modules/network/device_configuration.py:203: DeprecationWarning: NM.SettingConnection.get_read_only is deprecated
09:16:51,730 WARNING org.fedoraproject.Anaconda.Modules.Network:  if con_setting and con_setting.get_read_only():
09:16:51,730 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.device_configuration:add device: adding device ens4
09:16:51,731 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.device_configuration:added NetworkDeviceConfiguration(connection_uuid='1d201c9d-b2e9-36fe-87d8-24e2a3b3dd6a', device_name='ens4', device_type=<enum NM_DEVICE_TYPE_ETHERNET of type NM.DeviceType>)
09:16:51,731 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:Device configurations changed: [(NetworkDeviceConfiguration(connection_uuid='', device_name='', device_type=0), NetworkDeviceConfiguration(connection_uuid='1d201c9d-b2e9-36fe-87d8-24e2a3b3dd6a', device_name='ens4', device_type=<enum NM_DEVICE_TYPE_ETHERNET of type NM.DeviceType>))]
09:16:51,732 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.device_configuration:add_connection: not adding 04fc5111-9e75-45d4-aeee-29069e08b5a0: unsupported type
09:16:51,732 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.device_configuration:add_connection: not adding 1d201c9d-b2e9-36fe-87d8-24e2a3b3dd6a: already existing: [NetworkDeviceConfiguration(connection_uuid='1d201c9d-b2e9-36fe-87d8-24e2a3b3dd6a', device_name='ens4', device_type=<enum NM_DEVICE_TYPE_ETHERNET of type NM.DeviceType>)]
09:16:51,732 WARNING org.fedoraproject.Anaconda.Modules.Network:DEBUG:anaconda.modules.network.network:Device configurations created: [NetworkDeviceConfiguration(connection_uuid='1d201c9d-b2e9-36fe-87d8-24e2a3b3dd6a', device_name='ens4', device_type=<enum NM_DEVICE_TYPE_ETHERNET of type NM.DeviceType>)]
09:16:51,806 WARNING org.fedoraproject.Anaconda.Modules.Timezone:DEBUG:anaconda.modules.timezone.timezone:Time sources are set to: []
09:16:54,282 NOTICE audit:AVC avc:  denied  { execmem } for  pid=2162 comm="Xorg" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=process permissive=1
09:16:54,283 NOTICE kernel:audit: type=1400 audit(1683883014.281:381): avc:  denied  { execmem } for  pid=2162 comm="Xorg" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=process permissive=1
09:16:54,332 NOTICE audit:AVC avc:  denied  { map } for  pid=2162 comm="Xorg" path="/dev/dri/card0" dev="devtmpfs" ino=359 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:dri_device_t:s0 tclass=chr_file permissive=1
09:16:54,332 NOTICE kernel:audit: type=1400 audit(1683883014.331:382): avc:  denied  { map } for  pid=2162 comm="Xorg" path="/dev/dri/card0" dev="devtmpfs" ino=359 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:dri_device_t:s0 tclass=chr_file permissive=1
09:16:54,980 DEBUG spice-vdagent:vdagent virtio channel /dev/virtio-ports/com.redhat.spice.0 does not exist, exiting
09:16:54,991 NOTICE audit:AVC avc:  denied  { create } for  pid=2173 comm="systemd" name="chr" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:tmp_t:s0 tclass=chr_file permissive=1
09:16:54,991 NOTICE audit:AVC avc:  denied  { create } for  pid=2173 comm="systemd" name="blk" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:tmp_t:s0 tclass=blk_file permissive=1
09:16:54,991 NOTICE kernel:audit: type=1400 audit(1683883014.990:383): avc:  denied  { create } for  pid=2173 comm="systemd" name="chr" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:tmp_t:s0 tclass=chr_file permissive=1
09:16:54,992 NOTICE kernel:audit: type=1400 audit(1683883014.990:384): avc:  denied  { create } for  pid=2173 comm="systemd" name="blk" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:tmp_t:s0 tclass=blk_file permissive=1
09:16:55,280 INFO dbus-daemon:[session uid=0 pid=2183] SELinux support is enabled
09:16:55,294 NOTICE audit:USER_AVC pid=2185 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='avc:  denied  { send_msg } for msgtype=method_call interface=org.freedesktop.DBus member=Hello dest=org.freedesktop.DBus spid=2171 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=dbus permissive=1 exe="/usr/bin/dbus-daemon" sauid=0 hostname=? addr=? terminal=?'
09:16:55,294 NOTICE kernel:audit: type=1107 audit(1683883015.292:385): pid=2185 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='avc:  denied  { send_msg } for msgtype=method_call interface=org.freedesktop.DBus member=Hello dest=org.freedesktop.DBus spid=2171 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=dbus permissive=1 exe="/usr/bin/dbus-daemon" sauid=0 hostname=? addr=? terminal=?'
09:16:55,354 NOTICE audit:USER_AVC pid=2173 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='avc:  denied  { reload } for auid=n/a uid=0 gid=0 cmdline="" function="method_set_environment" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=system permissive=1 exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=pts/0'
09:16:55,355 NOTICE kernel:audit: type=1107 audit(1683883015.353:386): pid=2173 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='avc:  denied  { reload } for auid=n/a uid=0 gid=0 cmdline="" function="method_set_environment" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=system permissive=1 exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=pts/0'
09:16:55,537 INFO dbus-broker-launch:Policy to allow eavesdropping in /usr/share/dbus-1/session.conf +31: Eavesdropping is deprecated and ignored
09:16:55,537 INFO dbus-broker-launch:Policy to allow eavesdropping in /usr/share/dbus-1/session.conf +33: Eavesdropping is deprecated and ignored
09:16:55,542 INFO dbus-broker-launch:Ready
09:16:55,543 INFO dbus-broker-launch:avc:  denied  { send_msg } for  scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=dbus permissive=1
09:16:55,543 INFO dbus-broker-launch:avc:  denied  { acquire_svc } for  scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=dbus permissive=1
09:16:55,544 NOTICE audit:USER_AVC pid=2173 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='avc:  denied  { status } for auid=n/a uid=0 gid=0 cmdline="/usr/bin/dbus-broker-launch --scope user" function="method_subscribe" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=system permissive=1 exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=pts/0'
09:16:55,547 NOTICE kernel:audit: type=1107 audit(1683883015.543:387): pid=2173 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='avc:  denied  { status } for auid=n/a uid=0 gid=0 cmdline="/usr/bin/dbus-broker-launch --scope user" function="method_subscribe" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=system permissive=1 exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=pts/0'
09:16:55,549 NOTICE audit:USER_AVC pid=2173 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='avc:  denied  { status } for auid=n/a uid=0 gid=0 path="/usr/lib/systemd/user/at-spi-dbus-bus.service" cmdline="/usr/bin/dbus-broker-launch --scope user" function="reply_unit_path" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:mock_var_lib_t:s0 tclass=service permissive=1 exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=pts/0'
09:16:55,550 NOTICE kernel:audit: type=1107 audit(1683883015.548:388): pid=2173 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='avc:  denied  { status } for auid=n/a uid=0 gid=0 path="/usr/lib/systemd/user/at-spi-dbus-bus.service" cmdline="/usr/bin/dbus-broker-launch --scope user" function="reply_unit_path" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:mock_var_lib_t:s0 tclass=service permissive=1 exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=pts/0'
09:16:55,552 NOTICE audit:USER_AVC pid=2173 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='avc:  denied  { start } for auid=n/a uid=0 gid=0 path="/usr/lib/systemd/user/at-spi-dbus-bus.service" cmdline="/usr/bin/dbus-broker-launch --scope user" function="bus_unit_method_start_generic" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:mock_var_lib_t:s0 tclass=service permissive=1 exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=pts/0'
09:16:55,553 NOTICE kernel:audit: type=1107 audit(1683883015.551:389): pid=2173 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='avc:  denied  { start } for auid=n/a uid=0 gid=0 path="/usr/lib/systemd/user/at-spi-dbus-bus.service" cmdline="/usr/bin/dbus-broker-launch --scope user" function="bus_unit_method_start_generic" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:mock_var_lib_t:s0 tclass=service permissive=1 exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=pts/0'
09:16:55,581 WARNING journal:g_dbus_method_invocation_return_dbus_error: assertion 'error_message != NULL' failed
09:16:55,712 INFO systemd:Starting systemd-localed.service - Locale Service...
09:16:55,792 INFO systemd:Started systemd-localed.service - Locale Service.
09:16:55,805 NOTICE audit:USER_AVC pid=2185 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='avc:  denied  { acquire_svc } for service=org.gnome.Mutter.DisplayConfig spid=2171 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=dbus permissive=1 exe="/usr/bin/dbus-daemon" sauid=0 hostname=? addr=? terminal=?'
09:16:55,805 NOTICE kernel:audit: type=1107 audit(1683883015.804:390): pid=2185 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='avc:  denied  { acquire_svc } for service=org.gnome.Mutter.DisplayConfig spid=2171 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=dbus permissive=1 exe="/usr/bin/dbus-daemon" sauid=0 hostname=? addr=? terminal=?'
09:16:55,835 INFO systemd:Starting colord.service - Manage, Install and Generate Color Profiles...
09:16:55,984 INFO systemd:Started colord.service - Manage, Install and Generate Color Profiles.
09:17:16,870 INFO systemd:systemd-hostnamed.service: Deactivated successfully.
09:17:21,151 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:anaconda.modules.storage.checker.checker:Constraint 'min_ram' is set to '429916160'.
09:17:21,154 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:anaconda.modules.storage.disk_selection.selection:Disk images are set to '{}'.
09:17:21,368 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:anaconda.storage:Creating a copy of the storage model.
09:17:21,368 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:blivet:starting Blivet copy
09:17:21,369 WARNING org.fedoraproject.Anaconda.Modules.Storage:DEBUG:blivet:finished Blivet copy

Indeed there's 20 seconds there where nothing gets logged at all (this is from the 'syslog' log file). Not really sure what's going on in the gap.
Comment 2 Adam Williamson 2023-05-12 21:16:57 UTC 
It's noticeable that https://bugzilla.redhat.com/show_bug.cgi?id=2203455 broke on the same day, but I'm not *sure* if they're related. The failure mode is somewhat different: blivet-gui starts after a while, yelp never appears.
Comment 3 Adam Williamson 2023-05-12 21:29:40 UTC 
Well, actually, yelp does show up after nearly a minute. And a similar thing happens with nm-connection-editor. So...I think these three are *probably* all the same thing. Closing as a dupe of 2203455 .

*** This bug has been marked as a duplicate of bug 2203455 ***