Bug 1600699

Created attachment 1458525 [details]
File: anaconda-tb

Created attachment 1458526 [details]
File: anaconda.log

Created attachment 1458527 [details]
File: dbus.log

Created attachment 1458528 [details]
File: dnf.librepo.log

Created attachment 1458529 [details]
File: environ

Created attachment 1458530 [details]
File: hawkey.log

Created attachment 1458531 [details]
File: lorax-packages.log

Created attachment 1458532 [details]
File: lsblk_output

Created attachment 1458533 [details]
File: lvm.log

Created attachment 1458534 [details]
File: nmcli_dev_list

Created attachment 1458535 [details]
File: os_info

Created attachment 1458536 [details]
File: program.log

Created attachment 1458537 [details]
File: storage.log

Created attachment 1458538 [details]
File: syslog

Created attachment 1458539 [details]
File: ifcfg.log

Created attachment 1458540 [details]
File: packaging.log

This is happening in our storage library. Switching components.

Workaround for this is to force blivet to use the "old" libblockdev LVM plugin that doesn't use the DBus API. It is a simple patch (https://github.com/vojtechtrefny/blivet/commit/2f90040ff66eacc9715e370cd49ffb72d8d1f36f), I'll do a new blivet build with this for rawhide today.

python-blivet-3.1.0-0.4.b1.fc29 should fix this, but original problem is in lvmdbus -- changing component to lvm2

Martin, could you please try to run anaconda testsuite with 2.02.180 being built soon landing in rawhide repo?

(In reply to Marian Csontos from comment #24)
> Martin, could you please try to run anaconda testsuite with 2.02.180 being
> built soon landing in rawhide repo?

Sure, I'll try to do that tomorrow - but I guess I'll have to coordinate with Vojta to use a custom Blivet package with the workaround reverted so that the LVM-DBUS plugin is used again.

Looks like the race condition is still present in some form even with the new LVM package:

GLib.GError: g-io-error-quark: Failed to call the 'PvCreate' method on the '/com/redhat/lvmdbus1/Manager' object: Timeout was reached (24)

There might be a difference though - before I was getting also LvCreate & VgCreate issues, but now I see consistently only PvCreate. I'll ask Vojta on Monday to take a look at the detailed test results & to check the test setup was valid (eq. correct versions of LVM & Blivet were used).

To me this looks like different issue. In the first issue the return code was a mess. This looks just like an ordinary error.

After looking at the results with vtrefny, it looks like the new LVM version was indeed correctly used. Also all the failures now consistently look like this:

15:08:30,560 INFO anaconda:blivet: executing action: [136] create format lvmpv on mdarray pv.01 (id 131)
15:08:30,571 INFO anaconda:anaconda: progress: Creating lvmpv on /dev/md/pv.01
15:08:30,623 DEBUG anaconda:blivet:                     MDRaidArrayDevice.setup: pv.01 ; orig: False ; status: True ; controllable: True ;
15:08:30,669 DEBUG anaconda:blivet:                     LVMPhysicalVolume.create: device: /dev/md/pv.01 ; type: lvmpv ; status: False ;
15:08:30,728 DEBUG anaconda:blivet:                       LVMPhysicalVolume._create: device: /dev/md/pv.01 ; type: lvmpv ; status: False ;
15:08:30,738 INFO anaconda:program: [26] Calling the 'com.redhat.lvmdbus1.Manager.PvCreate' method on the '/com/redhat/lvmdbus1/Manager' object with the following parameters: '('/dev/md/pv.01', 1, {'--config': <' devices { preferred_names=["^/dev/mapper/", "^/dev/md/", "^/dev/sd"] } log {level=7 file=/tmp/lvm.log syslog=0}'>})'
15:08:30,751 INFO dbus-daemon:[system] Activating via systemd: service name='com.redhat.lvmdbus1' unit='lvm2-lvmdbusd.service' requested by ':1.8' (uid=0 pid=2971 comm="/usr/bin/python3 /sbin/anaconda " label="system_u:system_r:initrc_t:s0")
15:08:30,900 INFO systemd:Starting LVM2 D-Bus service...
15:08:34,021 INFO dbus-daemon:[system] Successfully activated service 'com.redhat.lvmdbus1'
15:08:34,031 NOTICE audit:SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=lvm2-lvmdbusd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
15:08:34,032 INFO systemd:Started LVM2 D-Bus service.
15:08:35,760 INFO anaconda:program: [26] Done.
15:08:35,766 INFO anaconda:program: [26] Got error: Failed to call the 'PvCreate' method on the '/com/redhat/lvmdbus1/Manager' object: Timeout was reached


Basically:
- PV creation has been requested
- the operation times out after 5 seconds

This looks like a bug as according to vtrefny the LVM DBUS API should either finish in <1 second or return a job object if the operation takes >1 seconds.

Maybe:
  1. dbus call is made and blivet/libblockdev D-Bus timeout clock starts ticking
  2. plenty of time passes while lvm D-Bus service gets started (approx 4 seconds)
  2.5 There occurs a brief hiatus while LVM D-Bus service is getting its act together and before it actually receives the message
  3. LVM D-Bus service gets a D-Bus message. Its 1 second clock starts ticking, but before that limit can be reached
  4. blivet/libblockdev reaches its five second timeout
?

I didn't notice it takes 4 seconds to start the lvmdbusd service (and we have a different bug for Fedora and it takes 8 seconds there). So this is definitely a different issue and we can close this one. I'll create a separate issue with this for libblockdev.

I was going to write the same. Check the load/free memory on the test system.

I checked the code (not that I fully understand all the magic), and this really should not happen, but!

Call, once in lvmdbusd, should really return result or job in 1 second, but! There is no guarantee the message will be delivered immediately, especially when either system or D-Bus is under high load.

Is not the system somewhat unstable or overloaded? (swapping?) It takes over 3 seconds to start lvmdbusd, so it may be possible the lvmdbusd just does not get enough time to process anything.