Bug 1780663

Summary: displaying volumes during deactivation/activation loops can lead to all kinds of "invalid" and "failed" stat and device messages
Product: Red Hat Enterprise Linux 8 Reporter: Corey Marthaler <cmarthal>
Component: lvm2Assignee: David Teigland <teigland>
lvm2 sub component: Activating existing Logical Volumes QA Contact: cluster-qe <cluster-qe>
Status: CLOSED ERRATA Docs Contact:
Severity: medium    
Priority: high CC: agk, heinzm, jbrassow, mcsontos, msnitzer, pasik, prajnoha, rhandlin, zkabelac
Version: 8.2   
Target Milestone: rc   
Target Release: 8.0   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: lvm2-2.03.09-2.el8 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2020-11-04 02:00:20 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:

Description Corey Marthaler 2019-12-06 15:27:07 UTC
Description of problem:
We have a test that creates a bunch of all the different lvm volume types and then deactivates and reactivates them over and over to stress the activation process. 

During this, if you also run display commands, you could potentially see a variety of "failure" and "invalid" messages which could be quite concerning to the user thinking devices are flakey or failing.


[root@hayes-02 ~]# lvs -a -o +devices | more
  /sys/dev/block/253:53/dm/uuid: fopen failed: No such file or directory
  /dev/mapper/activator1-pool1-tpool: open failed: No such device or address
  /dev/activator1/virt1: stat failed: No such file or directory
  Path /dev/activator1/virt1 no longer valid for device(253,53)
  /dev/dm-53: stat failed: No such file or directory
  Path /dev/dm-53 no longer valid for device(253,53)
  /dev/disk/by-id/dm-name-activator1-virt1: stat failed: No such file or directory
  Path /dev/disk/by-id/dm-name-activator1-virt1 no longer valid for device(253,53)
  /dev/disk/by-id/dm-uuid-LVM-CPdR2BPoYUqXBqjD10TlL3diypV8zcB5lb4mLw9JTklrSQFgHVvwISBplSovnuZS: stat failed: No such file or directory
  Path /dev/disk/by-id/dm-uuid-LVM-CPdR2BPoYUqXBqjD10TlL3diypV8zcB5lb4mLw9JTklrSQFgHVvwISBplSovnuZS no longer valid for device(253,53)
  /dev/mapper/activator1-virt1: stat failed: No such file or directory
  Path /dev/mapper/activator1-virt1 no longer valid for device(253,53)
  LV                        VG         Attr       LSize    Pool                Origin           Data%  Meta%  Move Log            Cpy%Sync Convert Devices                                                                                       
  cache1                    activator1 Cwi---C---  100.00m [cache1_fast_cpool] [cache1_corig]                                                      cache1_corig(0)                                                                               
  [cache1_corig]            activator1 owi---C---  100.00m                                                                                         /dev/sdp1(0)                                                                                  
  [cache1_fast_cpool]       activator1 Cwi---C---   52.00m                                                                                         cache1_fast_cpool_cdata(0)                                                                    
  [cache1_fast_cpool_cdata] activator1 Cwi-------   52.00m                                                                                         /dev/sdn2(1242)                                                                               
  [cache1_fast_cpool_cmeta] activator1 ewi-------    8.00m                                                                                         /dev/sdn2(1255)                                                                               
  linear1                   activator1 -wi-------  100.00m                                                                                         /dev/sdn2(143)                                                                                
  [lvol0_pmspare]           activator1 ewi-------    8.00m                                                                                         /dev/sdn2(117)                                                                                
  [lvol0_pmspare]           activator1 ewi-------    8.00m                                                                                         /dev/sdn2(1257)                                                                               
  mirror1                   activator1 mwi---m---  100.00m                                                         [mirror1_mlog]                  mirror1_mimage_0(0),mirror1_mimage_1(0),mirror1_mimage_2(0)                                   
  [mirror1_mimage_0]        activator1 Iwi---m---  100.00m                                                                                         /dev/sdn2(1217)                                                                               
  [mirror1_mimage_1]        activator1 Iwi---m---  100.00m                                                                                         /dev/sdn1(117)                                                                                
  [mirror1_mimage_2]        activator1 Iwi---m---  100.00m                                                                                         /dev/sdm2(78)                                                                                 
  [mirror1_mlog]            activator1 lwi---m---    4.00m                                                                                         /dev/sdo2(1)                                                                                  
  pool1                     activator1 twi---t---  100.00m                                                                                         pool1_tdata(0)                                                                                
  [pool1_tdata]             activator1 Twi-------  100.00m                                                                                         /dev/sdn2(118)                                                                                
  [pool1_tmeta]             activator1 ewi-------    4.00m                                                                                         /dev/sdo2(0)                                                                                  
  raid01                    activator1 rwi---r---  104.00m                                                                                         raid01_rimage_0(0),raid01_rimage_1(0)                                                         
  [raid01_rimage_0]         activator1 Iwi---r---   52.00m                                                                                         /dev/sdn2(0)                                                                                  
  [raid01_rimage_1]         activator1 Iwi---r---   52.00m                                                                                         /dev/sdn1(0)                                                                                  
  raid101                   activator1 rwi---r---  104.00m                                                                                         raid101_rimage_0(0),raid101_rimage_1(0),raid101_rimage_2(0),raid101_rimage_3(0)               
  [raid101_rimage_0]        activator1 Iwi---r---   52.00m                                                                                         /dev/sdn2(104)                                                                                
  [raid101_rimage_1]        activator1 Iwi---r---   52.00m                                                                                         /dev/sdn1(104)                                                                                
  [raid101_rimage_2]        activator1 Iwi---r---   52.00m                                                                                         /dev/sdm2(65)                                                                                 
  [raid101_rimage_3]        activator1 Iwi---r---   52.00m                                                                                         /dev/sdm1(11)                                                                                 
[...]


[root@hayes-02 ~]# lvs -a -o +devices | more
  /dev/mapper/activator1-upconvert1_rmeta_0: stat failed: No such file or directory
  Path /dev/mapper/activator1-upconvert1_rmeta_0 no longer valid for device(253,3)
  /dev/dm-3: stat failed: No such file or directory
  Path /dev/dm-3 no longer valid for device(253,3)
  Failed to read /sys/dev/block/253:14/dm/uuid.
  /dev/activator1/raid11: open failed: No such device or address
  LV                        VG         Attr       LSize    Pool                Origin           Data%  Meta%  Move Log            Cpy%Sync Convert Devices                                                                                       
  cache1                    activator1 Cwi---C---  100.00m [cache1_fast_cpool] [cache1_corig]                                                      cache1_corig(0)                                                                               
  [cache1_corig]            activator1 owi---C---  100.00m                                                                                         /dev/sdp1(0)                                                                                  
  [cache1_fast_cpool]       activator1 Cwi---C---   52.00m                                                                                         cache1_fast_cpool_cdata(0)                                                                    
  [cache1_fast_cpool_cdata] activator1 Cwi-------   52.00m                                                                                         /dev/sdn2(1242)                                                                               
  [cache1_fast_cpool_cmeta] activator1 ewi-------    8.00m                                                                                         /dev/sdn2(1255)                                                                               
  linear1                   activator1 -wi-------  100.00m                                                                                         /dev/sdn2(143)                                                                                
  [lvol0_pmspare]           activator1 ewi-------    8.00m                                                                                         /dev/sdn2(117)                                                                                
[...]


Version-Release number of selected component (if applicable):
kernel-4.18.0-151.el8    BUILT: Fri Nov 15 13:14:53 CST 2019
lvm2-2.03.07-1.el8    BUILT: Mon Dec  2 00:09:32 CST 2019
lvm2-libs-2.03.07-1.el8    BUILT: Mon Dec  2 00:09:32 CST 2019
lvm2-dbusd-2.03.07-1.el8    BUILT: Mon Dec  2 00:12:23 CST 2019
lvm2-lockd-2.03.07-1.el8    BUILT: Mon Dec  2 00:09:32 CST 2019
device-mapper-1.02.167-1.el8    BUILT: Mon Dec  2 00:09:32 CST 2019
device-mapper-libs-1.02.167-1.el8    BUILT: Mon Dec  2 00:09:32 CST 2019
device-mapper-event-1.02.167-1.el8    BUILT: Mon Dec  2 00:09:32 CST 2019
device-mapper-event-libs-1.02.167-1.el8    BUILT: Mon Dec  2 00:09:32 CST 2019
device-mapper-persistent-data-0.8.5-2.el8    BUILT: Wed Jun  5 10:28:04 CDT 2019



How reproducible:
Often

Comment 1 David Teigland 2020-03-11 19:20:36 UTC
The messages are a natural and harmless result of running commands concurrently, and the log levels should be changed so they don't appear.  This is not a new issue in general, it also appears in RHEL7 with or without lvmetad.

It is a result of lvm creating a list of /dev entries (directly or from udev) at the start of a command, and then collecting more info about those devs (like its uuid or size), but in the meantime the dev has changed or gone away due to another lvm command, causing the messages.  lvm does not use locking to "freeze" /dev while running because the entries are not really important.  LVM will open /dev nodes that are important and that it's going to read or write.  In those cases error messages are appropriate, so changing logging levels needs to be aware of that.

Comment 3 David Teigland 2020-03-12 15:27:27 UTC
Mainly two cases needed changing: not using the existing error_if_no_value to suppress noise in _get_sysfs_value, and dev_get_size not using the existing quiet option for dev_open to suppress noise in dev_name_confirmed().

fix in master
https://sourceware.org/git/?p=lvm2.git;a=commit;h=957904933b2b0f94eddc6204ca2fa61e2df741a0

Comment 7 Corey Marthaler 2020-06-18 18:37:24 UTC
Fix verified in the latest rpms. We're no longer seeing this issue during long run activation/deactivation testing.

kernel-4.18.0-211.el8    BUILT: Thu Jun  4 03:33:39 CDT 2020
lvm2-2.03.09-2.el8    BUILT: Fri May 29 11:29:58 CDT 2020
lvm2-libs-2.03.09-2.el8    BUILT: Fri May 29 11:29:58 CDT 2020
lvm2-dbusd-2.03.09-2.el8    BUILT: Fri May 29 11:32:49 CDT 2020
lvm2-lockd-2.03.09-2.el8    BUILT: Fri May 29 11:29:58 CDT 2020
boom-boot-1.2-1.el8    BUILT: Sun Jun  7 07:20:03 CDT 2020
device-mapper-1.02.171-2.el8    BUILT: Fri May 29 11:29:58 CDT 2020
device-mapper-libs-1.02.171-2.el8    BUILT: Fri May 29 11:29:58 CDT 2020
device-mapper-event-1.02.171-2.el8    BUILT: Fri May 29 11:29:58 CDT 2020
device-mapper-event-libs-1.02.171-2.el8    BUILT: Fri May 29 11:29:58 CDT 2020

Comment 10 errata-xmlrpc 2020-11-04 02:00:20 UTC
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 (lvm2 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-2020:4546