All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH] test: lvmetad_dump always timed out when using nc
@ 2017-12-13 11:13 Eric Ren
  2017-12-14 10:27 ` Eric Ren
  0 siblings, 1 reply; 6+ messages in thread
From: Eric Ren @ 2017-12-13 11:13 UTC (permalink / raw)
  To: lvm-devel

lvmetad_dump uses either "socat" or "nc" to communicate
with lvmetad. But when using "nc" if "socat" is not
available, nc will listen forever by default, causing the
testcase timed out.

Signed-off-by: Eric Ren <zren@suse.com>
---
 test/lib/aux.sh | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/test/lib/aux.sh b/test/lib/aux.sh
index 6bc7bd47e..4603c1504 100644
--- a/test/lib/aux.sh
+++ b/test/lib/aux.sh
@@ -243,14 +243,14 @@ lvmetad_talk() {
 	local use=nc
 	if type -p socat >& /dev/null; then
 		use=socat
-	elif echo | not nc -U "$TESTDIR/lvmetad.socket" ; then
+	elif echo | not nc -w 1 -U "$TESTDIR/lvmetad.socket" ; then
 		echo "WARNING: Neither socat nor nc -U seems to be available." 1>&2
 		echo "## failed to contact lvmetad."
 		return 1
 	fi
 
 	if test "$use" = nc ; then
-		nc -U "$TESTDIR/lvmetad.socket"
+		nc -w 1 -U "$TESTDIR/lvmetad.socket"
 	else
 		socat "unix-connect:$TESTDIR/lvmetad.socket" -
 	fi | tee -a lvmetad-talk.txt
-- 
2.13.6



^ permalink raw reply related	[flat|nested] 6+ messages in thread

* [PATCH] test: lvmetad_dump always timed out when using nc
  2017-12-13 11:13 [PATCH] test: lvmetad_dump always timed out when using nc Eric Ren
@ 2017-12-14 10:27 ` Eric Ren
  2017-12-14 10:39   ` Zdenek Kabelac
  0 siblings, 1 reply; 6+ messages in thread
From: Eric Ren @ 2017-12-14 10:27 UTC (permalink / raw)
  To: lvm-devel

Hi zkabelac,

Hmm strange, tested on fedora, it has not this issue.

```

[root at localhost test]# which oscat
/usr/bin/which: no oscat in 
(/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/root/bin)

[root at localhost test]# lib/runner --flavours udev-lvmetad --only 
lvmetad-dump.sh
running 1 tests
###?????? passed: [udev-lvmetad] shell/lvmetad-dump.sh 3
### 1 tests: 1 passed, 0 skipped, 0 timed out, 0 warned, 0 failed

```

I guess it may be because openSUSE and fedora use different "nc" tool:

```

openSUSE:

# rpm -qf /usr/bin/nc
netcat-openbsd-1.178-1.2.x86_64

fedora:
# rpm -qf /usr/bin/nc
nmap-ncat-7.50-3.fc27.x86_64

```

Thanks,
Eric


On 12/13/2017 07:13 PM, Eric Ren wrote:
> lvmetad_dump uses either "socat" or "nc" to communicate
> with lvmetad. But when using "nc" if "socat" is not
> available, nc will listen forever by default, causing the
> testcase timed out.
>
> Signed-off-by: Eric Ren <zren@suse.com>
> ---
>   test/lib/aux.sh | 4 ++--
>   1 file changed, 2 insertions(+), 2 deletions(-)
>
> diff --git a/test/lib/aux.sh b/test/lib/aux.sh
> index 6bc7bd47e..4603c1504 100644
> --- a/test/lib/aux.sh
> +++ b/test/lib/aux.sh
> @@ -243,14 +243,14 @@ lvmetad_talk() {
>   	local use=nc
>   	if type -p socat >& /dev/null; then
>   		use=socat
> -	elif echo | not nc -U "$TESTDIR/lvmetad.socket" ; then
> +	elif echo | not nc -w 1 -U "$TESTDIR/lvmetad.socket" ; then
>   		echo "WARNING: Neither socat nor nc -U seems to be available." 1>&2
>   		echo "## failed to contact lvmetad."
>   		return 1
>   	fi
>   
>   	if test "$use" = nc ; then
> -		nc -U "$TESTDIR/lvmetad.socket"
> +		nc -w 1 -U "$TESTDIR/lvmetad.socket"
>   	else
>   		socat "unix-connect:$TESTDIR/lvmetad.socket" -
>   	fi | tee -a lvmetad-talk.txt



^ permalink raw reply	[flat|nested] 6+ messages in thread

* [PATCH] test: lvmetad_dump always timed out when using nc
  2017-12-14 10:27 ` Eric Ren
@ 2017-12-14 10:39   ` Zdenek Kabelac
  2017-12-14 13:28     ` Eric Ren
  0 siblings, 1 reply; 6+ messages in thread
From: Zdenek Kabelac @ 2017-12-14 10:39 UTC (permalink / raw)
  To: lvm-devel

Dne 14.12.2017 v 11:27 Eric Ren napsal(a):
> Hi zkabelac,
> 
> Hmm strange, tested on fedora, it has not this issue.
> 
> ```
> 

Hi

Yep - in fact I've  been a bit puzzled by your patch since I could not think 
why that should be needed.

We will possibly need to put OpenSuse as a test machine  somewhere.


Can you provide full test trace where you get lock ?


'make check_local T=selectsometest  VERBOSE=1 LVM_TEST_AUX_TRACE=1  &>/tmp/log'


Regads

Zdenek



^ permalink raw reply	[flat|nested] 6+ messages in thread

* [PATCH] test: lvmetad_dump always timed out when using nc
  2017-12-14 10:39   ` Zdenek Kabelac
@ 2017-12-14 13:28     ` Eric Ren
  2017-12-14 14:07       ` Zdenek Kabelac
  0 siblings, 1 reply; 6+ messages in thread
From: Eric Ren @ 2017-12-14 13:28 UTC (permalink / raw)
  To: lvm-devel

Hi,

On 12/14/2017 06:39 PM, Zdenek Kabelac wrote:
> Dne 14.12.2017 v 11:27 Eric Ren napsal(a):
>> Hi zkabelac,
>>
>> Hmm strange, tested on fedora, it has not this issue.
>>
>> ```
>>
>
> Hi
>
> Yep - in fact I've? been a bit puzzled by your patch since I could not 
> think why that should be needed.

Hah sorry, I will always verify the issue on fedora first when I report 
problem in upstream :)

>
> We will possibly need to put OpenSuse as a test machine somewhere.

Thanks, but it's not a very trivial task. openSUSE tumbleweed is a 
rolling release, which
is usually used for developing purpose, but it's not that easy to 
maintain (upgrade). Besides,
some raid testcases in upstream code can pass on fedora, but fail on 
openSUSE, which seems
caused by some raid kernel patches (not yet inspect carefully on those 
failures).

It's already very cool to have such kind upstream, appreciate!

>
>
> Can you provide full test trace where you get lock ?
>
>
> 'make check_local T=selectsometest? VERBOSE=1 LVM_TEST_AUX_TRACE=1? 
> &>/tmp/log'

'make check_local' is skipped:
```
tw1:~/lvm2/test # make check_local T=lvmetad-dump? VERBOSE=1 
LVM_TEST_AUX_TRACE=1? &>/tmp/log1.txt
```

'make check'? hangs up forever until CTR+c:
```
tw1:~/lvm2/test # make check T=lvmetad-dump? VERBOSE=1 
LVM_TEST_AUX_TRACE=1? &>/tmp/log2.txt
^C
```

The logs are attached.

Thanks,
Eric
-------------- next part --------------
make -C api device-mapper
make[1]: Entering directory '/root/lvm2/test/api'
make[1]: Nothing to be done for 'device-mapper'.
make[1]: Leaving directory '/root/lvm2/test/api'
make -C unit device-mapper
make[1]: Entering directory '/root/lvm2/test/unit'
make[1]: Nothing to be done for 'device-mapper'.
make[1]: Leaving directory '/root/lvm2/test/unit'
make -C api
make[1]: Entering directory '/root/lvm2/test/api'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory '/root/lvm2/test/api'
make -C unit
make[1]: Entering directory '/root/lvm2/test/unit'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory '/root/lvm2/test/unit'
touch .tests-stamp
VERBOSE=1 ./lib/runner \
	--testdir . --outdir results \
	--flavours ndev-vanilla --only lvmetad-dump --skip @ 
running 1 tests

###      skipped: [ndev-vanilla] shell/lvmetad-dump.sh

### 1 tests: 0 passed, 1 skipped, 0 timed out, 0 warned, 0 failed
-------------- next part --------------
make -C api device-mapper
make[1]: Entering directory '/root/lvm2/test/api'
make[1]: Nothing to be done for 'device-mapper'.
make[1]: Leaving directory '/root/lvm2/test/api'
make -C unit device-mapper
make[1]: Entering directory '/root/lvm2/test/unit'
make[1]: Nothing to be done for 'device-mapper'.
make[1]: Leaving directory '/root/lvm2/test/unit'
make -C api
make[1]: Entering directory '/root/lvm2/test/api'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory '/root/lvm2/test/api'
make -C unit
make[1]: Entering directory '/root/lvm2/test/unit'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory '/root/lvm2/test/unit'
touch .tests-stamp
VERBOSE=1 ./lib/runner \
	--testdir . --outdir results \
	--flavours ndev-vanilla,ndev-cluster,ndev-lvmetad,ndev-lvmpolld,ndev-cluster-lvmpolld,ndev-lvmetad-lvmpolld --only lvmetad-dump --skip @ 
running 6 tests

###      skipped: [ndev-vanilla] shell/lvmetad-dump.sh

###      skipped: [ndev-cluster] shell/lvmetad-dump.sh

[ 0:00] Library version:   1.02.146-git (2017-11-03)
[ 0:00] Driver version:    4.36.0
[ 0:00] Kernel is Linux tw1 4.13.5-1-default #1 SMP PREEMPT Thu Oct 5 18:28:26 UTC 2017 (3fd9659) x86_64 x86_64 x86_64 GNU/Linux
[ 0:00] Selinux mode is not installed.
[ 0:00]               total        used        free      shared  buff/cache   available
[ 0:00] Mem:            974         203          82           0         688         616
[ 0:00] Swap:          2053          90        1963
[ 0:00] Filesystem      Size  Used Avail Use% Mounted on
[ 0:00] devtmpfs        993M  8.0K  993M   1% /dev
[ 0:00] tmpfs          1000M     0 1000M   0% /dev/shm
[ 0:00] tmpfs          1000M  1.3M  998M   1% /run
[ 0:00] tmpfs          1000M     0 1000M   0% /sys/fs/cgroup
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /usr/local
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /.snapshots
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /boot/grub2/x86_64-efi
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /var/crash
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /var/cache
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /var/opt
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /opt
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /var/lib/named
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /var/log
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /var/lib/pgsql
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /var/lib/mariadb
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /tmp
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /var/lib/mysql
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /var/spool
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /srv
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /boot/grub2/i386-pc
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /var/tmp
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /var/lib/libvirt/images
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /var/lib/machines
[ 0:00] /dev/vda2        40G   34G  6.0G  85% /var/lib/mailman
[ 0:00] /dev/vda3        59G  108M   59G   1% /home
[ 0:00] tmpfs            98M   16K   98M   1% /run/user/478
[ 0:00] tmpfs            98M     0   98M   0% /run/user/0
[ 0:00] @TESTDIR=/tmp/LVMTEST10053.1NwSxCR8mc
[ 0:00] @PREFIX=LVMTEST10053
[ 0:00] + test -f DEVICES
[ 0:00] + test prepare_lvmetad = dmsetup
[ 0:00] + prepare_lvmetad
[ 0:00] + check_daemon_in_builddir lvmetad
[ 0:00] + test -z ''
[ 0:00] + which lvmetad
[ 0:00] + grep -q /root/lvm2/test
[ 0:00] + rm -f debug.log strace.log
[ 0:00] + local run_valgrind=
[ 0:00] + test 0 -eq 0
[ 0:00] + kill_sleep_kill_ LOCAL_LVMETAD 0
[ 0:00] + local pidfile=LOCAL_LVMETAD
[ 0:00] + local slow=0
[ 0:00] + test -s LOCAL_LVMETAD
[ 0:00] + lvmconf 'global/use_lvmetad = 1' 'devices/md_component_detection = 0'
[ 0:00] + local profile_name=
[ 0:00] + test 2 -eq 0
[ 0:00] + local needed=0
[ 0:00] + for i in "$@"
[ 0:00] ++ grep global/use_lvmetad CONFIG_VALUES
[ 0:00] ++ tail -1
[ 0:00] + val=
[ 0:00] + needed=1
[ 0:00] + break
[ 0:00] + test 1 -eq 0
[ 0:00] + generate_config 'global/use_lvmetad = 1' 'devices/md_component_detection = 0'
[ 0:00] + test -n ''
[ 0:00] + config_values=CONFIG_VALUES
[ 0:00] + config=CONFIG
[ 0:00] + LVM_TEST_LOCKING=1
[ 0:00] + LVM_TEST_LVMETAD=1
[ 0:00] + LVM_TEST_LVMPOLLD=0
[ 0:00] + LVM_TEST_LVMLOCKD=0
[ 0:00] + test @TESTDIR@/dev = /dev
[ 0:00] + LVM_VERIFY_UDEV=1
[ 0:00] + test -f CONFIG_VALUES
[ 0:00] + cat
[ 0:00] + test -z varset
[ 0:00] + cat
[ 0:00] + local v
[ 0:00] + test 2 -gt 0
[ 0:00] + printf '%s\n' 'global/use_lvmetad = 1' 'devices/md_component_detection = 0'
[ 0:00] + declare -A CONF
[ 0:00] + local sec
[ 0:00] + local last_sec=
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='checks = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='monitoring = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='polling_interval = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='retry_deactivation = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='snapshot_autoextend_percent = 50'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='snapshot_autoextend_threshold = 50'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='udev_rules = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='udev_sync = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='verify_udev_operations = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='raid_region_size = 512'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='wipe_signatures_when_zeroing_new_lvs = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='archive = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='backup = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='cache_dir = "@TESTDIR@/etc"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='default_data_alignment = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='dir = "@TESTDIR@/dev"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='filter = "a|.*|"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='global_filter = [ "a|@TESTDIR@/dev/mapper/@PREFIX at .*pv[0-9_]*$|", "r|.*|" ]'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='md_component_detection  = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='scan = "@TESTDIR@/dev"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='sysfs_scan = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='write_cache_state = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='abort_on_internal_errors = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='cache_check_executable = "/usr/sbin/cache_check"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='cache_dump_executable = "/usr/sbin/cache_dump"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='cache_repair_executable = "/usr/sbin/cache_repair"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='detect_internal_vg_cache_corruption = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='fallback_to_local_locking = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='library_dir = "@TESTDIR@/lib"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='locking_dir = "@TESTDIR@/var/lock/lvm"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]=locking_type=1
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='notify_dbus = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='si_unit_consistency = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='thin_check_executable = "/usr/sbin/thin_check"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='thin_dump_executable = "/usr/sbin/thin_dump"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='thin_repair_executable = "/usr/sbin/thin_repair"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='use_lvmetad = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='use_lvmpolld = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='use_lvmlockd = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='activation = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='file = "@TESTDIR@/debug.log"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='indent = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='level = 9'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='overwrite = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='syslog = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='verbose = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='executable = "/root/lvm2/test/lib/dmeventd"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='fsadm_executable = "/root/lvm2/test/lib/fsadm"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='use_lvmetad = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='md_component_detection = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + sort
[ 0:00] + printf '%s\n' global/abort_on_internal_errors global/cache_repair_executable global/detect_internal_vg_cache_corruption devices/filter devices/sysfs_scan log/indent log/file global/use_lvmpolld activation/raid_region_size activation/polling_interval log/verbose global/locking_type global/si_unit_consistency global/notify_dbus dmeventd/executable devices/default_data_alignment global/use_lvmetad log/level log/activation devices/global_filter devices/write_cache_state activation/snapshot_autoextend_percent backup/archive log/overwrite devices/cache_dir global/locking_dir allocation/wipe_signatures_when_zeroing_new_lvs activation/monitoring global/fsadm_executable global/cache_check_executable activation/verify_udev_operations global/library_dir devices/md_component_detection activation/snapshot_autoextend_threshold activation/checks activation/udev_rules devices/dir log/syslog global/thin_check_executable global/thin_dump_executable global/thin_repair_executable activation/udev_sync devices/scan activation/retry_deactivation global/fallback_to_local_locking backup/backup global/use_lvmlockd global/cache_dump_executable
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = ''
[ 0:00] + test -z ''
[ 0:00] + echo 'activation {'
[ 0:00] + last_sec=activation
[ 0:00] + echo '    checks = 1'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    monitoring = 0'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    polling_interval = 1'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    raid_region_size = 512'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    retry_deactivation = 1'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    snapshot_autoextend_percent = 50'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    snapshot_autoextend_threshold = 50'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    udev_rules = 1'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    udev_sync = 1'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    verify_udev_operations = 1'
[ 0:00] + read -r v
[ 0:00] + sec=allocation
[ 0:00] + test allocation = activation
[ 0:00] + test -z activation
[ 0:00] + echo '}'
[ 0:00] + echo 'allocation {'
[ 0:00] + last_sec=allocation
[ 0:00] + echo '    wipe_signatures_when_zeroing_new_lvs = 0'
[ 0:00] + read -r v
[ 0:00] + sec=backup
[ 0:00] + test backup = allocation
[ 0:00] + test -z allocation
[ 0:00] + echo '}'
[ 0:00] + echo 'backup {'
[ 0:00] + last_sec=backup
[ 0:00] + echo '    archive = 0'
[ 0:00] + read -r v
[ 0:00] + sec=backup
[ 0:00] + test backup = backup
[ 0:00] + echo '    backup = 0'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = backup
[ 0:00] + test -z backup
[ 0:00] + echo '}'
[ 0:00] + echo 'devices {'
[ 0:00] + last_sec=devices
[ 0:00] + echo '    cache_dir = "@TESTDIR@/etc"'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = devices
[ 0:00] + echo '    default_data_alignment = 1'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = devices
[ 0:00] + echo '    dir = "@TESTDIR@/dev"'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = devices
[ 0:00] + echo '    filter = "a|.*|"'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = devices
[ 0:00] + echo '    global_filter = [ "a|@TESTDIR@/dev/mapper/@PREFIX at .*pv[0-9_]*$|", "r|.*|" ]'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = devices
[ 0:00] + echo '    md_component_detection = 0'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = devices
[ 0:00] + echo '    scan = "@TESTDIR@/dev"'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = devices
[ 0:00] + echo '    sysfs_scan = 1'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = devices
[ 0:00] + echo '    write_cache_state = 0'
[ 0:00] + read -r v
[ 0:00] + sec=dmeventd
[ 0:00] + test dmeventd = devices
[ 0:00] + test -z devices
[ 0:00] + echo '}'
[ 0:00] + echo 'dmeventd {'
[ 0:00] + last_sec=dmeventd
[ 0:00] + echo '    executable = "/root/lvm2/test/lib/dmeventd"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = dmeventd
[ 0:00] + test -z dmeventd
[ 0:00] + echo '}'
[ 0:00] + echo 'global {'
[ 0:00] + last_sec=global
[ 0:00] + echo '    abort_on_internal_errors = 1'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    cache_check_executable = "/usr/sbin/cache_check"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    cache_dump_executable = "/usr/sbin/cache_dump"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    cache_repair_executable = "/usr/sbin/cache_repair"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    detect_internal_vg_cache_corruption = 1'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    fallback_to_local_locking = 0'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    fsadm_executable = "/root/lvm2/test/lib/fsadm"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    library_dir = "@TESTDIR@/lib"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    locking_dir = "@TESTDIR@/var/lock/lvm"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    locking_type=1'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    notify_dbus = 0'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    si_unit_consistency = 1'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    thin_check_executable = "/usr/sbin/thin_check"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    thin_dump_executable = "/usr/sbin/thin_dump"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    thin_repair_executable = "/usr/sbin/thin_repair"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    use_lvmetad = 1'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    use_lvmlockd = 0'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    use_lvmpolld = 0'
[ 0:00] + read -r v
[ 0:00] + sec=log
[ 0:00] + test log = global
[ 0:00] + test -z global
[ 0:00] + echo '}'
[ 0:00] + echo 'log {'
[ 0:00] + last_sec=log
[ 0:00] + echo '    activation = 1'
[ 0:00] + read -r v
[ 0:00] + sec=log
[ 0:00] + test log = log
[ 0:00] + echo '    file = "@TESTDIR@/debug.log"'
[ 0:00] + read -r v
[ 0:00] + sec=log
[ 0:00] + test log = log
[ 0:00] + echo '    indent = 1'
[ 0:00] + read -r v
[ 0:00] + sec=log
[ 0:00] + test log = log
[ 0:00] + echo '    level = 9'
[ 0:00] + read -r v
[ 0:00] + sec=log
[ 0:00] + test log = log
[ 0:00] + echo '    overwrite = 1'
[ 0:00] + read -r v
[ 0:00] + sec=log
[ 0:00] + test log = log
[ 0:00] + echo '    syslog = 0'
[ 0:00] + read -r v
[ 0:00] + sec=log
[ 0:00] + test log = log
[ 0:00] + echo '    verbose = 0'
[ 0:00] + read -r v
[ 0:00] + echo '}'
[ 0:00] + sed -e 's,^,## LVMCONF: ,' CONFIG
[ 0:00] ## LVMCONF: activation {
[ 0:00] ## LVMCONF:     checks = 1
[ 0:00] ## LVMCONF:     monitoring = 0
[ 0:00] ## LVMCONF:     polling_interval = 1
[ 0:00] ## LVMCONF:     raid_region_size = 512
[ 0:00] ## LVMCONF:     retry_deactivation = 1
[ 0:00] ## LVMCONF:     snapshot_autoextend_percent = 50
[ 0:00] ## LVMCONF:     snapshot_autoextend_threshold = 50
[ 0:00] ## LVMCONF:     udev_rules = 1
[ 0:00] ## LVMCONF:     udev_sync = 1
[ 0:00] ## LVMCONF:     verify_udev_operations = 1
[ 0:00] ## LVMCONF: }
[ 0:00] ## LVMCONF: allocation {
[ 0:00] ## LVMCONF:     wipe_signatures_when_zeroing_new_lvs = 0
[ 0:00] ## LVMCONF: }
[ 0:00] ## LVMCONF: backup {
[ 0:00] ## LVMCONF:     archive = 0
[ 0:00] ## LVMCONF:     backup = 0
[ 0:00] ## LVMCONF: }
[ 0:00] ## LVMCONF: devices {
[ 0:00] ## LVMCONF:     cache_dir = "@TESTDIR@/etc"
[ 0:00] ## LVMCONF:     default_data_alignment = 1
[ 0:00] ## LVMCONF:     dir = "@TESTDIR@/dev"
[ 0:00] ## LVMCONF:     filter = "a|.*|"
[ 0:00] ## LVMCONF:     global_filter = [ "a|@TESTDIR@/dev/mapper/@PREFIX at .*pv[0-9_]*$|", "r|.*|" ]
[ 0:00] ## LVMCONF:     md_component_detection = 0
[ 0:00] ## LVMCONF:     scan = "@TESTDIR@/dev"
[ 0:00] ## LVMCONF:     sysfs_scan = 1
[ 0:00] ## LVMCONF:     write_cache_state = 0
[ 0:00] ## LVMCONF: }
[ 0:00] ## LVMCONF: dmeventd {
[ 0:00] ## LVMCONF:     executable = "/root/lvm2/test/lib/dmeventd"
[ 0:00] ## LVMCONF: }
[ 0:00] ## LVMCONF: global {
[ 0:00] ## LVMCONF:     abort_on_internal_errors = 1
[ 0:00] ## LVMCONF:     cache_check_executable = "/usr/sbin/cache_check"
[ 0:00] ## LVMCONF:     cache_dump_executable = "/usr/sbin/cache_dump"
[ 0:00] ## LVMCONF:     cache_repair_executable = "/usr/sbin/cache_repair"
[ 0:00] ## LVMCONF:     detect_internal_vg_cache_corruption = 1
[ 0:00] ## LVMCONF:     fallback_to_local_locking = 0
[ 0:00] ## LVMCONF:     fsadm_executable = "/root/lvm2/test/lib/fsadm"
[ 0:00] ## LVMCONF:     library_dir = "@TESTDIR@/lib"
[ 0:00] ## LVMCONF:     locking_dir = "@TESTDIR@/var/lock/lvm"
[ 0:00] ## LVMCONF:     locking_type=1
[ 0:00] ## LVMCONF:     notify_dbus = 0
[ 0:00] ## LVMCONF:     si_unit_consistency = 1
[ 0:00] ## LVMCONF:     thin_check_executable = "/usr/sbin/thin_check"
[ 0:00] ## LVMCONF:     thin_dump_executable = "/usr/sbin/thin_dump"
[ 0:00] ## LVMCONF:     thin_repair_executable = "/usr/sbin/thin_repair"
[ 0:00] ## LVMCONF:     use_lvmetad = 1
[ 0:00] ## LVMCONF:     use_lvmlockd = 0
[ 0:00] ## LVMCONF:     use_lvmpolld = 0
[ 0:00] ## LVMCONF: }
[ 0:00] ## LVMCONF: log {
[ 0:00] ## LVMCONF:     activation = 1
[ 0:00] ## LVMCONF:     file = "@TESTDIR@/debug.log"
[ 0:00] ## LVMCONF:     indent = 1
[ 0:00] ## LVMCONF:     level = 9
[ 0:00] ## LVMCONF:     overwrite = 1
[ 0:00] ## LVMCONF:     syslog = 0
[ 0:00] ## LVMCONF:     verbose = 0
[ 0:00] ## LVMCONF: }
[ 0:00] + mv -f CONFIG @TESTDIR@/etc/lvm.conf
[ 0:00] + echo -n '## preparing lvmetad...'
[ 0:00] ## preparing lvmetad...+ echo 10099
[ 0:00] + lvmetad -f -s @TESTDIR@/lvmetad.socket -l all
[ 0:00] + for i in {1..100}
[ 0:00] + test 1 -eq 100
[ 0:00] + test -e @TESTDIR@/lvmetad.socket
[ 0:00] + echo -n .
[ 0:00] .+ sleep .1
[ 0:00] [D] creating @TESTDIR@/lvmetad.socket
[ 0:00] initialised state: vgid_to_metadata = 0x559977076f80
[ 0:00] + for i in {1..100}
[ 0:00] + test 2 -eq 100
[ 0:00] + test -e @TESTDIR@/lvmetad.socket
[ 0:00] + break
[ 0:00] + echo ok
[ 0:00] ok
[ 0:00] <======== Processing test: "lvmetad-dump.sh" ========>
[ 0:00] 
[ 0:00] aux prepare_vg 2
[ 0:00] #lvmetad-dump.sh:19+ aux prepare_vg 2
[ 0:00] + test -f DEVICES
[ 0:00] + test prepare_vg = dmsetup
[ 0:00] + prepare_vg 2
[ 0:00] + teardown_devs
[ 0:00] + teardown_udev_cookies
[ 0:00] + test 1 = 1
[ 0:00] + dmsetup udevcomplete_all -y 10
[ 0:00] + grep -v '^0 '
[ 0:00] + true
[ 0:00] + test '!' -f MD_DEV
[ 0:00] + test '!' -f DEVICES
[ 0:00] + test -f SCSI_DEBUG_DEV
[ 0:00] + test '!' -f LOOP
[ 0:00] + test '!' -f LOOPFILE
[ 0:00] + not diff LOOP BACKING_DEV
[ 0:00] + rm -f DEVICES LOOP
[ 0:00] + test 0 -eq 1
[ 0:00] + test -z LVMTEST
[ 0:00] + stray_loops=($(losetup -a | grep "$COMMON_PREFIX" | cut -d: -f1))
[ 0:00] ++ losetup -a
[ 0:00] ++ grep LVMTEST
[ 0:00] ++ cut -d: -f1
[ 0:00] + local stray_loops
[ 0:00] + test 0 -eq 0
[ 0:00] + prepare_devs 2
[ 0:00] + local n=2
[ 0:00] + local devsize=34
[ 0:00] + local pvname=pv
[ 0:00] + local shift=0
[ 0:00] + test -n ''
[ 0:00] + touch DEVICES
[ 0:00] + prepare_backing_dev 68
[ 0:00] + test -f BACKING_DEV
[ 0:00] + test -b ''
[ 0:00] + prepare_loop 68
[ 0:00] + local size=68
[ 0:00] + shift
[ 0:00] + local i
[ 0:00] + local slash
[ 0:00] + test -f LOOP
[ 0:00] + echo -n '## preparing loop device...'
[ 0:00] ## preparing loop device...+ test -f SCSI_DEBUG_DEV -a -f LOOP
[ 0:00] + test '!' -e LOOP
[ 0:00] + test -n @TESTDIR@/dev
[ 0:00] + for i in 0 1 2 3 4 5 6 7
[ 0:00] + test -e @TESTDIR@/dev/loop0
[ 0:00] + mknod @TESTDIR@/dev/loop0 b 7 0
[ 0:00] + for i in 0 1 2 3 4 5 6 7
[ 0:00] + test -e @TESTDIR@/dev/loop1
[ 0:00] + mknod @TESTDIR@/dev/loop1 b 7 1
[ 0:00] + for i in 0 1 2 3 4 5 6 7
[ 0:01] + test -e @TESTDIR@/dev/loop2
[ 0:01] + mknod @TESTDIR@/dev/loop2 b 7 2
[ 0:01] + for i in 0 1 2 3 4 5 6 7
[ 0:01] + test -e @TESTDIR@/dev/loop3
[ 0:01] + mknod @TESTDIR@/dev/loop3 b 7 3
[ 0:01] + for i in 0 1 2 3 4 5 6 7
[ 0:01] + test -e @TESTDIR@/dev/loop4
[ 0:01] + mknod @TESTDIR@/dev/loop4 b 7 4
[ 0:01] + for i in 0 1 2 3 4 5 6 7
[ 0:01] + test -e @TESTDIR@/dev/loop5
[ 0:01] + mknod @TESTDIR@/dev/loop5 b 7 5
[ 0:01] + for i in 0 1 2 3 4 5 6 7
[ 0:01] + test -e @TESTDIR@/dev/loop6
[ 0:01] + mknod @TESTDIR@/dev/loop6 b 7 6
[ 0:01] + for i in 0 1 2 3 4 5 6 7
[ 0:01] + test -e @TESTDIR@/dev/loop7
[ 0:01] + mknod @TESTDIR@/dev/loop7 b 7 7
[ 0:01] + echo -n .
[ 0:01] .+ local LOOPFILE=@TESTDIR@/test.img
[ 0:01] + rm -f @TESTDIR@/test.img
[ 0:01] + dd if=/dev/zero of=@TESTDIR@/test.img bs=1048576 count=0 seek=69
[ 0:01] ++ losetup -s -f @TESTDIR@/test.img
[ 0:01] + LOOP=
[ 0:01] ++ losetup -f
[ 0:01] + LOOP=/dev/loop0
[ 0:01] + losetup /dev/loop0 @TESTDIR@/test.img
[ 0:01] + :
[ 0:01] + test -n /dev/loop0
[ 0:01] + BACKING_DEV=/dev/loop0
[ 0:01] + echo /dev/loop0
[ 0:01] + echo /dev/loop0
[ 0:01] + echo 'ok (/dev/loop0)'
[ 0:01] ok (/dev/loop0)
[ 0:01] + not diff LOOP BACKING_DEV
[ 0:01] + shift=2048
[ 0:01] + echo -n '## preparing 2 devices...'
[ 0:01] ## preparing 2 devices...+ local size=69632
[ 0:01] + local count=0
[ 0:01] + rm -f CREATE_FAILED
[ 0:01] + init_udev_transaction
[ 0:01] + test 1 = 1
[ 0:01] + local cookie
[ 0:01] ++ dmsetup udevcreatecookie
[ 0:01] + cookie=0x0D4D2C98
[ 0:01] + test -z 0x0D4D2C98
[ 0:01] + export DM_UDEV_COOKIE=0x0D4D2C98
[ 0:01] + DM_UDEV_COOKIE=0x0D4D2C98
[ 0:01] ++ seq 1 2
[ 0:01] + for i in $(seq 1 "$n")
[ 0:01] + local name=@PREFIX at pv1
[ 0:01] + local dev=@TESTDIR@/dev/mapper/@PREFIX at pv1
[ 0:01] + DEVICES[$count]=@TESTDIR@/dev/mapper/@PREFIX at pv1
[ 0:01] + count=1
[ 0:01] + echo 0 69632 linear /dev/loop0 2048
[ 0:01] + test -f CREATE_FAILED
[ 0:01] + for i in $(seq 1 "$n")
[ 0:01] + local name=@PREFIX at pv2
[ 0:01] + local dev=@TESTDIR@/dev/mapper/@PREFIX at pv2
[ 0:01] + DEVICES[$count]=@TESTDIR@/dev/mapper/@PREFIX at pv2
[ 0:01] + dmsetup create -u TEST- at PREFIX@pv1 @PREFIX at pv1 @PREFIX at pv1.table
[ 0:01] + count=2
[ 0:01] + echo 0 69632 linear /dev/loop0 71680
[ 0:01] + test -f CREATE_FAILED
[ 0:01] + wait
[ 0:01] + dmsetup create -u TEST- at PREFIX@pv2 @PREFIX at pv2 @PREFIX at pv2.table
[ 0:01] + finish_udev_transaction
[ 0:01] + test 1 = 1
[ 0:01] + test -n 0x0D4D2C98
[ 0:01] + dmsetup udevreleasecookie
[ 0:01] + unset DM_UDEV_COOKIE
[ 0:01] + test -f CREATE_FAILED -a -n ''
[ 0:01] + test -f LOOP
[ 0:01] + printf '%s\n' @TESTDIR@/dev/mapper/@PREFIX at pv1 @TESTDIR@/dev/mapper/@PREFIX at pv2
[ 0:01] + echo ok
[ 0:01] ok
[ 0:01] + test -e LOCAL_LVMETAD
[ 0:01] + for dev in "${DEVICES[@]}"
[ 0:01] + notify_lvmetad @TESTDIR@/dev/mapper/@PREFIX at pv1
[ 0:01] + test -e LOCAL_LVMETAD
[ 0:01] + LVM_LOG_FILE_EPOCH=
[ 0:01] + pvscan --cache @TESTDIR@/dev/mapper/@PREFIX at pv1
[ 0:01] <- request="hello"
[ 0:01] -> response = "OK"
[ 0:01] -> protocol = "lvmetad"
[ 0:01] -> version = 1
[ 0:01] -> 
[ 0:01] <- request="get_global_info"
[ 0:01] <- token="skip"
[ 0:01] <- pid=10151
[ 0:01] <- cmd="pvscan"
[ 0:01] 10151 global info flags none reason none token none update_pid 0
[ 0:01] -> response = "OK"
[ 0:01] -> global_invalid = 0
[ 0:01] -> global_disable = 0
[ 0:01] -> disable_reason = "none"
[ 0:01] -> daemon_pid = 10099
[ 0:01] -> token = "none"
[ 0:01] -> update_cmd = ""
[ 0:01] -> update_pid = 0
[ 0:01] -> update_begin = 0
[ 0:01] -> update_timeout = 0
[ 0:01] -> 
[ 0:01] <- request="token_update"
[ 0:01] <- token="update in progress"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10151
[ 0:01] <- cmd="pvscan"
[ 0:01] token_update begin 255555 timeout 10 pid 10151 cmd pvscan
[ 0:01] -> response = "OK"
[ 0:01] -> prev_token = ""
[ 0:01] -> update_pid = 10151
[ 0:01] -> 
[ 0:01] <- request="pv_clear_all"
[ 0:01] <- token="update in progress"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10151
[ 0:01] <- cmd="pvscan"
[ 0:01] pv_clear_all
[ 0:01] -> response = "OK"
[ 0:01] -> 
[ 0:01] <- request="pv_gone"
[ 0:01] <- device=65026
[ 0:01] <- token="update in progress"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10151
[ 0:01] <- cmd="pvscan"
[ 0:01] pv_gone device 65026 not found
[ 0:01] -> response = "unknown"
[ 0:01] -> reason = "device not in cache"
[ 0:01] -> 
[ 0:01] <- request="pv_gone"
[ 0:01] <- device=65027
[ 0:01] <- token="update in progress"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10151
[ 0:01] <- cmd="pvscan"
[ 0:01] pv_gone device 65027 not found
[ 0:01] -> response = "unknown"
[ 0:01] -> reason = "device not in cache"
[ 0:01] -> 
[ 0:01] <- request="token_update"
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10151
[ 0:01] <- cmd="pvscan"
[ 0:01] token_update end len 0 pid 10151 new token filter:4177279013
[ 0:01] -> response = "OK"
[ 0:01] -> prev_token = "update in progress"
[ 0:01] -> update_pid = 0
[ 0:01] -> 
[ 0:01] <- request="get_global_info"
[ 0:01] <- token="skip"
[ 0:01] <- pid=10151
[ 0:01] <- cmd="pvscan"
[ 0:01] 10151 global info flags none reason none token filter:4177279013 update_pid 0
[ 0:01] -> response = "OK"
[ 0:01] -> global_invalid = 0
[ 0:01] -> global_disable = 0
[ 0:01] -> disable_reason = "none"
[ 0:01] -> daemon_pid = 10099
[ 0:01] -> token = "filter:4177279013"
[ 0:01] -> update_cmd = ""
[ 0:01] -> update_pid = 0
[ 0:01] -> update_begin = 0
[ 0:01] -> update_timeout = 0
[ 0:01] -> 
[ 0:01] <- request="get_global_info"
[ 0:01] <- token="skip"
[ 0:01] <- pid=10151
[ 0:01] <- cmd="pvscan"
[ 0:01] 10151 global info flags none reason none token filter:4177279013 update_pid 0
[ 0:01] -> response = "OK"
[ 0:01] -> global_invalid = 0
[ 0:01] -> global_disable = 0
[ 0:01] -> disable_reason = "none"
[ 0:01] -> daemon_pid = 10099
[ 0:01] -> token = "filter:4177279013"
[ 0:01] -> update_cmd = ""
[ 0:01] -> update_pid = 0
[ 0:01] -> update_begin = 0
[ 0:01] -> update_timeout = 0
[ 0:01] -> 
[ 0:01] + rm -f debug.log
[ 0:01] + for dev in "${DEVICES[@]}"
[ 0:01] + notify_lvmetad @TESTDIR@/dev/mapper/@PREFIX at pv2
[ 0:01] + test -e LOCAL_LVMETAD
[ 0:01] + LVM_LOG_FILE_EPOCH=
[ 0:01] + pvscan --cache @TESTDIR@/dev/mapper/@PREFIX at pv2
[ 0:01] <- request="hello"
[ 0:01] -> response = "OK"
[ 0:01] -> protocol = "lvmetad"
[ 0:01] -> version = 1
[ 0:01] -> 
[ 0:01] <- request="get_global_info"
[ 0:01] <- token="skip"
[ 0:01] <- pid=10154
[ 0:01] <- cmd="pvscan"
[ 0:01] 10154 global info flags none reason none token filter:4177279013 update_pid 0
[ 0:01] -> response = "OK"
[ 0:01] -> global_invalid = 0
[ 0:01] -> global_disable = 0
[ 0:01] -> disable_reason = "none"
[ 0:01] -> daemon_pid = 10099
[ 0:01] -> token = "filter:4177279013"
[ 0:01] -> update_cmd = ""
[ 0:01] -> update_pid = 0
[ 0:01] -> update_begin = 0
[ 0:01] -> update_timeout = 0
[ 0:01] -> 
[ 0:01] <- request="get_global_info"
[ 0:01] <- token="skip"
[ 0:01] <- pid=10154
[ 0:01] <- cmd="pvscan"
[ 0:01] 10154 global info flags none reason none token filter:4177279013 update_pid 0
[ 0:01] -> response = "OK"
[ 0:01] -> global_invalid = 0
[ 0:01] -> global_disable = 0
[ 0:01] -> disable_reason = "none"
[ 0:01] -> daemon_pid = 10099
[ 0:01] -> token = "filter:4177279013"
[ 0:01] -> update_cmd = ""
[ 0:01] -> update_pid = 0
[ 0:01] -> update_begin = 0
[ 0:01] -> update_timeout = 0
[ 0:01] -> 
[ 0:01]   No PV label found on @TESTDIR@/dev/mapper/@PREFIX at pv2.
[ 0:01] <- request="pv_gone"
[ 0:01] <- device=65027
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10154
[ 0:01] <- cmd="pvscan"
[ 0:01] pv_gone device 65027 not found
[ 0:01] -> response = "unknown"
[ 0:01] -> reason = "device not in cache"
[ 0:01] -> 
[ 0:01] + rm -f debug.log
[ 0:01] + vgcreate -s 512K @PREFIX at vg @TESTDIR@/dev/mapper/@PREFIX at pv1 @TESTDIR@/dev/mapper/@PREFIX at pv2
[ 0:01] <- request="hello"
[ 0:01] -> response = "OK"
[ 0:01] -> protocol = "lvmetad"
[ 0:01] -> version = 1
[ 0:01] -> 
[ 0:01] <- request="get_global_info"
[ 0:01] <- token="skip"
[ 0:01] <- pid=10157
[ 0:01] <- cmd="vgcreate"
[ 0:01] 10157 global info flags none reason none token filter:4177279013 update_pid 0
[ 0:01] -> response = "OK"
[ 0:01] -> global_invalid = 0
[ 0:01] -> global_disable = 0
[ 0:01] -> disable_reason = "none"
[ 0:01] -> daemon_pid = 10099
[ 0:01] -> token = "filter:4177279013"
[ 0:01] -> update_cmd = ""
[ 0:01] -> update_pid = 0
[ 0:01] -> update_begin = 0
[ 0:01] -> update_timeout = 0
[ 0:01] -> 
[ 0:01] <- request="get_global_info"
[ 0:01] <- token="skip"
[ 0:01] <- pid=10157
[ 0:01] <- cmd="vgcreate"
[ 0:01] 10157 global info flags none reason none token filter:4177279013 update_pid 0
[ 0:01] -> response = "OK"
[ 0:01] -> global_invalid = 0
[ 0:01] -> global_disable = 0
[ 0:01] -> disable_reason = "none"
[ 0:01] -> daemon_pid = 10099
[ 0:01] -> token = "filter:4177279013"
[ 0:01] -> update_cmd = ""
[ 0:01] -> update_pid = 0
[ 0:01] -> update_begin = 0
[ 0:01] -> update_timeout = 0
[ 0:01] -> 
[ 0:01] <- request="pv_list"
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10157
[ 0:01] <- cmd="vgcreate"
[ 0:01] pv_list
[ 0:01] -> response="OK"
[ 0:01] -> physical_volumes {
[ 0:01] -> }
[ 0:01] -> 
[ 0:01] -> 
[ 0:01] -> 
[ 0:01] <- request="vg_lookup"
[ 0:01] <- name="@PREFIX at vg"
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10157
[ 0:01] <- cmd="vgcreate"
[ 0:01] vg_lookup vgid none name @PREFIX@vg needs lookup
[ 0:01] -> response = "unknown"
[ 0:01] -> reason = "VG not found"
[ 0:01] -> 
[ 0:01] <- request="vg_lookup"
[ 0:01] <- name="@PREFIX at vg"
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10157
[ 0:01] <- cmd="vgcreate"
[ 0:01] vg_lookup vgid none name @PREFIX@vg needs lookup
[ 0:01] -> response = "unknown"
[ 0:01] -> reason = "VG not found"
[ 0:01] -> 
[ 0:01] <- request="vg_lookup"
[ 0:01] <- name="@PREFIX at vg"
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10157
[ 0:01] <- cmd="vgcreate"
[ 0:01] vg_lookup vgid none name @PREFIX@vg needs lookup
[ 0:01] -> response = "unknown"
[ 0:01] -> reason = "VG not found"
[ 0:01] -> 
[ 0:01] <- request="vg_list"
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10157
[ 0:01] <- cmd="vgcreate"
[ 0:01] vg_list
[ 0:01] -> response="OK"
[ 0:01] -> volume_groups {
[ 0:01] -> }
[ 0:01] -> 
[ 0:01] -> 
[ 0:01] -> 
[ 0:01] <- request="pv_list"
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10157
[ 0:01] <- cmd="vgcreate"
[ 0:01] pv_list
[ 0:01] -> response="OK"
[ 0:01] -> physical_volumes {
[ 0:01] -> }
[ 0:01] -> 
[ 0:01] -> 
[ 0:01] -> 
[ 0:01] <- request="pv_found"
[ 0:01] <- pvmeta {
[ 0:01] <- 	device=65026
[ 0:01] <- 	dev_size=35651584
[ 0:01] <- 	format="lvm2"
[ 0:01] <- 	label_sector=1
[ 0:01] <- 	id="2SW9iQ-fVZh-4zkR-npWT-9DRQ-GHo9-ETrxlP"
[ 0:01] <- 	ext_version=2
[ 0:01] <- 	ext_flags=0
[ 0:01] <- 	mda0 {
[ 0:01] <- 		ignore=0
[ 0:01] <- 		start=4096
[ 0:01] <- 		size=1044480
[ 0:01] <- 		free_sectors=0
[ 0:01] <- 	}
[ 0:01] <- 	da0 {
[ 0:01] <- 		offset=1048576
[ 0:01] <- 		size=0
[ 0:01] <- 	}
[ 0:01] <- 	ba0 {
[ 0:01] <- 		offset=0
[ 0:01] <- 		size=0
[ 0:01] <- 	}
[ 0:01] <- }
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10157
[ 0:01] <- cmd="vgcreate"
[ 0:01] pv_found pvid 2SW9iQ-fVZh-4zkR-npWT-9DRQ-GHo9-ETrxlP on device 65026 is new
[ 0:01] pv_found new entry device_to_pvid 65026 to 2SW9iQ-fVZh-4zkR-npWT-9DRQ-GHo9-ETrxlP
[ 0:01] pv_found pvid 2SW9iQ-fVZh-4zkR-npWT-9DRQ-GHo9-ETrxlP on 65026 not in VG 
[ 0:01] -> response = "OK"
[ 0:01] -> status = "orphan"
[ 0:01] -> changed = 1
[ 0:01] -> vgid = "#orphan"
[ 0:01] -> vgname = "#orphan"
[ 0:01] -> seqno_before = -1
[ 0:01] -> seqno_after = -1
[ 0:01] -> 
[ 0:01]   Physical volume "@TESTDIR@/dev/mapper/@PREFIX at pv1" successfully created.
[ 0:01] <- request="pv_found"
[ 0:01] <- pvmeta {
[ 0:01] <- 	device=65027
[ 0:01] <- 	dev_size=35651584
[ 0:01] <- 	format="lvm2"
[ 0:01] <- 	label_sector=1
[ 0:01] <- 	id="RtrWis-I0kI-1gLf-zwwl-Yqsq-U1Yz-TIzSOa"
[ 0:01] <- 	ext_version=2
[ 0:01] <- 	ext_flags=0
[ 0:01] <- 	mda0 {
[ 0:01] <- 		ignore=0
[ 0:01] <- 		start=4096
[ 0:01] <- 		size=1044480
[ 0:01] <- 		free_sectors=0
[ 0:01] <- 	}
[ 0:01] <- 	da0 {
[ 0:01] <- 		offset=1048576
[ 0:01] <- 		size=0
[ 0:01] <- 	}
[ 0:01] <- 	ba0 {
[ 0:01] <- 		offset=0
[ 0:01] <- 		size=0
[ 0:01] <- 	}
[ 0:01] <- }
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10157
[ 0:01] <- cmd="vgcreate"
[ 0:01] pv_found pvid RtrWis-I0kI-1gLf-zwwl-Yqsq-U1Yz-TIzSOa on device 65027 is new
[ 0:01] pv_found new entry device_to_pvid 65027 to RtrWis-I0kI-1gLf-zwwl-Yqsq-U1Yz-TIzSOa
[ 0:01] pv_found pvid RtrWis-I0kI-1gLf-zwwl-Yqsq-U1Yz-TIzSOa on 65027 not in VG 
[ 0:01] -> response = "OK"
[ 0:01] -> status = "orphan"
[ 0:01] -> changed = 1
[ 0:01] -> vgid = "#orphan"
[ 0:01] -> vgname = "#orphan"
[ 0:01] -> seqno_before = -1
[ 0:01] -> seqno_after = -1
[ 0:01] -> 
[ 0:01]   Physical volume "@TESTDIR@/dev/mapper/@PREFIX at pv2" successfully created.
[ 0:01] <- request="pv_found"
[ 0:01] <- pvmeta {
[ 0:01] <- 	device=65026
[ 0:01] <- 	dev_size=35651584
[ 0:01] <- 	format="lvm2"
[ 0:01] <- 	label_sector=1
[ 0:01] <- 	id="2SW9iQ-fVZh-4zkR-npWT-9DRQ-GHo9-ETrxlP"
[ 0:01] <- 	ext_version=2
[ 0:01] <- 	ext_flags=1
[ 0:01] <- 	mda0 {
[ 0:01] <- 		ignore=0
[ 0:01] <- 		start=4096
[ 0:01] <- 		size=1044480
[ 0:01] <- 		free_sectors=0
[ 0:01] <- 	}
[ 0:01] <- 	da0 {
[ 0:01] <- 		offset=1048576
[ 0:01] <- 		size=0
[ 0:01] <- 	}
[ 0:01] <- 	ba0 {
[ 0:01] <- 		offset=0
[ 0:01] <- 		size=0
[ 0:01] <- 	}
[ 0:01] <- }
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10157
[ 0:01] <- cmd="vgcreate"
[ 0:01] pv_found pvid 2SW9iQ-fVZh-4zkR-npWT-9DRQ-GHo9-ETrxlP on device 65026 matches existing
[ 0:01] pv_found pvid 2SW9iQ-fVZh-4zkR-npWT-9DRQ-GHo9-ETrxlP on 65026 not in VG 
[ 0:01] -> response = "OK"
[ 0:01] -> status = "orphan"
[ 0:01] -> changed = 1
[ 0:01] -> vgid = "#orphan"
[ 0:01] -> vgname = "#orphan"
[ 0:01] -> seqno_before = -1
[ 0:01] -> seqno_after = -1
[ 0:01] -> 
[ 0:01] <- request="pv_found"
[ 0:01] <- pvmeta {
[ 0:01] <- 	device=65027
[ 0:01] <- 	dev_size=35651584
[ 0:01] <- 	format="lvm2"
[ 0:01] <- 	label_sector=1
[ 0:01] <- 	id="RtrWis-I0kI-1gLf-zwwl-Yqsq-U1Yz-TIzSOa"
[ 0:01] <- 	ext_version=2
[ 0:01] <- 	ext_flags=1
[ 0:01] <- 	mda0 {
[ 0:01] <- 		ignore=0
[ 0:01] <- 		start=4096
[ 0:01] <- 		size=1044480
[ 0:01] <- 		free_sectors=0
[ 0:01] <- 	}
[ 0:01] <- 	da0 {
[ 0:01] <- 		offset=1048576
[ 0:01] <- 		size=0
[ 0:01] <- 	}
[ 0:01] <- 	ba0 {
[ 0:01] <- 		offset=0
[ 0:01] <- 		size=0
[ 0:01] <- 	}
[ 0:01] <- }
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10157
[ 0:01] <- cmd="vgcreate"
[ 0:01] pv_found pvid RtrWis-I0kI-1gLf-zwwl-Yqsq-U1Yz-TIzSOa on device 65027 matches existing
[ 0:01] pv_found pvid RtrWis-I0kI-1gLf-zwwl-Yqsq-U1Yz-TIzSOa on 65027 not in VG 
[ 0:01] -> response = "OK"
[ 0:01] -> status = "orphan"
[ 0:01] -> changed = 1
[ 0:01] -> vgid = "#orphan"
[ 0:01] -> vgname = "#orphan"
[ 0:01] -> seqno_before = -1
[ 0:01] -> seqno_after = -1
[ 0:01] -> 
[ 0:01] <- request="set_vg_info"
[ 0:01] <- name="@PREFIX@vg"
[ 0:01] <- uuid="lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg"
[ 0:01] <- version=1
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10157
[ 0:01] <- cmd="vgcreate"
[ 0:01] -> response = "OK"
[ 0:01] -> 
[ 0:01] <- request="vg_update"
[ 0:01] <- vgname="@PREFIX at vg"
[ 0:01] <- metadata {
[ 0:01] <- 	id="lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg"
[ 0:01] <- 	seqno=1
[ 0:01] <- 	format="lvm2"
[ 0:01] <- 	status=["RESIZEABLE","READ","WRITE"]
[ 0:01] <- 	flags=[]
[ 0:01] <- 	extent_size=1024
[ 0:01] <- 	max_lv=0
[ 0:01] <- 	max_pv=0
[ 0:01] <- 	metadata_copies=0
[ 0:01] <- 	physical_volumes {
[ 0:01] <- 		pv0 {
[ 0:01] <- 			id="2SW9iQ-fVZh-4zkR-npWT-9DRQ-GHo9-ETrxlP"
[ 0:01] <- 			device="@TESTDIR@/dev/mapper/@PREFIX at pv1"
[ 0:01] <- 			status="ALLOCATABLE"
[ 0:01] <- 			flags=[]
[ 0:01] <- 			dev_size=69632
[ 0:01] <- 			pe_start=2048
[ 0:01] <- 			pe_count=66
[ 0:01] <- 		}
[ 0:01] <- 		pv1 {
[ 0:01] <- 			id="RtrWis-I0kI-1gLf-zwwl-Yqsq-U1Yz-TIzSOa"
[ 0:01] <- 			device="@TESTDIR@/dev/mapper/@PREFIX at pv2"
[ 0:01] <- 			status="ALLOCATABLE"
[ 0:01] <- 			flags=[]
[ 0:01] <- 			dev_size=69632
[ 0:01] <- 			pe_start=2048
[ 0:01] <- 			pe_count=66
[ 0:01] <- 		}
[ 0:01] <- 	}
[ 0:01] <- }
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10157
[ 0:01] <- cmd="vgcreate"
[ 0:01] vg_update vgid lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg name @PREFIX at vg
[ 0:01] update_metadata begin arg_vgid lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg arg_name @PREFIX at vg pvid none
[ 0:01] update_metadata new name @PREFIX at vg and new vgid lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg
[ 0:01] update_metadata_add_new for @PREFIX at vg lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg
[ 0:01] moving PV 2SW9iQ-fVZh-4zkR-npWT-9DRQ-GHo9-ETrxlP to VG lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg
[ 0:01] moving PV RtrWis-I0kI-1gLf-zwwl-Yqsq-U1Yz-TIzSOa to VG lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg
[ 0:01] update_metadata_add_new is done for @PREFIX@vg lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg
[ 0:01] -> response = "OK"
[ 0:01] -> 
[ 0:01] <- request="pv_found"
[ 0:01] <- pvmeta {
[ 0:01] <- 	device=65026
[ 0:01] <- 	dev_size=35651584
[ 0:01] <- 	format="lvm2"
[ 0:01] <- 	label_sector=1
[ 0:01] <- 	id="2SW9iQ-fVZh-4zkR-npWT-9DRQ-GHo9-ETrxlP"
[ 0:01] <- 	ext_version=2
[ 0:01] <- 	ext_flags=1
[ 0:01] <- 	mda0 {
[ 0:01] <- 		ignore=0
[ 0:01] <- 		start=4096
[ 0:01] <- 		size=1044480
[ 0:01] <- 		free_sectors=0
[ 0:01] <- 	}
[ 0:01] <- 	da0 {
[ 0:01] <- 		offset=1048576
[ 0:01] <- 		size=0
[ 0:01] <- 	}
[ 0:01] <- 	ba0 {
[ 0:01] <- 		offset=0
[ 0:01] <- 		size=0
[ 0:01] <- 	}
[ 0:01] <- }
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10157
[ 0:01] <- cmd="vgcreate"
[ 0:01] pv_found pvid 2SW9iQ-fVZh-4zkR-npWT-9DRQ-GHo9-ETrxlP on device 65026 matches existing
[ 0:01] -> response = "OK"
[ 0:01] -> status = "complete"
[ 0:01] -> changed = 0
[ 0:01] -> vgid = "lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg"
[ 0:01] -> vgname = "@PREFIX at vg"
[ 0:01] -> seqno_before = -1
[ 0:01] -> seqno_after = 1
[ 0:01] -> 
[ 0:01] <- request="pv_found"
[ 0:01] <- pvmeta {
[ 0:01] <- 	device=65027
[ 0:01] <- 	dev_size=35651584
[ 0:01] <- 	format="lvm2"
[ 0:01] <- 	label_sector=1
[ 0:01] <- 	id="RtrWis-I0kI-1gLf-zwwl-Yqsq-U1Yz-TIzSOa"
[ 0:01] <- 	ext_version=2
[ 0:01] <- 	ext_flags=1
[ 0:01] <- 	mda0 {
[ 0:01] <- 		ignore=0
[ 0:01] <- 		start=4096
[ 0:01] <- 		size=1044480
[ 0:01] <- 		free_sectors=0
[ 0:01] <- 	}
[ 0:01] <- 	da0 {
[ 0:01] <- 		offset=1048576
[ 0:01] <- 		size=0
[ 0:01] <- 	}
[ 0:01] <- 	ba0 {
[ 0:01] <- 		offset=0
[ 0:01] <- 		size=0
[ 0:01] <- 	}
[ 0:01] <- }
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10157
[ 0:01] <- cmd="vgcreate"
[ 0:01] pv_found pvid RtrWis-I0kI-1gLf-zwwl-Yqsq-U1Yz-TIzSOa on device 65027 matches existing
[ 0:01] -> response = "OK"
[ 0:01] -> status = "complete"
[ 0:01] -> changed = 0
[ 0:01] -> vgid = "lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg"
[ 0:01] -> vgname = "@PREFIX at vg"
[ 0:01] -> seqno_before = -1
[ 0:01] -> seqno_after = 1
[ 0:01] -> 
[ 0:01]   WARNING: This metadata update is NOT backed up.
[ 0:01]   Volume group "@PREFIX at vg" successfully created
[ 0:01] lvcreate -n bar -l 1 $vg
[ 0:01] #lvmetad-dump.sh:20+ lvcreate -n bar -l 1 @PREFIX at vg
[ 0:01] <- request="hello"
[ 0:01] -> response = "OK"
[ 0:01] -> protocol = "lvmetad"
[ 0:01] -> version = 1
[ 0:01] -> 
[ 0:01] <- request="get_global_info"
[ 0:01] <- token="skip"
[ 0:01] <- pid=10159
[ 0:01] <- cmd="lvcreate"
[ 0:01] 10159 global info flags none reason none token filter:4177279013 update_pid 0
[ 0:01] -> response = "OK"
[ 0:01] -> global_invalid = 0
[ 0:01] -> global_disable = 0
[ 0:01] -> disable_reason = "none"
[ 0:01] -> daemon_pid = 10099
[ 0:01] -> token = "filter:4177279013"
[ 0:01] -> update_cmd = ""
[ 0:01] -> update_pid = 0
[ 0:01] -> update_begin = 0
[ 0:01] -> update_timeout = 0
[ 0:01] -> 
[ 0:01] <- request="get_global_info"
[ 0:01] <- token="skip"
[ 0:01] <- pid=10159
[ 0:01] <- cmd="lvcreate"
[ 0:01] 10159 global info flags none reason none token filter:4177279013 update_pid 0
[ 0:01] -> response = "OK"
[ 0:01] -> global_invalid = 0
[ 0:01] -> global_disable = 0
[ 0:01] -> disable_reason = "none"
[ 0:01] -> daemon_pid = 10099
[ 0:01] -> token = "filter:4177279013"
[ 0:01] -> update_cmd = ""
[ 0:01] -> update_pid = 0
[ 0:01] -> update_begin = 0
[ 0:01] -> update_timeout = 0
[ 0:01] -> 
[ 0:01] <- request="vg_list"
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10159
[ 0:01] <- cmd="lvcreate"
[ 0:01] vg_list
[ 0:01] -> response="OK"
[ 0:01] -> volume_groups {
[ 0:01] -> 	lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg {
[ 0:01] -> 		name="@PREFIX at vg"
[ 0:01] -> 	}
[ 0:01] -> }
[ 0:01] -> 
[ 0:01] -> 
[ 0:01] -> 
[ 0:01] <- request="vg_lookup"
[ 0:01] <- uuid="lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg"
[ 0:01] <- name="@PREFIX at vg"
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10159
[ 0:01] <- cmd="lvcreate"
[ 0:01] vg_lookup vgid lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg name @PREFIX@vg
[ 0:01] -> response="OK"
[ 0:01] -> name="@PREFIX at vg"
[ 0:01] -> metadata {
[ 0:01] -> 	id="lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg"
[ 0:01] -> 	seqno=1
[ 0:01] -> 	format="lvm2"
[ 0:01] -> 	status=["RESIZEABLE","READ","WRITE"]
[ 0:01] -> 	flags=[]
[ 0:01] -> 	extent_size=1024
[ 0:01] -> 	max_lv=0
[ 0:01] -> 	max_pv=0
[ 0:01] -> 	metadata_copies=0
[ 0:01] -> 	physical_volumes {
[ 0:01] -> 		pv0 {
[ 0:01] -> 			device=65026
[ 0:01] -> 			format="lvm2"
[ 0:01] -> 			label_sector=1
[ 0:01] -> 			ext_version=2
[ 0:01] -> 			ext_flags=1
[ 0:01] -> 			mda0 {
[ 0:01] -> 				ignore=0
[ 0:01] -> 				start=4096
[ 0:01] -> 				size=1044480
[ 0:01] -> 				free_sectors=0
[ 0:01] -> 			}
[ 0:01] -> 			da0 {
[ 0:01] -> 				offset=1048576
[ 0:01] -> 				size=0
[ 0:01] -> 			}
[ 0:01] -> 			ba0 {
[ 0:01] -> 				offset=0
[ 0:01] -> 				size=0
[ 0:01] -> 			}
[ 0:01] -> 			id="2SW9iQ-fVZh-4zkR-npWT-9DRQ-GHo9-ETrxlP"
[ 0:01] -> 			status="ALLOCATABLE"
[ 0:01] -> 			flags=[]
[ 0:01] -> 			dev_size=69632
[ 0:01] -> 			pe_start=2048
[ 0:01] -> 			pe_count=66
[ 0:01] -> 		}
[ 0:01] -> 		pv1 {
[ 0:01] -> 			device=65027
[ 0:01] -> 			format="lvm2"
[ 0:01] -> 			label_sector=1
[ 0:01] -> 			ext_version=2
[ 0:01] -> 			ext_flags=1
[ 0:01] -> 			mda0 {
[ 0:01] -> 				ignore=0
[ 0:01] -> 				start=4096
[ 0:01] -> 				size=1044480
[ 0:01] -> 				free_sectors=0
[ 0:01] -> 			}
[ 0:01] -> 			da0 {
[ 0:01] -> 				offset=1048576
[ 0:01] -> 				size=0
[ 0:01] -> 			}
[ 0:01] -> 			ba0 {
[ 0:01] -> 				offset=0
[ 0:01] -> 				size=0
[ 0:01] -> 			}
[ 0:01] -> 			id="RtrWis-I0kI-1gLf-zwwl-Yqsq-U1Yz-TIzSOa"
[ 0:01] -> 			status="ALLOCATABLE"
[ 0:01] -> 			flags=[]
[ 0:01] -> 			dev_size=69632
[ 0:01] -> 			pe_start=2048
[ 0:01] -> 			pe_count=66
[ 0:01] -> 		}
[ 0:01] -> 	}
[ 0:01] -> }
[ 0:01] -> 
[ 0:01] -> 
[ 0:01] -> 
[ 0:01] <- request="vg_clear_outdated_pvs"
[ 0:01] <- vgid="lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg"
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10159
[ 0:01] <- cmd="lvcreate"
[ 0:01] vg_clear_outdated_pvs vgid lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg
[ 0:01] -> response = "OK"
[ 0:01] -> 
[ 0:01] <- request="set_vg_info"
[ 0:01] <- name="@PREFIX@vg"
[ 0:01] <- uuid="lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg"
[ 0:01] <- version=2
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10159
[ 0:01] <- cmd="lvcreate"
[ 0:01] set info VG name none uuid lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg cache_version 1 new_version 2
[ 0:01] -> response = "OK"
[ 0:01] -> 
[ 0:01]   WARNING: This metadata update is NOT backed up.
[ 0:01]   The link @TESTDIR@/dev/@PREFIX at vg/bar should have been created by udev but it was not found. Falling back to direct link creation.
[ 0:01]   @TESTDIR@/dev/mapper/@PREFIX at vg-bar not set up by udev: Falling back to direct node creation.
[ 0:01]   Logical volume "bar" created.
[ 0:01] <- request="vg_update"
[ 0:01] <- vgname="@PREFIX at vg"
[ 0:01] <- metadata {
[ 0:01] <- 	id="lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg"
[ 0:01] <- 	seqno=2
[ 0:01] <- 	format="lvm2"
[ 0:01] <- 	status=["RESIZEABLE","READ","WRITE"]
[ 0:01] <- 	flags=[]
[ 0:01] <- 	extent_size=1024
[ 0:01] <- 	max_lv=0
[ 0:01] <- 	max_pv=0
[ 0:01] <- 	metadata_copies=0
[ 0:01] <- 	physical_volumes {
[ 0:01] <- 		pv0 {
[ 0:01] <- 			id="2SW9iQ-fVZh-4zkR-npWT-9DRQ-GHo9-ETrxlP"
[ 0:01] <- 			device="@TESTDIR@/dev/mapper/@PREFIX at pv1"
[ 0:01] <- 			status="ALLOCATABLE"
[ 0:01] <- 			flags=[]
[ 0:01] <- 			dev_size=69632
[ 0:01] <- 			pe_start=2048
[ 0:01] <- 			pe_count=66
[ 0:01] <- 		}
[ 0:01] <- 		pv1 {
[ 0:01] <- 			id="RtrWis-I0kI-1gLf-zwwl-Yqsq-U1Yz-TIzSOa"
[ 0:01] <- 			device="@TESTDIR@/dev/mapper/@PREFIX at pv2"
[ 0:01] <- 			status="ALLOCATABLE"
[ 0:01] <- 			flags=[]
[ 0:01] <- 			dev_size=69632
[ 0:01] <- 			pe_start=2048
[ 0:01] <- 			pe_count=66
[ 0:01] <- 		}
[ 0:01] <- 	}
[ 0:01] <- 	logical_volumes {
[ 0:01] <- 		bar {
[ 0:01] <- 			id="9XWATe-xwqb-yU97-kbBO-WWPH-vmS4-U2HdkX"
[ 0:01] <- 			status=["READ","WRITE","VISIBLE"]
[ 0:01] <- 			flags=[]
[ 0:01] <- 			creation_time=1513257348
[ 0:01] <- 			creation_host="tw1"
[ 0:01] <- 			segment_count=1
[ 0:01] <- 			segment1 {
[ 0:01] <- 				start_extent=0
[ 0:01] <- 				extent_count=1
[ 0:01] <- 				type="striped"
[ 0:01] <- 				stripe_count=1
[ 0:01] <- 				stripes=["pv0",0]
[ 0:01] <- 			}
[ 0:01] <- 		}
[ 0:01] <- 	}
[ 0:01] <- }
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10159
[ 0:01] <- cmd="lvcreate"
[ 0:01] vg_update vgid lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg name @PREFIX at vg
[ 0:01] update_metadata begin arg_vgid lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg arg_name @PREFIX at vg pvid none
[ 0:01] update_metadata existing vgid lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg and existing name @PREFIX at vg
[ 0:01] update_metadata for @PREFIX at vg lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg from 1 to 2
[ 0:01] moving PV 2SW9iQ-fVZh-4zkR-npWT-9DRQ-GHo9-ETrxlP to VG #orphan
[ 0:01] moving PV RtrWis-I0kI-1gLf-zwwl-Yqsq-U1Yz-TIzSOa to VG #orphan
[ 0:01] moving PV 2SW9iQ-fVZh-4zkR-npWT-9DRQ-GHo9-ETrxlP to VG lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg
[ 0:01] moving PV RtrWis-I0kI-1gLf-zwwl-Yqsq-U1Yz-TIzSOa to VG lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg
[ 0:01] update_metadata is done for @PREFIX@vg lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg
[ 0:01] -> response = "OK"
[ 0:01] -> 
[ 0:01] <- request="pv_found"
[ 0:01] <- pvmeta {
[ 0:01] <- 	device=65026
[ 0:01] <- 	dev_size=69632
[ 0:01] <- 	format="lvm2"
[ 0:01] <- 	label_sector=1
[ 0:01] <- 	id="2SW9iQ-fVZh-4zkR-npWT-9DRQ-GHo9-ETrxlP"
[ 0:01] <- 	ext_version=2
[ 0:01] <- 	ext_flags=1
[ 0:01] <- 	mda0 {
[ 0:01] <- 		ignore=0
[ 0:01] <- 		start=4096
[ 0:01] <- 		size=1044480
[ 0:01] <- 		free_sectors=0
[ 0:01] <- 	}
[ 0:01] <- 	da0 {
[ 0:01] <- 		offset=1048576
[ 0:01] <- 		size=0
[ 0:01] <- 	}
[ 0:01] <- 	ba0 {
[ 0:01] <- 		offset=0
[ 0:01] <- 		size=0
[ 0:01] <- 	}
[ 0:01] <- }
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10159
[ 0:01] <- cmd="lvcreate"
[ 0:01] pv_found pvid 2SW9iQ-fVZh-4zkR-npWT-9DRQ-GHo9-ETrxlP on device 65026 matches existing
[ 0:01] -> response = "OK"
[ 0:01] -> status = "complete"
[ 0:01] -> changed = 1
[ 0:01] -> vgid = "lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg"
[ 0:01] -> vgname = "@PREFIX at vg"
[ 0:01] -> seqno_before = -1
[ 0:01] -> seqno_after = 2
[ 0:01] -> 
[ 0:01] <- request="pv_found"
[ 0:01] <- pvmeta {
[ 0:01] <- 	device=65027
[ 0:01] <- 	dev_size=69632
[ 0:01] <- 	format="lvm2"
[ 0:01] <- 	label_sector=1
[ 0:01] <- 	id="RtrWis-I0kI-1gLf-zwwl-Yqsq-U1Yz-TIzSOa"
[ 0:01] <- 	ext_version=2
[ 0:01] <- 	ext_flags=1
[ 0:01] <- 	mda0 {
[ 0:01] <- 		ignore=0
[ 0:01] <- 		start=4096
[ 0:01] <- 		size=1044480
[ 0:01] <- 		free_sectors=0
[ 0:01] <- 	}
[ 0:01] <- 	da0 {
[ 0:01] <- 		offset=1048576
[ 0:01] <- 		size=0
[ 0:01] <- 	}
[ 0:01] <- 	ba0 {
[ 0:01] <- 		offset=0
[ 0:01] <- 		size=0
[ 0:01] <- 	}
[ 0:01] <- }
[ 0:01] <- token="filter:4177279013"
[ 0:01] <- update_timeout=10
[ 0:01] <- pid=10159
[ 0:01] <- cmd="lvcreate"
[ 0:01] pv_found pvid RtrWis-I0kI-1gLf-zwwl-Yqsq-U1Yz-TIzSOa on device 65027 matches existing
[ 0:01] -> response = "OK"
[ 0:01] -> status = "complete"
[ 0:01] -> changed = 1
[ 0:01] -> vgid = "lTvD1O-DOED-MioS-nwcM-WXA0-SZis-lsbqMg"
[ 0:01] -> vgname = "@PREFIX at vg"
[ 0:01] -> seqno_before = -1
[ 0:01] -> seqno_after = 2
[ 0:01] -> 
[ 0:01] 
[ 0:01] aux lvmetad_dump | tee lvmetad.txt
[ 0:01] #lvmetad-dump.sh:22+ tee lvmetad.txt
[ 0:01] #lvmetad-dump.sh:22+ aux lvmetad_dump
[ 0:01] + test -f DEVICES
[ 0:01] + devs='@TESTDIR@/dev/mapper/@PREFIX at pv1
[ 0:01] @TESTDIR@/dev/mapper/@PREFIX at pv2'
[ 0:01] + test lvmetad_dump = dmsetup
[ 0:01] + lvmetad_dump
[ 0:01] + echo 'request="dump"'
[ 0:01] + echo '##'
[ 0:01] + lvmetad_talk
[ 0:01] + local use=nc
[ 0:01] + type -p socat
[ 0:01] + echo
[ 0:01] + not nc -U @TESTDIR@/lvmetad.socket
[ 0:01] aux teardown
[ 1:24] ##lvmetad-dump.sh:1+ aux teardown
[ 1:24] + test -f DEVICES
[ 1:24] + devs='@TESTDIR@/dev/mapper/@PREFIX at pv1
[ 1:24] @TESTDIR@/dev/mapper/@PREFIX at pv2'
[ 1:24] + test teardown = dmsetup
[ 1:24] + teardown
[ 1:24] + local TEST_LEAKED_DEVICES=
[ 1:24] + echo -n '## teardown...'
[ 1:24] ## teardown...+ unset LVM_LOG_FILE_EPOCH
[ 1:24] + test -f TESTNAME
[ 1:24] + test '!' -f SKIP_THIS_TEST
[ 1:24] ++ dmsetup table
[ 1:24] ++ grep @PREFIX@
[ 1:24] ++ grep -v @PREFIX at pv
[ 1:24] + TEST_LEAKED_DEVICES='@PREFIX at vg-bar: 0 1024 linear 254:2 2048'
[ 1:24] + kill_tagged_processes
[ 1:24] + local pid
[ 1:24] + local wait
[ 1:24] + pids=()
[ 1:24] + local pids
[ 1:24] + read -r pid wait
[ 1:24] ++ print_procs_by_tag_
[ 1:24] ++ ps -o pid,args ehax
[ 1:24] ++ grep -weLVM_TEST_TAG=kill_me_ at PREFIX@
[ 1:24] ++ true
[ 1:24] + test 0 -eq 0
[ 1:24] + return
[ 1:24] + test -n ''
[ 1:24] + kill_sleep_kill_ LOCAL_LVMETAD 0
[ 1:24] + local pidfile=LOCAL_LVMETAD
[ 1:24] + local slow=0
[ 1:24] + test -s LOCAL_LVMETAD
[ 1:24] + pid=10099
[ 1:24] + rm -f LOCAL_LVMETAD
[ 1:24] + kill -TERM 10099
[ 1:24] + test 0 -eq 0
[ 1:24] + sleep .1
[ 1:24] I: lvmetad waiting for client threads to finish
[ 1:24] fini
[ 1:24] I: lvmetad shutting down
[ 1:24] + kill -KILL 10099
[ 1:24] + true
[ 1:24] + local wait=0
[ 1:24] + ps 10099
[ 1:24] + dm_table
[ 1:24] + should dmsetup table
[ 1:24] + not grep -E -q '@PREFIX at vg|@PREFIX at vg1|@PREFIX at vg2|@PREFIX at vg3|@PREFIX at vg4'
[ 1:24] ++ test -s LOCAL_DMEVENTD
[ 1:24] ++ echo '--config activation{monitoring=0}'
[ 1:24] + cfg='--config activation{monitoring=0}'
[ 1:24] + dm_info suspended,name
[ 1:24] + should dmsetup info --noheadings -c -o suspended,name
[ 1:24] + grep -q '^Suspended:.*@PREFIX@'
[ 1:24] + vgremove -ff '--config activation{monitoring=0}' @PREFIX at vg @PREFIX at vg1 @PREFIX at vg2 @PREFIX at vg3 @PREFIX at vg4
[ 1:24] + rm -f debug.log strace.log
[ 1:24] + kill_sleep_kill_ LOCAL_LVMDBUSD 0
[ 1:24] + local pidfile=LOCAL_LVMDBUSD
[ 1:24] + local slow=0
[ 1:24] + test -s LOCAL_LVMDBUSD
[ 1:24] + echo -n .
[ 1:24] .+ kill_sleep_kill_ LOCAL_LVMPOLLD 0
[ 1:24] + local pidfile=LOCAL_LVMPOLLD
[ 1:24] + local slow=0
[ 1:24] + test -s LOCAL_LVMPOLLD
[ 1:24] + echo -n .
[ 1:24] .+ kill_sleep_kill_ LOCAL_CLVMD 0
[ 1:24] + local pidfile=LOCAL_CLVMD
[ 1:24] + local slow=0
[ 1:24] + test -s LOCAL_CLVMD
[ 1:24] + echo -n .
[ 1:24] .+ kill_sleep_kill_ LOCAL_DMEVENTD 0
[ 1:24] + local pidfile=LOCAL_DMEVENTD
[ 1:24] + local slow=0
[ 1:24] + test -s LOCAL_DMEVENTD
[ 1:24] + echo -n .
[ 1:24] .+ test -d @TESTDIR@/dev/mapper
[ 1:24] + teardown_devs
[ 1:24] + teardown_udev_cookies
[ 1:24] + test 1 = 1
[ 1:24] + grep -v '^0 '
[ 1:24] + dmsetup udevcomplete_all -y 10
[ 1:24] + true
[ 1:24] + test '!' -f MD_DEV
[ 1:24] + test '!' -f DEVICES
[ 1:24] + teardown_devs_prefixed @PREFIX@
[ 1:24] + local prefix=@PREFIX@
[ 1:24] + local stray=0
[ 1:24] + local 'IFS=
[ 1:24] '
[ 1:24] + local dm
[ 1:24] + rm -rf '@TESTDIR@/dev/@PREFIX@*'
[ 1:24] ++ dm_info suspended,name
[ 1:24] ++ grep '^Suspended:.*@PREFIX@'
[ 1:24] ++ should dmsetup info --noheadings -c -o suspended,name
[ 1:24] + wait
[ 1:24] + mounts=($(grep "$prefix" /proc/mounts | cut -d' ' -f1))
[ 1:24] ++ grep @PREFIX@ /proc/mounts
[ 1:24] ++ cut '-d ' -f1
[ 1:24] + local mounts
[ 1:24] + test 0 -gt 0
[ 1:24] + rm -f REMOVE_FAILED
[ 1:24] + for i in 0 1
[ 1:24] + local num_remaining_devs=999999
[ 1:24] + local num_devs=0
[ 1:24] + test 0 = 1
[ 1:24] + :
[ 1:24] + local cnt
[ 1:24] + local sortby=name
[ 1:24] + local need_udev_wait=0
[ 1:24] + test 0 = 0
[ 1:24] + dm_info name,open --separator ' ' --sort open,name
[ 1:24] + should dmsetup info --noheadings -c -o name,open --separator ' ' --sort open,name
[ 1:24] + grep @PREFIX@
[ 1:24] ++ wc -l
[ 1:24] + num_devs=3
[ 1:24] + test 3 -lt 999999
[ 1:24] + test 0 = 0
[ 1:24] + IFS=' '
[ 1:24] + read -r dm cnt
[ 1:24] + test 0 = 0
[ 1:24] + test 0 -eq 0
[ 1:24] + need_udev_wait=1
[ 1:24] + IFS=' '
[ 1:24] + read -r dm cnt
[ 1:24] + test 0 = 0
[ 1:24] + test 0 -eq 0
[ 1:24] + need_udev_wait=1
[ 1:24] + IFS=' '
[ 1:24] + read -r dm cnt
[ 1:24] + dmsetup remove @PREFIX at vg-bar
[ 1:24] + test 0 = 0
[ 1:24] + test 1 -eq 0
[ 1:24] + break
[ 1:24] + test 1 -eq 1
[ 1:24] + udev_wait
[ 1:24] + pgrep udev
[ 1:24] + dmsetup remove @PREFIX at pv2
[ 1:24] + which udevadm
[ 1:24] + test -n ''
[ 1:24] + udevadm settle --timeout=15
[ 1:24] + wait
[ 1:24] + num_remaining_devs=3
[ 1:24] + :
[ 1:24] + local cnt
[ 1:24] + local sortby=name
[ 1:24] + local need_udev_wait=0
[ 1:24] + test 0 = 0
[ 1:24] + dm_info name,open --separator ' ' --sort open,name
[ 1:24] + should dmsetup info --noheadings -c -o name,open --separator ' ' --sort open,name
[ 1:24] + grep @PREFIX@
[ 1:24] ++ wc -l
[ 1:24] + num_devs=1
[ 1:24] + test 1 -lt 3
[ 1:24] + test 0 = 0
[ 1:24] + IFS=' '
[ 1:24] + read -r dm cnt
[ 1:24] + test 0 = 0
[ 1:24] + test 0 -eq 0
[ 1:24] + need_udev_wait=1
[ 1:24] + IFS=' '
[ 1:24] + read -r dm cnt
[ 1:24] + test 1 -eq 1
[ 1:24] + udev_wait
[ 1:24] + pgrep udev
[ 1:24] + dmsetup remove @PREFIX at pv1
[ 1:24] + which udevadm
[ 1:24] + test -n ''
[ 1:24] + udevadm settle --timeout=15
[ 1:24] + wait
[ 1:24] + num_remaining_devs=1
[ 1:24] + :
[ 1:24] + local cnt
[ 1:24] + local sortby=name
[ 1:24] + local need_udev_wait=0
[ 1:24] + test 0 = 0
[ 1:24] + dm_info name,open --separator ' ' --sort open,name
[ 1:24] + grep @PREFIX@
[ 1:24] + should dmsetup info --noheadings -c -o name,open --separator ' ' --sort open,name
[ 1:24] + break 2
[ 1:24] + test -f SCSI_DEBUG_DEV
[ 1:24] + test '!' -f LOOP
[ 1:24] + losetup -d /dev/loop0
[ 1:24] + test '!' -f LOOPFILE
[ 1:24] + not diff LOOP BACKING_DEV
[ 1:24] + rm -f BACKING_DEV
[ 1:24] + rm -f DEVICES LOOP
[ 1:24] + test 0 -eq 1
[ 1:24] + test -z LVMTEST
[ 1:24] + stray_loops=($(losetup -a | grep "$COMMON_PREFIX" | cut -d: -f1))
[ 1:24] ++ losetup -a
[ 1:24] ++ grep LVMTEST
[ 1:24] ++ cut -d: -f1
[ 1:24] + local stray_loops
[ 1:24] + test 0 -eq 0
[ 1:24] + echo -n .
[ 1:24] .+ test -z '@PREFIX at vg-bar: 0 1024 linear 254:2 2048'
[ 1:24] + echo '## unexpected devices left dm table:'
[ 1:24] ## unexpected devices left dm table:
[ 1:24] + echo '@PREFIX at vg-bar: 0 1024 linear 254:2 2048'
[ 1:24] @PREFIX at vg-bar: 0 1024 linear 254:2 2048
[ 1:24] + return 1
[ 1:24] set +vx; STACKTRACE; set -vx
[ 1:24] ###lvmetad-dump.sh:1+ set +vx
[ 1:24] ## - /root/lvm2/test/shell/lvmetad-dump.sh:1
[ 1:24] ## 1 STACKTRACE() called from /root/lvm2/test/shell/lvmetad-dump.sh:1
[ 1:24] <======== Script file "lvmetad-dump.sh" ========>
[ 1:24] ## Line: 1 	 #!/usr/bin/env bash
[ 1:24] ## Line: 2 	 
[ 1:24] ## Line: 3 	 # Copyright (C) 2012 Red Hat, Inc. All rights reserved.
[ 1:24] ## Line: 4 	 #
[ 1:24] ## Line: 5 	 # This copyrighted material is made available to anyone wishing to use,
[ 1:24] ## Line: 6 	 # modify, copy, or redistribute it subject to the terms and conditions
[ 1:24] ## Line: 7 	 # of the GNU General Public License v.2.
[ 1:24] ## Line: 8 	 #
[ 1:24] ## Line: 9 	 # You should have received a copy of the GNU General Public License
[ 1:24] ## Line: 10 	 # along with this program; if not, write to the Free Software Foundation,
[ 1:24] ## Line: 11 	 # Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA
[ 1:24] ## Line: 12 	 
[ 1:24] ## Line: 13 	 SKIP_WITH_LVMLOCKD=1
[ 1:24] ## Line: 14 	 SKIP_WITHOUT_LVMETAD=1
[ 1:24] ## Line: 15 	 SKIP_WITH_LVMPOLLD=1
[ 1:24] ## Line: 16 	 
[ 1:24] ## Line: 17 	 . lib/inittest
[ 1:24] ## Line: 18 	 
[ 1:24] ## Line: 19 	 aux prepare_vg 2
[ 1:24] ## Line: 20 	 lvcreate -n bar -l 1 $vg
[ 1:24] ## Line: 21 	 
[ 1:24] ## Line: 22 	 aux lvmetad_dump | tee lvmetad.txt
[ 1:24] ## Line: 23 	 
[ 1:24] ## Line: 24 	 grep $vg lvmetad.txt
[ 1:24] ## Line: 25 	 
[ 1:24] ## Line: 26 	 vgremove -ff $vg
###  interrupted: [ndev-lvmetad] shell/lvmetad-dump.sh

### 3 tests: 0 passed, 2 skipped, 0 timed out, 0 warned, 0 failed
make: *** [Makefile:123: check] Error 1

^ permalink raw reply	[flat|nested] 6+ messages in thread

* [PATCH] test: lvmetad_dump always timed out when using nc
  2017-12-14 13:28     ` Eric Ren
@ 2017-12-14 14:07       ` Zdenek Kabelac
  2017-12-14 15:01         ` Eric Ren
  0 siblings, 1 reply; 6+ messages in thread
From: Zdenek Kabelac @ 2017-12-14 14:07 UTC (permalink / raw)
  To: lvm-devel

Dne 14.12.2017 v 14:28 Eric Ren napsal(a):
> Hi,
> 
> On 12/14/2017 06:39 PM, Zdenek Kabelac wrote:
>> Dne 14.12.2017 v 11:27 Eric Ren napsal(a):
>>> Hi zkabelac,
>>>
>>> Hmm strange, tested on fedora, it has not this issue.
>>>
>>> ```
>>>
>>
>> Hi
>>
>> Yep - in fact I've? been a bit puzzled by your patch since I could not think 
>> why that should be needed.
> 
> Hah sorry, I will always verify the issue on fedora first when I report 
> problem in upstream :)
> 
>>
>> We will possibly need to put OpenSuse as a test machine somewhere.
> 
> Thanks, but it's not a very trivial task. openSUSE tumbleweed is a rolling 
> release, which
> is usually used for developing purpose, but it's not that easy to maintain 
> (upgrade). Besides,
> some raid testcases in upstream code can pass on fedora, but fail on openSUSE, 
> which seems
> caused by some raid kernel patches (not yet inspect carefully on those failures).
> 
> It's already very cool to have such kind upstream, appreciate!
> 
>>
>>
>> Can you provide full test trace where you get lock ?
>>
>>
>> 'make check_local T=selectsometest? VERBOSE=1 LVM_TEST_AUX_TRACE=1 &>/tmp/log'
> 
> 'make check_local' is skipped:
> ```
> tw1:~/lvm2/test # make check_local T=lvmetad-dump? VERBOSE=1 
> LVM_TEST_AUX_TRACE=1? &>/tmp/log1.txt
> ```
> 
> 'make check'? hangs up forever until CTR+c:
> ```
> tw1:~/lvm2/test # make check T=lvmetad-dump? VERBOSE=1 LVM_TEST_AUX_TRACE=1  
> &>/tmp/log2.txt
> ^C
> ```
> 
> The logs are attached.


While the trace shows nothing wrong - isn't this same issue as you had with 
dmeventd ?

Both services needs to be masked together with their sockets on testing 
machine for testing services (unless you build test package which then is able 
to run with installed binaries)

Although the socket for testing should be different from 'real one'.

but anyway - you need to provide trace from blocking run:

make check_lvmetad T=lvmetad-dump  VERBOSE=1 LVM_TEST_AUX_TRACE=1 &>/tmp/log.txt



Regards

Zdenek



^ permalink raw reply	[flat|nested] 6+ messages in thread

* [PATCH] test: lvmetad_dump always timed out when using nc
  2017-12-14 14:07       ` Zdenek Kabelac
@ 2017-12-14 15:01         ` Eric Ren
  0 siblings, 0 replies; 6+ messages in thread
From: Eric Ren @ 2017-12-14 15:01 UTC (permalink / raw)
  To: lvm-devel

Hi,

> While the trace shows nothing wrong - isn't this same issue as you had 
> with dmeventd ?

log2.txt - the log of the blocked one shows it blocks at "not nc -U ..." 
until Ctr+c to teardown:

```
[ 0:01] aux lvmetad_dump | tee lvmetad.txt
[ 0:01] #lvmetad-dump.sh:22+ tee lvmetad.txt
[ 0:01] #lvmetad-dump.sh:22+ aux lvmetad_dump
[ 0:01] + test -f DEVICES
[ 0:01] + devs='@TESTDIR@/dev/mapper/@PREFIX at pv1
[ 0:01] @TESTDIR@/dev/mapper/@PREFIX at pv2'
[ 0:01] + test lvmetad_dump = dmsetup
[ 0:01] + lvmetad_dump
[ 0:01] + echo 'request="dump"'
[ 0:01] + echo '##'
[ 0:01] + lvmetad_talk
[ 0:01] + local use=nc
[ 0:01] + type -p socat
[ 0:01] + echo
[ 0:01] + not nc -U @TESTDIR@/lvmetad.socket
[ 0:01] aux teardown
[ 1:24] ##lvmetad-dump.sh:1+ aux teardown
```
>
> Both services needs to be masked together with their sockets on 
> testing machine for testing services (unless you build test package 
> which then is able to run with installed binaries)
>
> Although the socket for testing should be different from 'real one'.

Both lvm2-lvmetad.[service|socket] are disabled/stopped:
```
tw1:~/lvm2/test # systemctl status lvm2-lvmetad.service
? lvm2-lvmetad.service - LVM2 metadata daemon
 ?? Loaded: loaded (/usr/lib/systemd/system/lvm2-lvmetad.service; 
static; vendor preset: disabled)
 ?? Active: inactive (dead)
 ???? Docs: man:lvmetad(8)
tw1:~/lvm2/test # systemctl status lvm2-lvmetad.socket
? lvm2-lvmetad.socket - LVM2 metadata daemon socket
 ?? Loaded: loaded (/usr/lib/systemd/system/lvm2-lvmetad.socket; 
disabled; vendor preset: enabled)
 ?? Active: inactive (dead) since Thu 2017-12-14 21:11:04 CST; 1h 52min ago
 ???? Docs: man:lvmetad(8)
 ?? Listen: /run/lvm/lvmetad.socket (Stream)

Dec 14 21:11:04 tw1 systemd[1]: Closed LVM2 metadata daemon socket.
```

>
> but anyway - you need to provide trace from blocking run:
>
> make check_lvmetad T=lvmetad-dump? VERBOSE=1 LVM_TEST_AUX_TRACE=1 
> &>/tmp/log.txt

tw1:~/lvm2/test # make check_lvmetad T=lvmetad-dump? VERBOSE=1 
LVM_TEST_AUX_TRACE=1 &>/tmp/log3.txt
^C

log3.txt attached.

Thanks,
Eric
-------------- next part --------------
make -C api device-mapper
make[1]: Entering directory '/root/lvm2/test/api'
make[1]: Nothing to be done for 'device-mapper'.
make[1]: Leaving directory '/root/lvm2/test/api'
make -C unit device-mapper
make[1]: Entering directory '/root/lvm2/test/unit'
make[1]: Nothing to be done for 'device-mapper'.
make[1]: Leaving directory '/root/lvm2/test/unit'
make -C api
make[1]: Entering directory '/root/lvm2/test/api'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory '/root/lvm2/test/api'
make -C unit
make[1]: Entering directory '/root/lvm2/test/unit'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory '/root/lvm2/test/unit'
touch .tests-stamp
VERBOSE=1 ./lib/runner \
	--testdir . --outdir results \
	--flavours ndev-lvmetad --only lvmetad-dump --skip @ 
running 1 tests

[ 0:00] Library version:   1.02.146-git (2017-11-03)
[ 0:00] Driver version:    4.36.0
[ 0:00] Kernel is Linux tw1 4.13.5-1-default #1 SMP PREEMPT Thu Oct 5 18:28:26 UTC 2017 (3fd9659) x86_64 x86_64 x86_64 GNU/Linux
[ 0:00] Selinux mode is not installed.
[ 0:00]               total        used        free      shared  buff/cache   available
[ 0:00] Mem:            974         203          68           0         702         616
[ 0:00] Swap:          2053          90        1963
[ 0:00] Filesystem      Size  Used Avail Use% Mounted on
[ 0:00] devtmpfs        993M  8.0K  993M   1% /dev
[ 0:00] tmpfs          1000M     0 1000M   0% /dev/shm
[ 0:00] tmpfs          1000M  1.3M  998M   1% /run
[ 0:00] tmpfs          1000M     0 1000M   0% /sys/fs/cgroup
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /usr/local
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /.snapshots
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /boot/grub2/x86_64-efi
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /var/crash
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /var/cache
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /var/opt
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /opt
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /var/lib/named
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /var/log
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /var/lib/pgsql
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /var/lib/mariadb
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /tmp
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /var/lib/mysql
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /var/spool
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /srv
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /boot/grub2/i386-pc
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /var/tmp
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /var/lib/libvirt/images
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /var/lib/machines
[ 0:00] /dev/vda2        40G   34G  5.7G  86% /var/lib/mailman
[ 0:00] /dev/vda3        59G  108M   59G   1% /home
[ 0:00] tmpfs            98M   16K   98M   1% /run/user/478
[ 0:00] tmpfs            98M     0   98M   0% /run/user/0
[ 0:00] @TESTDIR=/tmp/LVMTEST10799.Ar4WzFQAt6
[ 0:00] @PREFIX=LVMTEST10799
[ 0:00] + test -f DEVICES
[ 0:00] + test prepare_lvmetad = dmsetup
[ 0:00] + prepare_lvmetad
[ 0:00] + check_daemon_in_builddir lvmetad
[ 0:00] + test -z ''
[ 0:00] + which lvmetad
[ 0:00] + grep -q /root/lvm2/test
[ 0:00] + rm -f debug.log strace.log
[ 0:00] + local run_valgrind=
[ 0:00] + test 0 -eq 0
[ 0:00] + kill_sleep_kill_ LOCAL_LVMETAD 0
[ 0:00] + local pidfile=LOCAL_LVMETAD
[ 0:00] + local slow=0
[ 0:00] + test -s LOCAL_LVMETAD
[ 0:00] + lvmconf 'global/use_lvmetad = 1' 'devices/md_component_detection = 0'
[ 0:00] + local profile_name=
[ 0:00] + test 2 -eq 0
[ 0:00] + local needed=0
[ 0:00] + for i in "$@"
[ 0:00] ++ grep global/use_lvmetad CONFIG_VALUES
[ 0:00] ++ tail -1
[ 0:00] + val=
[ 0:00] + needed=1
[ 0:00] + break
[ 0:00] + test 1 -eq 0
[ 0:00] + generate_config 'global/use_lvmetad = 1' 'devices/md_component_detection = 0'
[ 0:00] + test -n ''
[ 0:00] + config_values=CONFIG_VALUES
[ 0:00] + config=CONFIG
[ 0:00] + LVM_TEST_LOCKING=1
[ 0:00] + LVM_TEST_LVMETAD=1
[ 0:00] + LVM_TEST_LVMPOLLD=0
[ 0:00] + LVM_TEST_LVMLOCKD=0
[ 0:00] + test @TESTDIR@/dev = /dev
[ 0:00] + LVM_VERIFY_UDEV=1
[ 0:00] + test -f CONFIG_VALUES
[ 0:00] + cat
[ 0:00] + test -z varset
[ 0:00] + cat
[ 0:00] + local v
[ 0:00] + test 2 -gt 0
[ 0:00] + printf '%s\n' 'global/use_lvmetad = 1' 'devices/md_component_detection = 0'
[ 0:00] + declare -A CONF
[ 0:00] + local sec
[ 0:00] + local last_sec=
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='checks = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='monitoring = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='polling_interval = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='retry_deactivation = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='snapshot_autoextend_percent = 50'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='snapshot_autoextend_threshold = 50'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='udev_rules = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='udev_sync = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='verify_udev_operations = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='raid_region_size = 512'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='wipe_signatures_when_zeroing_new_lvs = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='archive = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='backup = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='cache_dir = "@TESTDIR@/etc"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='default_data_alignment = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='dir = "@TESTDIR@/dev"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='filter = "a|.*|"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='global_filter = [ "a|@TESTDIR@/dev/mapper/@PREFIX at .*pv[0-9_]*$|", "r|.*|" ]'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='md_component_detection  = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='scan = "@TESTDIR@/dev"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='sysfs_scan = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='write_cache_state = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='abort_on_internal_errors = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='cache_check_executable = "/usr/sbin/cache_check"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='cache_dump_executable = "/usr/sbin/cache_dump"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='cache_repair_executable = "/usr/sbin/cache_repair"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='detect_internal_vg_cache_corruption = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='fallback_to_local_locking = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='library_dir = "@TESTDIR@/lib"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='locking_dir = "@TESTDIR@/var/lock/lvm"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]=locking_type=1
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='notify_dbus = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='si_unit_consistency = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='thin_check_executable = "/usr/sbin/thin_check"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='thin_dump_executable = "/usr/sbin/thin_dump"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='thin_repair_executable = "/usr/sbin/thin_repair"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='use_lvmetad = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='use_lvmpolld = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='use_lvmlockd = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='activation = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='file = "@TESTDIR@/debug.log"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='indent = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='level = 9'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='overwrite = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='syslog = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='verbose = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='executable = "/root/lvm2/test/lib/dmeventd"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='fsadm_executable = "/root/lvm2/test/lib/fsadm"'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='use_lvmetad = 1'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + CONF["${v%%[={ ]*}"]='md_component_detection = 0'
[ 0:00] + IFS=
[ 0:00] + read -r v
[ 0:00] + printf '%s\n' global/abort_on_internal_errors global/cache_repair_executable global/detect_internal_vg_cache_corruption devices/filter devices/sysfs_scan log/indent log/file global/use_lvmpolld activation/raid_region_size activation/polling_interval log/verbose global/locking_type global/si_unit_consistency global/notify_dbus dmeventd/executable devices/default_data_alignment global/use_lvmetad log/level log/activation devices/global_filter devices/write_cache_state activation/snapshot_autoextend_percent backup/archive log/overwrite devices/cache_dir global/locking_dir allocation/wipe_signatures_when_zeroing_new_lvs activation/monitoring global/fsadm_executable global/cache_check_executable activation/verify_udev_operations global/library_dir devices/md_component_detection activation/snapshot_autoextend_threshold activation/checks activation/udev_rules devices/dir log/syslog global/thin_check_executable global/thin_dump_executable global/thin_repair_executable activation/udev_sync devices/scan activation/retry_deactivation global/fallback_to_local_locking backup/backup global/use_lvmlockd global/cache_dump_executable
[ 0:00] + read -r v
[ 0:00] + sort
[ 0:00] + sec=activation
[ 0:00] + test activation = ''
[ 0:00] + test -z ''
[ 0:00] + echo 'activation {'
[ 0:00] + last_sec=activation
[ 0:00] + echo '    checks = 1'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    monitoring = 0'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    polling_interval = 1'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    raid_region_size = 512'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    retry_deactivation = 1'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    snapshot_autoextend_percent = 50'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    snapshot_autoextend_threshold = 50'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    udev_rules = 1'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    udev_sync = 1'
[ 0:00] + read -r v
[ 0:00] + sec=activation
[ 0:00] + test activation = activation
[ 0:00] + echo '    verify_udev_operations = 1'
[ 0:00] + read -r v
[ 0:00] + sec=allocation
[ 0:00] + test allocation = activation
[ 0:00] + test -z activation
[ 0:00] + echo '}'
[ 0:00] + echo 'allocation {'
[ 0:00] + last_sec=allocation
[ 0:00] + echo '    wipe_signatures_when_zeroing_new_lvs = 0'
[ 0:00] + read -r v
[ 0:00] + sec=backup
[ 0:00] + test backup = allocation
[ 0:00] + test -z allocation
[ 0:00] + echo '}'
[ 0:00] + echo 'backup {'
[ 0:00] + last_sec=backup
[ 0:00] + echo '    archive = 0'
[ 0:00] + read -r v
[ 0:00] + sec=backup
[ 0:00] + test backup = backup
[ 0:00] + echo '    backup = 0'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = backup
[ 0:00] + test -z backup
[ 0:00] + echo '}'
[ 0:00] + echo 'devices {'
[ 0:00] + last_sec=devices
[ 0:00] + echo '    cache_dir = "@TESTDIR@/etc"'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = devices
[ 0:00] + echo '    default_data_alignment = 1'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = devices
[ 0:00] + echo '    dir = "@TESTDIR@/dev"'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = devices
[ 0:00] + echo '    filter = "a|.*|"'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = devices
[ 0:00] + echo '    global_filter = [ "a|@TESTDIR@/dev/mapper/@PREFIX at .*pv[0-9_]*$|", "r|.*|" ]'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = devices
[ 0:00] + echo '    md_component_detection = 0'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = devices
[ 0:00] + echo '    scan = "@TESTDIR@/dev"'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = devices
[ 0:00] + echo '    sysfs_scan = 1'
[ 0:00] + read -r v
[ 0:00] + sec=devices
[ 0:00] + test devices = devices
[ 0:00] + echo '    write_cache_state = 0'
[ 0:00] + read -r v
[ 0:00] + sec=dmeventd
[ 0:00] + test dmeventd = devices
[ 0:00] + test -z devices
[ 0:00] + echo '}'
[ 0:00] + echo 'dmeventd {'
[ 0:00] + last_sec=dmeventd
[ 0:00] + echo '    executable = "/root/lvm2/test/lib/dmeventd"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = dmeventd
[ 0:00] + test -z dmeventd
[ 0:00] + echo '}'
[ 0:00] + echo 'global {'
[ 0:00] + last_sec=global
[ 0:00] + echo '    abort_on_internal_errors = 1'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    cache_check_executable = "/usr/sbin/cache_check"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    cache_dump_executable = "/usr/sbin/cache_dump"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    cache_repair_executable = "/usr/sbin/cache_repair"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    detect_internal_vg_cache_corruption = 1'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    fallback_to_local_locking = 0'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    fsadm_executable = "/root/lvm2/test/lib/fsadm"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    library_dir = "@TESTDIR@/lib"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    locking_dir = "@TESTDIR@/var/lock/lvm"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    locking_type=1'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    notify_dbus = 0'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    si_unit_consistency = 1'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    thin_check_executable = "/usr/sbin/thin_check"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    thin_dump_executable = "/usr/sbin/thin_dump"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    thin_repair_executable = "/usr/sbin/thin_repair"'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    use_lvmetad = 1'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    use_lvmlockd = 0'
[ 0:00] + read -r v
[ 0:00] + sec=global
[ 0:00] + test global = global
[ 0:00] + echo '    use_lvmpolld = 0'
[ 0:00] + read -r v
[ 0:00] + sec=log
[ 0:00] + test log = global
[ 0:00] + test -z global
[ 0:00] + echo '}'
[ 0:00] + echo 'log {'
[ 0:00] + last_sec=log
[ 0:00] + echo '    activation = 1'
[ 0:00] + read -r v
[ 0:00] + sec=log
[ 0:00] + test log = log
[ 0:00] + echo '    file = "@TESTDIR@/debug.log"'
[ 0:00] + read -r v
[ 0:00] + sec=log
[ 0:00] + test log = log
[ 0:00] + echo '    indent = 1'
[ 0:00] + read -r v
[ 0:00] + sec=log
[ 0:00] + test log = log
[ 0:00] + echo '    level = 9'
[ 0:00] + read -r v
[ 0:00] + sec=log
[ 0:00] + test log = log
[ 0:00] + echo '    overwrite = 1'
[ 0:00] + read -r v
[ 0:00] + sec=log
[ 0:00] + test log = log
[ 0:00] + echo '    syslog = 0'
[ 0:00] + read -r v
[ 0:00] + sec=log
[ 0:00] + test log = log
[ 0:00] + echo '    verbose = 0'
[ 0:00] + read -r v
[ 0:00] + echo '}'
[ 0:00] + sed -e 's,^,## LVMCONF: ,' CONFIG
[ 0:00] ## LVMCONF: activation {
[ 0:00] ## LVMCONF:     checks = 1
[ 0:00] ## LVMCONF:     monitoring = 0
[ 0:00] ## LVMCONF:     polling_interval = 1
[ 0:00] ## LVMCONF:     raid_region_size = 512
[ 0:00] ## LVMCONF:     retry_deactivation = 1
[ 0:00] ## LVMCONF:     snapshot_autoextend_percent = 50
[ 0:00] ## LVMCONF:     snapshot_autoextend_threshold = 50
[ 0:00] ## LVMCONF:     udev_rules = 1
[ 0:00] ## LVMCONF:     udev_sync = 1
[ 0:00] ## LVMCONF:     verify_udev_operations = 1
[ 0:00] ## LVMCONF: }
[ 0:00] ## LVMCONF: allocation {
[ 0:00] ## LVMCONF:     wipe_signatures_when_zeroing_new_lvs = 0
[ 0:00] ## LVMCONF: }
[ 0:00] ## LVMCONF: backup {
[ 0:00] ## LVMCONF:     archive = 0
[ 0:00] ## LVMCONF:     backup = 0
[ 0:00] ## LVMCONF: }
[ 0:00] ## LVMCONF: devices {
[ 0:00] ## LVMCONF:     cache_dir = "@TESTDIR@/etc"
[ 0:00] ## LVMCONF:     default_data_alignment = 1
[ 0:00] ## LVMCONF:     dir = "@TESTDIR@/dev"
[ 0:00] ## LVMCONF:     filter = "a|.*|"
[ 0:00] ## LVMCONF:     global_filter = [ "a|@TESTDIR@/dev/mapper/@PREFIX at .*pv[0-9_]*$|", "r|.*|" ]
[ 0:00] ## LVMCONF:     md_component_detection = 0
[ 0:00] ## LVMCONF:     scan = "@TESTDIR@/dev"
[ 0:00] ## LVMCONF:     sysfs_scan = 1
[ 0:00] ## LVMCONF:     write_cache_state = 0
[ 0:00] ## LVMCONF: }
[ 0:00] ## LVMCONF: dmeventd {
[ 0:00] ## LVMCONF:     executable = "/root/lvm2/test/lib/dmeventd"
[ 0:00] ## LVMCONF: }
[ 0:00] ## LVMCONF: global {
[ 0:00] ## LVMCONF:     abort_on_internal_errors = 1
[ 0:00] ## LVMCONF:     cache_check_executable = "/usr/sbin/cache_check"
[ 0:00] ## LVMCONF:     cache_dump_executable = "/usr/sbin/cache_dump"
[ 0:00] ## LVMCONF:     cache_repair_executable = "/usr/sbin/cache_repair"
[ 0:00] ## LVMCONF:     detect_internal_vg_cache_corruption = 1
[ 0:00] ## LVMCONF:     fallback_to_local_locking = 0
[ 0:00] ## LVMCONF:     fsadm_executable = "/root/lvm2/test/lib/fsadm"
[ 0:00] ## LVMCONF:     library_dir = "@TESTDIR@/lib"
[ 0:00] ## LVMCONF:     locking_dir = "@TESTDIR@/var/lock/lvm"
[ 0:00] ## LVMCONF:     locking_type=1
[ 0:00] ## LVMCONF:     notify_dbus = 0
[ 0:00] ## LVMCONF:     si_unit_consistency = 1
[ 0:00] ## LVMCONF:     thin_check_executable = "/usr/sbin/thin_check"
[ 0:00] ## LVMCONF:     thin_dump_executable = "/usr/sbin/thin_dump"
[ 0:00] ## LVMCONF:     thin_repair_executable = "/usr/sbin/thin_repair"
[ 0:00] ## LVMCONF:     use_lvmetad = 1
[ 0:00] ## LVMCONF:     use_lvmlockd = 0
[ 0:00] ## LVMCONF:     use_lvmpolld = 0
[ 0:00] ## LVMCONF: }
[ 0:00] ## LVMCONF: log {
[ 0:00] ## LVMCONF:     activation = 1
[ 0:00] ## LVMCONF:     file = "@TESTDIR@/debug.log"
[ 0:00] ## LVMCONF:     indent = 1
[ 0:00] ## LVMCONF:     level = 9
[ 0:00] ## LVMCONF:     overwrite = 1
[ 0:00] ## LVMCONF:     syslog = 0
[ 0:00] ## LVMCONF:     verbose = 0
[ 0:00] ## LVMCONF: }
[ 0:00] + mv -f CONFIG @TESTDIR@/etc/lvm.conf
[ 0:00] + echo -n '## preparing lvmetad...'
[ 0:00] ## preparing lvmetad...+ echo 10845
[ 0:00] + lvmetad -f -s @TESTDIR@/lvmetad.socket -l all
[ 0:00] + for i in {1..100}
[ 0:00] + test 1 -eq 100
[ 0:00] + test -e @TESTDIR@/lvmetad.socket
[ 0:00] + echo -n .
[ 0:00] .+ sleep .1
[ 0:00] [D] creating @TESTDIR@/lvmetad.socket
[ 0:00] initialised state: vgid_to_metadata = 0x559dd2792f80
[ 0:00] + for i in {1..100}
[ 0:00] + test 2 -eq 100
[ 0:00] + test -e @TESTDIR@/lvmetad.socket
[ 0:00] + break
[ 0:00] + echo ok
[ 0:00] ok
[ 0:00] <======== Processing test: "lvmetad-dump.sh" ========>
[ 0:00] 
[ 0:00] aux prepare_vg 2
[ 0:00] #lvmetad-dump.sh:19+ aux prepare_vg 2
[ 0:00] + test -f DEVICES
[ 0:00] + test prepare_vg = dmsetup
[ 0:00] + prepare_vg 2
[ 0:00] + teardown_devs
[ 0:00] + teardown_udev_cookies
[ 0:00] + test 1 = 1
[ 0:00] + dmsetup udevcomplete_all -y 10
[ 0:00] + grep -v '^0 '
[ 0:00] + true
[ 0:00] + test '!' -f MD_DEV
[ 0:00] + test '!' -f DEVICES
[ 0:00] + test -f SCSI_DEBUG_DEV
[ 0:00] + test '!' -f LOOP
[ 0:00] + test '!' -f LOOPFILE
[ 0:00] + not diff LOOP BACKING_DEV
[ 0:00] + rm -f DEVICES LOOP
[ 0:00] + test 0 -eq 1
[ 0:00] + test -z LVMTEST
[ 0:00] + stray_loops=($(losetup -a | grep "$COMMON_PREFIX" | cut -d: -f1))
[ 0:00] ++ losetup -a
[ 0:00] ++ grep LVMTEST
[ 0:00] ++ cut -d: -f1
[ 0:00] + local stray_loops
[ 0:00] + test 0 -eq 0
[ 0:00] + prepare_devs 2
[ 0:00] + local n=2
[ 0:00] + local devsize=34
[ 0:00] + local pvname=pv
[ 0:00] + local shift=0
[ 0:00] + test -n ''
[ 0:00] + touch DEVICES
[ 0:00] + prepare_backing_dev 68
[ 0:00] + test -f BACKING_DEV
[ 0:00] + test -b ''
[ 0:00] + prepare_loop 68
[ 0:00] + local size=68
[ 0:00] + shift
[ 0:00] + local i
[ 0:00] + local slash
[ 0:00] + test -f LOOP
[ 0:00] + echo -n '## preparing loop device...'
[ 0:00] ## preparing loop device...+ test -f SCSI_DEBUG_DEV -a -f LOOP
[ 0:00] + test '!' -e LOOP
[ 0:00] + test -n @TESTDIR@/dev
[ 0:00] + for i in 0 1 2 3 4 5 6 7
[ 0:00] + test -e @TESTDIR@/dev/loop0
[ 0:00] + mknod @TESTDIR@/dev/loop0 b 7 0
[ 0:00] + for i in 0 1 2 3 4 5 6 7
[ 0:00] + test -e @TESTDIR@/dev/loop1
[ 0:00] + mknod @TESTDIR@/dev/loop1 b 7 1
[ 0:00] + for i in 0 1 2 3 4 5 6 7
[ 0:00] + test -e @TESTDIR@/dev/loop2
[ 0:00] + mknod @TESTDIR@/dev/loop2 b 7 2
[ 0:00] + for i in 0 1 2 3 4 5 6 7
[ 0:00] + test -e @TESTDIR@/dev/loop3
[ 0:00] + mknod @TESTDIR@/dev/loop3 b 7 3
[ 0:00] + for i in 0 1 2 3 4 5 6 7
[ 0:00] + test -e @TESTDIR@/dev/loop4
[ 0:00] + mknod @TESTDIR@/dev/loop4 b 7 4
[ 0:00] + for i in 0 1 2 3 4 5 6 7
[ 0:00] + test -e @TESTDIR@/dev/loop5
[ 0:00] + mknod @TESTDIR@/dev/loop5 b 7 5
[ 0:00] + for i in 0 1 2 3 4 5 6 7
[ 0:00] + test -e @TESTDIR@/dev/loop6
[ 0:00] + mknod @TESTDIR@/dev/loop6 b 7 6
[ 0:00] + for i in 0 1 2 3 4 5 6 7
[ 0:00] + test -e @TESTDIR@/dev/loop7
[ 0:00] + mknod @TESTDIR@/dev/loop7 b 7 7
[ 0:00] + echo -n .
[ 0:00] .+ local LOOPFILE=@TESTDIR@/test.img
[ 0:00] + rm -f @TESTDIR@/test.img
[ 0:00] + dd if=/dev/zero of=@TESTDIR@/test.img bs=1048576 count=0 seek=69
[ 0:00] ++ losetup -s -f @TESTDIR@/test.img
[ 0:00] + LOOP=
[ 0:00] ++ losetup -f
[ 0:00] + LOOP=/dev/loop0
[ 0:00] + losetup /dev/loop0 @TESTDIR@/test.img
[ 0:00] + :
[ 0:00] + test -n /dev/loop0
[ 0:00] + BACKING_DEV=/dev/loop0
[ 0:00] + echo /dev/loop0
[ 0:00] + echo /dev/loop0
[ 0:00] + echo 'ok (/dev/loop0)'
[ 0:00] ok (/dev/loop0)
[ 0:00] + not diff LOOP BACKING_DEV
[ 0:00] + shift=2048
[ 0:00] + echo -n '## preparing 2 devices...'
[ 0:00] ## preparing 2 devices...+ local size=69632
[ 0:00] + local count=0
[ 0:00] + rm -f CREATE_FAILED
[ 0:00] + init_udev_transaction
[ 0:00] + test 1 = 1
[ 0:00] + local cookie
[ 0:00] ++ dmsetup udevcreatecookie
[ 0:00] + cookie=0x0D4DD955
[ 0:00] + test -z 0x0D4DD955
[ 0:00] + export DM_UDEV_COOKIE=0x0D4DD955
[ 0:00] + DM_UDEV_COOKIE=0x0D4DD955
[ 0:00] ++ seq 1 2
[ 0:00] + for i in $(seq 1 "$n")
[ 0:00] + local name=@PREFIX at pv1
[ 0:00] + local dev=@TESTDIR@/dev/mapper/@PREFIX at pv1
[ 0:00] + DEVICES[$count]=@TESTDIR@/dev/mapper/@PREFIX at pv1
[ 0:00] + count=1
[ 0:00] + echo 0 69632 linear /dev/loop0 2048
[ 0:00] + test -f CREATE_FAILED
[ 0:00] + for i in $(seq 1 "$n")
[ 0:00] + local name=@PREFIX at pv2
[ 0:00] + local dev=@TESTDIR@/dev/mapper/@PREFIX at pv2
[ 0:00] + DEVICES[$count]=@TESTDIR@/dev/mapper/@PREFIX at pv2
[ 0:00] + count=2
[ 0:00] + echo 0 69632 linear /dev/loop0 71680
[ 0:00] + test -f CREATE_FAILED
[ 0:00] + wait
[ 0:00] + dmsetup create -u TEST- at PREFIX@pv2 @PREFIX at pv2 @PREFIX at pv2.table
[ 0:00] + dmsetup create -u TEST- at PREFIX@pv1 @PREFIX at pv1 @PREFIX at pv1.table
[ 0:00] + finish_udev_transaction
[ 0:00] + test 1 = 1
[ 0:00] + test -n 0x0D4DD955
[ 0:00] + dmsetup udevreleasecookie
[ 0:00] + unset DM_UDEV_COOKIE
[ 0:00] + test -f CREATE_FAILED -a -n ''
[ 0:00] + test -f LOOP
[ 0:00] + printf '%s\n' @TESTDIR@/dev/mapper/@PREFIX at pv1 @TESTDIR@/dev/mapper/@PREFIX at pv2
[ 0:00] + echo ok
[ 0:00] ok
[ 0:00] + test -e LOCAL_LVMETAD
[ 0:00] + for dev in "${DEVICES[@]}"
[ 0:00] + notify_lvmetad @TESTDIR@/dev/mapper/@PREFIX at pv1
[ 0:00] + test -e LOCAL_LVMETAD
[ 0:00] + LVM_LOG_FILE_EPOCH=
[ 0:00] + pvscan --cache @TESTDIR@/dev/mapper/@PREFIX at pv1
[ 0:00] <- request="hello"
[ 0:00] -> response = "OK"
[ 0:00] -> protocol = "lvmetad"
[ 0:00] -> version = 1
[ 0:00] -> 
[ 0:00] <- request="get_global_info"
[ 0:00] <- token="skip"
[ 0:00] <- pid=10897
[ 0:00] <- cmd="pvscan"
[ 0:00] 10897 global info flags none reason none token none update_pid 0
[ 0:00] -> response = "OK"
[ 0:00] -> global_invalid = 0
[ 0:00] -> global_disable = 0
[ 0:00] -> disable_reason = "none"
[ 0:00] -> daemon_pid = 10845
[ 0:00] -> token = "none"
[ 0:00] -> update_cmd = ""
[ 0:00] -> update_pid = 0
[ 0:00] -> update_begin = 0
[ 0:00] -> update_timeout = 0
[ 0:00] -> 
[ 0:00] <- request="token_update"
[ 0:00] <- token="update in progress"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10897
[ 0:00] <- cmd="pvscan"
[ 0:00] token_update begin 262010 timeout 10 pid 10897 cmd pvscan
[ 0:00] -> response = "OK"
[ 0:00] -> prev_token = ""
[ 0:00] -> update_pid = 10897
[ 0:00] -> 
[ 0:00] <- request="pv_clear_all"
[ 0:00] <- token="update in progress"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10897
[ 0:00] <- cmd="pvscan"
[ 0:00] pv_clear_all
[ 0:00] -> response = "OK"
[ 0:00] -> 
[ 0:00] <- request="pv_gone"
[ 0:00] <- device=65026
[ 0:00] <- token="update in progress"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10897
[ 0:00] <- cmd="pvscan"
[ 0:00] pv_gone device 65026 not found
[ 0:00] -> response = "unknown"
[ 0:00] -> reason = "device not in cache"
[ 0:00] -> 
[ 0:00] <- request="pv_gone"
[ 0:00] <- device=65027
[ 0:00] <- token="update in progress"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10897
[ 0:00] <- cmd="pvscan"
[ 0:00] pv_gone device 65027 not found
[ 0:00] -> response = "unknown"
[ 0:00] -> reason = "device not in cache"
[ 0:00] -> 
[ 0:00] <- request="token_update"
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10897
[ 0:00] <- cmd="pvscan"
[ 0:00] token_update end len 0 pid 10897 new token filter:1939810257
[ 0:00] -> response = "OK"
[ 0:00] -> prev_token = "update in progress"
[ 0:00] -> update_pid = 0
[ 0:00] -> 
[ 0:00] <- request="get_global_info"
[ 0:00] <- token="skip"
[ 0:00] <- pid=10897
[ 0:00] <- cmd="pvscan"
[ 0:00] 10897 global info flags none reason none token filter:1939810257 update_pid 0
[ 0:00] -> response = "OK"
[ 0:00] -> global_invalid = 0
[ 0:00] -> global_disable = 0
[ 0:00] -> disable_reason = "none"
[ 0:00] -> daemon_pid = 10845
[ 0:00] -> token = "filter:1939810257"
[ 0:00] -> update_cmd = ""
[ 0:00] -> update_pid = 0
[ 0:00] -> update_begin = 0
[ 0:00] -> update_timeout = 0
[ 0:00] -> 
[ 0:00] <- request="get_global_info"
[ 0:00] <- token="skip"
[ 0:00] <- pid=10897
[ 0:00] <- cmd="pvscan"
[ 0:00] 10897 global info flags none reason none token filter:1939810257 update_pid 0
[ 0:00] -> response = "OK"
[ 0:00] -> global_invalid = 0
[ 0:00] -> global_disable = 0
[ 0:00] -> disable_reason = "none"
[ 0:00] -> daemon_pid = 10845
[ 0:00] -> token = "filter:1939810257"
[ 0:00] -> update_cmd = ""
[ 0:00] -> update_pid = 0
[ 0:00] -> update_begin = 0
[ 0:00] -> update_timeout = 0
[ 0:00] -> 
[ 0:00] + rm -f debug.log
[ 0:00] + for dev in "${DEVICES[@]}"
[ 0:00] + notify_lvmetad @TESTDIR@/dev/mapper/@PREFIX at pv2
[ 0:00] + test -e LOCAL_LVMETAD
[ 0:00] + LVM_LOG_FILE_EPOCH=
[ 0:00] + pvscan --cache @TESTDIR@/dev/mapper/@PREFIX at pv2
[ 0:00] <- request="hello"
[ 0:00] -> response = "OK"
[ 0:00] -> protocol = "lvmetad"
[ 0:00] -> version = 1
[ 0:00] -> 
[ 0:00] <- request="get_global_info"
[ 0:00] <- token="skip"
[ 0:00] <- pid=10901
[ 0:00] <- cmd="pvscan"
[ 0:00] 10901 global info flags none reason none token filter:1939810257 update_pid 0
[ 0:00] -> response = "OK"
[ 0:00] -> global_invalid = 0
[ 0:00] -> global_disable = 0
[ 0:00] -> disable_reason = "none"
[ 0:00] -> daemon_pid = 10845
[ 0:00] -> token = "filter:1939810257"
[ 0:00] -> update_cmd = ""
[ 0:00] -> update_pid = 0
[ 0:00] -> update_begin = 0
[ 0:00] -> update_timeout = 0
[ 0:00] -> 
[ 0:00] <- request="get_global_info"
[ 0:00] <- token="skip"
[ 0:00] <- pid=10901
[ 0:00] <- cmd="pvscan"
[ 0:00] 10901 global info flags none reason none token filter:1939810257 update_pid 0
[ 0:00] -> response = "OK"
[ 0:00] -> global_invalid = 0
[ 0:00] -> global_disable = 0
[ 0:00] -> disable_reason = "none"
[ 0:00] -> daemon_pid = 10845
[ 0:00] -> token = "filter:1939810257"
[ 0:00] -> update_cmd = ""
[ 0:00] -> update_pid = 0
[ 0:00] -> update_begin = 0
[ 0:00] -> update_timeout = 0
[ 0:00] -> 
[ 0:00]   No PV label found on @TESTDIR@/dev/mapper/@PREFIX at pv2.
[ 0:00] <- request="pv_gone"
[ 0:00] <- device=65026
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10901
[ 0:00] <- cmd="pvscan"
[ 0:00] pv_gone device 65026 not found
[ 0:00] -> response = "unknown"
[ 0:00] -> reason = "device not in cache"
[ 0:00] -> 
[ 0:00] + rm -f debug.log
[ 0:00] + vgcreate -s 512K @PREFIX at vg @TESTDIR@/dev/mapper/@PREFIX at pv1 @TESTDIR@/dev/mapper/@PREFIX at pv2
[ 0:00] <- request="hello"
[ 0:00] -> response = "OK"
[ 0:00] -> protocol = "lvmetad"
[ 0:00] -> version = 1
[ 0:00] -> 
[ 0:00] <- request="get_global_info"
[ 0:00] <- token="skip"
[ 0:00] <- pid=10904
[ 0:00] <- cmd="vgcreate"
[ 0:00] 10904 global info flags none reason none token filter:1939810257 update_pid 0
[ 0:00] -> response = "OK"
[ 0:00] -> global_invalid = 0
[ 0:00] -> global_disable = 0
[ 0:00] -> disable_reason = "none"
[ 0:00] -> daemon_pid = 10845
[ 0:00] -> token = "filter:1939810257"
[ 0:00] -> update_cmd = ""
[ 0:00] -> update_pid = 0
[ 0:00] -> update_begin = 0
[ 0:00] -> update_timeout = 0
[ 0:00] -> 
[ 0:00] <- request="get_global_info"
[ 0:00] <- token="skip"
[ 0:00] <- pid=10904
[ 0:00] <- cmd="vgcreate"
[ 0:00] 10904 global info flags none reason none token filter:1939810257 update_pid 0
[ 0:00] -> response = "OK"
[ 0:00] -> global_invalid = 0
[ 0:00] -> global_disable = 0
[ 0:00] -> disable_reason = "none"
[ 0:00] -> daemon_pid = 10845
[ 0:00] -> token = "filter:1939810257"
[ 0:00] -> update_cmd = ""
[ 0:00] -> update_pid = 0
[ 0:00] -> update_begin = 0
[ 0:00] -> update_timeout = 0
[ 0:00] -> 
[ 0:00] <- request="pv_list"
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10904
[ 0:00] <- cmd="vgcreate"
[ 0:00] pv_list
[ 0:00] -> response="OK"
[ 0:00] -> physical_volumes {
[ 0:00] -> }
[ 0:00] -> 
[ 0:00] -> 
[ 0:00] -> 
[ 0:00] <- request="vg_lookup"
[ 0:00] <- name="@PREFIX at vg"
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10904
[ 0:00] <- cmd="vgcreate"
[ 0:00] vg_lookup vgid none name @PREFIX@vg needs lookup
[ 0:00] -> response = "unknown"
[ 0:00] -> reason = "VG not found"
[ 0:00] -> 
[ 0:00] <- request="vg_lookup"
[ 0:00] <- name="@PREFIX at vg"
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10904
[ 0:00] <- cmd="vgcreate"
[ 0:00] vg_lookup vgid none name @PREFIX@vg needs lookup
[ 0:00] -> response = "unknown"
[ 0:00] -> reason = "VG not found"
[ 0:00] -> 
[ 0:00] <- request="vg_lookup"
[ 0:00] <- name="@PREFIX at vg"
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10904
[ 0:00] <- cmd="vgcreate"
[ 0:00] vg_lookup vgid none name @PREFIX@vg needs lookup
[ 0:00] -> response = "unknown"
[ 0:00] -> reason = "VG not found"
[ 0:00] -> 
[ 0:00] <- request="vg_list"
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10904
[ 0:00] <- cmd="vgcreate"
[ 0:00] vg_list
[ 0:00] -> response="OK"
[ 0:00] -> volume_groups {
[ 0:00] -> }
[ 0:00] -> 
[ 0:00] -> 
[ 0:00] -> 
[ 0:00] <- request="pv_list"
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10904
[ 0:00] <- cmd="vgcreate"
[ 0:00] pv_list
[ 0:00] -> response="OK"
[ 0:00] -> physical_volumes {
[ 0:00] -> }
[ 0:00] -> 
[ 0:00] -> 
[ 0:00] -> 
[ 0:00] <- request="pv_found"
[ 0:00] <- pvmeta {
[ 0:00] <- 	device=65027
[ 0:00] <- 	dev_size=35651584
[ 0:00] <- 	format="lvm2"
[ 0:00] <- 	label_sector=1
[ 0:00] <- 	id="qixJkV-CSD1-CFsF-u9Fd-EwWL-cdgm-Uh2OO2"
[ 0:00] <- 	ext_version=2
[ 0:00] <- 	ext_flags=0
[ 0:00] <- 	mda0 {
[ 0:00] <- 		ignore=0
[ 0:00] <- 		start=4096
[ 0:00] <- 		size=1044480
[ 0:00] <- 		free_sectors=0
[ 0:00] <- 	}
[ 0:00] <- 	da0 {
[ 0:00] <- 		offset=1048576
[ 0:00] <- 		size=0
[ 0:00] <- 	}
[ 0:00] <- 	ba0 {
[ 0:00] <- 		offset=0
[ 0:00] <- 		size=0
[ 0:00] <- 	}
[ 0:00] <- }
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10904
[ 0:00] <- cmd="vgcreate"
[ 0:00] pv_found pvid qixJkV-CSD1-CFsF-u9Fd-EwWL-cdgm-Uh2OO2 on device 65027 is new
[ 0:00] pv_found new entry device_to_pvid 65027 to qixJkV-CSD1-CFsF-u9Fd-EwWL-cdgm-Uh2OO2
[ 0:00] pv_found pvid qixJkV-CSD1-CFsF-u9Fd-EwWL-cdgm-Uh2OO2 on 65027 not in VG 
[ 0:00] -> response = "OK"
[ 0:00] -> status = "orphan"
[ 0:00] -> changed = 1
[ 0:00] -> vgid = "#orphan"
[ 0:00] -> vgname = "#orphan"
[ 0:00] -> seqno_before = -1
[ 0:00] -> seqno_after = -1
[ 0:00] -> 
[ 0:00]   Physical volume "@TESTDIR@/dev/mapper/@PREFIX at pv1" successfully created.
[ 0:00] <- request="pv_found"
[ 0:00] <- pvmeta {
[ 0:00] <- 	device=65026
[ 0:00] <- 	dev_size=35651584
[ 0:00] <- 	format="lvm2"
[ 0:00] <- 	label_sector=1
[ 0:00] <- 	id="y01sNE-hCt0-fNSA-qz5v-kgcf-HfiJ-heL91S"
[ 0:00] <- 	ext_version=2
[ 0:00] <- 	ext_flags=0
[ 0:00] <- 	mda0 {
[ 0:00] <- 		ignore=0
[ 0:00] <- 		start=4096
[ 0:00] <- 		size=1044480
[ 0:00] <- 		free_sectors=0
[ 0:00] <- 	}
[ 0:00] <- 	da0 {
[ 0:00] <- 		offset=1048576
[ 0:00] <- 		size=0
[ 0:00] <- 	}
[ 0:00] <- 	ba0 {
[ 0:00] <- 		offset=0
[ 0:00] <- 		size=0
[ 0:00] <- 	}
[ 0:00] <- }
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10904
[ 0:00] <- cmd="vgcreate"
[ 0:00] pv_found pvid y01sNE-hCt0-fNSA-qz5v-kgcf-HfiJ-heL91S on device 65026 is new
[ 0:00] pv_found new entry device_to_pvid 65026 to y01sNE-hCt0-fNSA-qz5v-kgcf-HfiJ-heL91S
[ 0:00] pv_found pvid y01sNE-hCt0-fNSA-qz5v-kgcf-HfiJ-heL91S on 65026 not in VG 
[ 0:00] -> response = "OK"
[ 0:00] -> status = "orphan"
[ 0:00] -> changed = 1
[ 0:00] -> vgid = "#orphan"
[ 0:00] -> vgname = "#orphan"
[ 0:00] -> seqno_before = -1
[ 0:00] -> seqno_after = -1
[ 0:00] -> 
[ 0:00]   Physical volume "@TESTDIR@/dev/mapper/@PREFIX at pv2" successfully created.
[ 0:00] <- request="pv_found"
[ 0:00] <- pvmeta {
[ 0:00] <- 	device=65027
[ 0:00] <- 	dev_size=35651584
[ 0:00] <- 	format="lvm2"
[ 0:00] <- 	label_sector=1
[ 0:00] <- 	id="qixJkV-CSD1-CFsF-u9Fd-EwWL-cdgm-Uh2OO2"
[ 0:00] <- 	ext_version=2
[ 0:00] <- 	ext_flags=1
[ 0:00] <- 	mda0 {
[ 0:00] <- 		ignore=0
[ 0:00] <- 		start=4096
[ 0:00] <- 		size=1044480
[ 0:00] <- 		free_sectors=0
[ 0:00] <- 	}
[ 0:00] <- 	da0 {
[ 0:00] <- 		offset=1048576
[ 0:00] <- 		size=0
[ 0:00] <- 	}
[ 0:00] <- 	ba0 {
[ 0:00] <- 		offset=0
[ 0:00] <- 		size=0
[ 0:00] <- 	}
[ 0:00] <- }
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10904
[ 0:00] <- cmd="vgcreate"
[ 0:00] pv_found pvid qixJkV-CSD1-CFsF-u9Fd-EwWL-cdgm-Uh2OO2 on device 65027 matches existing
[ 0:00] pv_found pvid qixJkV-CSD1-CFsF-u9Fd-EwWL-cdgm-Uh2OO2 on 65027 not in VG 
[ 0:00] -> response = "OK"
[ 0:00] -> status = "orphan"
[ 0:00] -> changed = 1
[ 0:00] -> vgid = "#orphan"
[ 0:00] -> vgname = "#orphan"
[ 0:00] -> seqno_before = -1
[ 0:00] -> seqno_after = -1
[ 0:00] -> 
[ 0:00] <- request="pv_found"
[ 0:00] <- pvmeta {
[ 0:00] <- 	device=65026
[ 0:00] <- 	dev_size=35651584
[ 0:00] <- 	format="lvm2"
[ 0:00] <- 	label_sector=1
[ 0:00] <- 	id="y01sNE-hCt0-fNSA-qz5v-kgcf-HfiJ-heL91S"
[ 0:00] <- 	ext_version=2
[ 0:00] <- 	ext_flags=1
[ 0:00] <- 	mda0 {
[ 0:00] <- 		ignore=0
[ 0:00] <- 		start=4096
[ 0:00] <- 		size=1044480
[ 0:00] <- 		free_sectors=0
[ 0:00] <- 	}
[ 0:00] <- 	da0 {
[ 0:00] <- 		offset=1048576
[ 0:00] <- 		size=0
[ 0:00] <- 	}
[ 0:00] <- 	ba0 {
[ 0:00] <- 		offset=0
[ 0:00] <- 		size=0
[ 0:00] <- 	}
[ 0:00] <- }
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10904
[ 0:00] <- cmd="vgcreate"
[ 0:00] pv_found pvid y01sNE-hCt0-fNSA-qz5v-kgcf-HfiJ-heL91S on device 65026 matches existing
[ 0:00] pv_found pvid y01sNE-hCt0-fNSA-qz5v-kgcf-HfiJ-heL91S on 65026 not in VG 
[ 0:00] -> response = "OK"
[ 0:00] -> status = "orphan"
[ 0:00] -> changed = 1
[ 0:00] -> vgid = "#orphan"
[ 0:00] -> vgname = "#orphan"
[ 0:00] -> seqno_before = -1
[ 0:00] -> seqno_after = -1
[ 0:00] -> 
[ 0:00] <- request="set_vg_info"
[ 0:00] <- name="@PREFIX@vg"
[ 0:00] <- uuid="wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg"
[ 0:00] <- version=1
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10904
[ 0:00] <- cmd="vgcreate"
[ 0:00] -> response = "OK"
[ 0:00] -> 
[ 0:00] <- request="vg_update"
[ 0:00] <- vgname="@PREFIX at vg"
[ 0:00] <- metadata {
[ 0:00] <- 	id="wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg"
[ 0:00] <- 	seqno=1
[ 0:00] <- 	format="lvm2"
[ 0:00] <- 	status=["RESIZEABLE","READ","WRITE"]
[ 0:00] <- 	flags=[]
[ 0:00] <- 	extent_size=1024
[ 0:00] <- 	max_lv=0
[ 0:00] <- 	max_pv=0
[ 0:00] <- 	metadata_copies=0
[ 0:00] <- 	physical_volumes {
[ 0:00] <- 		pv0 {
[ 0:00] <- 			id="qixJkV-CSD1-CFsF-u9Fd-EwWL-cdgm-Uh2OO2"
[ 0:00] <- 			device="@TESTDIR@/dev/mapper/@PREFIX at pv1"
[ 0:00] <- 			status="ALLOCATABLE"
[ 0:00] <- 			flags=[]
[ 0:00] <- 			dev_size=69632
[ 0:00] <- 			pe_start=2048
[ 0:00] <- 			pe_count=66
[ 0:00] <- 		}
[ 0:00] <- 		pv1 {
[ 0:00] <- 			id="y01sNE-hCt0-fNSA-qz5v-kgcf-HfiJ-heL91S"
[ 0:00] <- 			device="@TESTDIR@/dev/mapper/@PREFIX at pv2"
[ 0:00] <- 			status="ALLOCATABLE"
[ 0:00] <- 			flags=[]
[ 0:00] <- 			dev_size=69632
[ 0:00] <- 			pe_start=2048
[ 0:00] <- 			pe_count=66
[ 0:00] <- 		}
[ 0:00] <- 	}
[ 0:00] <- }
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10904
[ 0:00] <- cmd="vgcreate"
[ 0:00] vg_update vgid wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg name @PREFIX at vg
[ 0:00] update_metadata begin arg_vgid wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg arg_name @PREFIX at vg pvid none
[ 0:00] update_metadata new name @PREFIX at vg and new vgid wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg
[ 0:00] update_metadata_add_new for @PREFIX at vg wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg
[ 0:00] moving PV qixJkV-CSD1-CFsF-u9Fd-EwWL-cdgm-Uh2OO2 to VG wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg
[ 0:00] moving PV y01sNE-hCt0-fNSA-qz5v-kgcf-HfiJ-heL91S to VG wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg
[ 0:00] update_metadata_add_new is done for @PREFIX@vg wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg
[ 0:00] -> response = "OK"
[ 0:00] -> 
[ 0:00] <- request="pv_found"
[ 0:00] <- pvmeta {
[ 0:00] <- 	device=65027
[ 0:00] <- 	dev_size=35651584
[ 0:00] <- 	format="lvm2"
[ 0:00] <- 	label_sector=1
[ 0:00] <- 	id="qixJkV-CSD1-CFsF-u9Fd-EwWL-cdgm-Uh2OO2"
[ 0:00] <- 	ext_version=2
[ 0:00] <- 	ext_flags=1
[ 0:00] <- 	mda0 {
[ 0:00] <- 		ignore=0
[ 0:00] <- 		start=4096
[ 0:00] <- 		size=1044480
[ 0:00] <- 		free_sectors=0
[ 0:00] <- 	}
[ 0:00] <- 	da0 {
[ 0:00] <- 		offset=1048576
[ 0:00] <- 		size=0
[ 0:00] <- 	}
[ 0:00] <- 	ba0 {
[ 0:00] <- 		offset=0
[ 0:00] <- 		size=0
[ 0:00] <- 	}
[ 0:00] <- }
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10904
[ 0:00] <- cmd="vgcreate"
[ 0:00] pv_found pvid qixJkV-CSD1-CFsF-u9Fd-EwWL-cdgm-Uh2OO2 on device 65027 matches existing
[ 0:00] -> response = "OK"
[ 0:00] -> status = "complete"
[ 0:00] -> changed = 0
[ 0:00] -> vgid = "wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg"
[ 0:00] -> vgname = "@PREFIX at vg"
[ 0:00] -> seqno_before = -1
[ 0:00] -> seqno_after = 1
[ 0:00] -> 
[ 0:00] <- request="pv_found"
[ 0:00] <- pvmeta {
[ 0:00] <- 	device=65026
[ 0:00] <- 	dev_size=35651584
[ 0:00] <- 	format="lvm2"
[ 0:00] <- 	label_sector=1
[ 0:00] <- 	id="y01sNE-hCt0-fNSA-qz5v-kgcf-HfiJ-heL91S"
[ 0:00] <- 	ext_version=2
[ 0:00] <- 	ext_flags=1
[ 0:00] <- 	mda0 {
[ 0:00] <- 		ignore=0
[ 0:00] <- 		start=4096
[ 0:00] <- 		size=1044480
[ 0:00] <- 		free_sectors=0
[ 0:00] <- 	}
[ 0:00] <- 	da0 {
[ 0:00] <- 		offset=1048576
[ 0:00] <- 		size=0
[ 0:00] <- 	}
[ 0:00] <- 	ba0 {
[ 0:00] <- 		offset=0
[ 0:00] <- 		size=0
[ 0:00] <- 	}
[ 0:00] <- }
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10904
[ 0:00] <- cmd="vgcreate"
[ 0:00] pv_found pvid y01sNE-hCt0-fNSA-qz5v-kgcf-HfiJ-heL91S on device 65026 matches existing
[ 0:00] -> response = "OK"
[ 0:00] -> status = "complete"
[ 0:00] -> changed = 0
[ 0:00] -> vgid = "wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg"
[ 0:00] -> vgname = "@PREFIX at vg"
[ 0:00] -> seqno_before = -1
[ 0:00] -> seqno_after = 1
[ 0:00] -> 
[ 0:00]   WARNING: This metadata update is NOT backed up.
[ 0:00]   Volume group "@PREFIX at vg" successfully created
[ 0:00] lvcreate -n bar -l 1 $vg
[ 0:00] #lvmetad-dump.sh:20+ lvcreate -n bar -l 1 @PREFIX at vg
[ 0:00] <- request="hello"
[ 0:00] -> response = "OK"
[ 0:00] -> protocol = "lvmetad"
[ 0:00] -> version = 1
[ 0:00] -> 
[ 0:00] <- request="get_global_info"
[ 0:00] <- token="skip"
[ 0:00] <- pid=10906
[ 0:00] <- cmd="lvcreate"
[ 0:00] 10906 global info flags none reason none token filter:1939810257 update_pid 0
[ 0:00] -> response = "OK"
[ 0:00] -> global_invalid = 0
[ 0:00] -> global_disable = 0
[ 0:00] -> disable_reason = "none"
[ 0:00] -> daemon_pid = 10845
[ 0:00] -> token = "filter:1939810257"
[ 0:00] -> update_cmd = ""
[ 0:00] -> update_pid = 0
[ 0:00] -> update_begin = 0
[ 0:00] -> update_timeout = 0
[ 0:00] -> 
[ 0:00] <- request="get_global_info"
[ 0:00] <- token="skip"
[ 0:00] <- pid=10906
[ 0:00] <- cmd="lvcreate"
[ 0:00] 10906 global info flags none reason none token filter:1939810257 update_pid 0
[ 0:00] -> response = "OK"
[ 0:00] -> global_invalid = 0
[ 0:00] -> global_disable = 0
[ 0:00] -> disable_reason = "none"
[ 0:00] -> daemon_pid = 10845
[ 0:00] -> token = "filter:1939810257"
[ 0:00] -> update_cmd = ""
[ 0:00] -> update_pid = 0
[ 0:00] -> update_begin = 0
[ 0:00] -> update_timeout = 0
[ 0:00] -> 
[ 0:00] <- request="vg_list"
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10906
[ 0:00] <- cmd="lvcreate"
[ 0:00] vg_list
[ 0:00] -> response="OK"
[ 0:00] -> volume_groups {
[ 0:00] -> 	wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg {
[ 0:00] -> 		name="@PREFIX at vg"
[ 0:00] -> 	}
[ 0:00] -> }
[ 0:00] -> 
[ 0:00] -> 
[ 0:00] -> 
[ 0:00] <- request="vg_lookup"
[ 0:00] <- uuid="wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg"
[ 0:00] <- name="@PREFIX at vg"
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10906
[ 0:00] <- cmd="lvcreate"
[ 0:00] vg_lookup vgid wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg name @PREFIX@vg
[ 0:00] -> response="OK"
[ 0:00] -> name="@PREFIX at vg"
[ 0:00] -> metadata {
[ 0:00] -> 	id="wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg"
[ 0:00] -> 	seqno=1
[ 0:00] -> 	format="lvm2"
[ 0:00] -> 	status=["RESIZEABLE","READ","WRITE"]
[ 0:00] -> 	flags=[]
[ 0:00] -> 	extent_size=1024
[ 0:00] -> 	max_lv=0
[ 0:00] -> 	max_pv=0
[ 0:00] -> 	metadata_copies=0
[ 0:00] -> 	physical_volumes {
[ 0:00] -> 		pv0 {
[ 0:00] -> 			device=65027
[ 0:00] -> 			format="lvm2"
[ 0:00] -> 			label_sector=1
[ 0:00] -> 			ext_version=2
[ 0:00] -> 			ext_flags=1
[ 0:00] -> 			mda0 {
[ 0:00] -> 				ignore=0
[ 0:00] -> 				start=4096
[ 0:00] -> 				size=1044480
[ 0:00] -> 				free_sectors=0
[ 0:00] -> 			}
[ 0:00] -> 			da0 {
[ 0:00] -> 				offset=1048576
[ 0:00] -> 				size=0
[ 0:00] -> 			}
[ 0:00] -> 			ba0 {
[ 0:00] -> 				offset=0
[ 0:00] -> 				size=0
[ 0:00] -> 			}
[ 0:00] -> 			id="qixJkV-CSD1-CFsF-u9Fd-EwWL-cdgm-Uh2OO2"
[ 0:00] -> 			status="ALLOCATABLE"
[ 0:00] -> 			flags=[]
[ 0:00] -> 			dev_size=69632
[ 0:00] -> 			pe_start=2048
[ 0:00] -> 			pe_count=66
[ 0:00] -> 		}
[ 0:00] -> 		pv1 {
[ 0:00] -> 			device=65026
[ 0:00] -> 			format="lvm2"
[ 0:00] -> 			label_sector=1
[ 0:00] -> 			ext_version=2
[ 0:00] -> 			ext_flags=1
[ 0:00] -> 			mda0 {
[ 0:00] -> 				ignore=0
[ 0:00] -> 				start=4096
[ 0:00] -> 				size=1044480
[ 0:00] -> 				free_sectors=0
[ 0:00] -> 			}
[ 0:00] -> 			da0 {
[ 0:00] -> 				offset=1048576
[ 0:00] -> 				size=0
[ 0:00] -> 			}
[ 0:00] -> 			ba0 {
[ 0:00] -> 				offset=0
[ 0:00] -> 				size=0
[ 0:00] -> 			}
[ 0:00] -> 			id="y01sNE-hCt0-fNSA-qz5v-kgcf-HfiJ-heL91S"
[ 0:00] -> 			status="ALLOCATABLE"
[ 0:00] -> 			flags=[]
[ 0:00] -> 			dev_size=69632
[ 0:00] -> 			pe_start=2048
[ 0:00] -> 			pe_count=66
[ 0:00] -> 		}
[ 0:00] -> 	}
[ 0:00] -> }
[ 0:00] -> 
[ 0:00] -> 
[ 0:00] -> 
[ 0:00] <- request="vg_clear_outdated_pvs"
[ 0:00] <- vgid="wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg"
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10906
[ 0:00] <- cmd="lvcreate"
[ 0:00] vg_clear_outdated_pvs vgid wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg
[ 0:00] -> response = "OK"
[ 0:00] -> 
[ 0:00] <- request="set_vg_info"
[ 0:00] <- name="@PREFIX@vg"
[ 0:00] <- uuid="wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg"
[ 0:00] <- version=2
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10906
[ 0:00] <- cmd="lvcreate"
[ 0:00] set info VG name none uuid wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg cache_version 1 new_version 2
[ 0:00] -> response = "OK"
[ 0:00] -> 
[ 0:00]   WARNING: This metadata update is NOT backed up.
[ 0:00]   The link @TESTDIR@/dev/@PREFIX at vg/bar should have been created by udev but it was not found. Falling back to direct link creation.
[ 0:00]   @TESTDIR@/dev/mapper/@PREFIX at vg-bar not set up by udev: Falling back to direct node creation.
[ 0:00]   Logical volume "bar" created.
[ 0:00] <- request="vg_update"
[ 0:00] <- vgname="@PREFIX at vg"
[ 0:00] <- metadata {
[ 0:00] <- 	id="wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg"
[ 0:00] <- 	seqno=2
[ 0:00] <- 	format="lvm2"
[ 0:00] <- 	status=["RESIZEABLE","READ","WRITE"]
[ 0:00] <- 	flags=[]
[ 0:00] <- 	extent_size=1024
[ 0:00] <- 	max_lv=0
[ 0:00] <- 	max_pv=0
[ 0:00] <- 	metadata_copies=0
[ 0:00] <- 	physical_volumes {
[ 0:00] <- 		pv0 {
[ 0:00] <- 			id="qixJkV-CSD1-CFsF-u9Fd-EwWL-cdgm-Uh2OO2"
[ 0:00] <- 			device="@TESTDIR@/dev/mapper/@PREFIX at pv1"
[ 0:00] <- 			status="ALLOCATABLE"
[ 0:00] <- 			flags=[]
[ 0:00] <- 			dev_size=69632
[ 0:00] <- 			pe_start=2048
[ 0:00] <- 			pe_count=66
[ 0:00] <- 		}
[ 0:00] <- 		pv1 {
[ 0:00] <- 			id="y01sNE-hCt0-fNSA-qz5v-kgcf-HfiJ-heL91S"
[ 0:00] <- 			device="@TESTDIR@/dev/mapper/@PREFIX at pv2"
[ 0:00] <- 			status="ALLOCATABLE"
[ 0:00] <- 			flags=[]
[ 0:00] <- 			dev_size=69632
[ 0:00] <- 			pe_start=2048
[ 0:00] <- 			pe_count=66
[ 0:00] <- 		}
[ 0:00] <- 	}
[ 0:00] <- 	logical_volumes {
[ 0:00] <- 		bar {
[ 0:00] <- 			id="ji8FVC-6cRg-3fK2-AVLQ-DVHx-tU4e-Qg1aZd"
[ 0:00] <- 			status=["READ","WRITE","VISIBLE"]
[ 0:00] <- 			flags=[]
[ 0:00] <- 			creation_time=1513263803
[ 0:00] <- 			creation_host="tw1"
[ 0:00] <- 			segment_count=1
[ 0:00] <- 			segment1 {
[ 0:00] <- 				start_extent=0
[ 0:00] <- 				extent_count=1
[ 0:00] <- 				type="striped"
[ 0:00] <- 				stripe_count=1
[ 0:00] <- 				stripes=["pv0",0]
[ 0:00] <- 			}
[ 0:00] <- 		}
[ 0:00] <- 	}
[ 0:00] <- }
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10906
[ 0:00] <- cmd="lvcreate"
[ 0:00] vg_update vgid wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg name @PREFIX at vg
[ 0:00] update_metadata begin arg_vgid wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg arg_name @PREFIX at vg pvid none
[ 0:00] update_metadata existing vgid wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg and existing name @PREFIX at vg
[ 0:00] update_metadata for @PREFIX at vg wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg from 1 to 2
[ 0:00] moving PV qixJkV-CSD1-CFsF-u9Fd-EwWL-cdgm-Uh2OO2 to VG #orphan
[ 0:00] moving PV y01sNE-hCt0-fNSA-qz5v-kgcf-HfiJ-heL91S to VG #orphan
[ 0:00] moving PV qixJkV-CSD1-CFsF-u9Fd-EwWL-cdgm-Uh2OO2 to VG wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg
[ 0:00] moving PV y01sNE-hCt0-fNSA-qz5v-kgcf-HfiJ-heL91S to VG wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg
[ 0:00] update_metadata is done for @PREFIX@vg wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg
[ 0:00] -> response = "OK"
[ 0:00] -> 
[ 0:00] <- request="pv_found"
[ 0:00] <- pvmeta {
[ 0:00] <- 	device=65027
[ 0:00] <- 	dev_size=69632
[ 0:00] <- 	format="lvm2"
[ 0:00] <- 	label_sector=1
[ 0:00] <- 	id="qixJkV-CSD1-CFsF-u9Fd-EwWL-cdgm-Uh2OO2"
[ 0:00] <- 	ext_version=2
[ 0:00] <- 	ext_flags=1
[ 0:00] <- 	mda0 {
[ 0:00] <- 		ignore=0
[ 0:00] <- 		start=4096
[ 0:00] <- 		size=1044480
[ 0:00] <- 		free_sectors=0
[ 0:00] <- 	}
[ 0:00] <- 	da0 {
[ 0:00] <- 		offset=1048576
[ 0:00] <- 		size=0
[ 0:00] <- 	}
[ 0:00] <- 	ba0 {
[ 0:00] <- 		offset=0
[ 0:00] <- 		size=0
[ 0:00] <- 	}
[ 0:00] <- }
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10906
[ 0:00] <- cmd="lvcreate"
[ 0:00] pv_found pvid qixJkV-CSD1-CFsF-u9Fd-EwWL-cdgm-Uh2OO2 on device 65027 matches existing
[ 0:00] -> response = "OK"
[ 0:00] -> status = "complete"
[ 0:00] -> changed = 1
[ 0:00] -> vgid = "wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg"
[ 0:00] -> vgname = "@PREFIX at vg"
[ 0:00] -> seqno_before = -1
[ 0:00] -> seqno_after = 2
[ 0:00] -> 
[ 0:00] <- request="pv_found"
[ 0:00] <- pvmeta {
[ 0:00] <- 	device=65026
[ 0:00] <- 	dev_size=69632
[ 0:00] <- 	format="lvm2"
[ 0:00] <- 	label_sector=1
[ 0:00] <- 	id="y01sNE-hCt0-fNSA-qz5v-kgcf-HfiJ-heL91S"
[ 0:00] <- 	ext_version=2
[ 0:00] <- 	ext_flags=1
[ 0:00] <- 	mda0 {
[ 0:00] <- 		ignore=0
[ 0:00] <- 		start=4096
[ 0:00] <- 		size=1044480
[ 0:00] <- 		free_sectors=0
[ 0:00] <- 	}
[ 0:00] <- 	da0 {
[ 0:00] <- 		offset=1048576
[ 0:00] <- 		size=0
[ 0:00] <- 	}
[ 0:00] <- 	ba0 {
[ 0:00] <- 		offset=0
[ 0:00] <- 		size=0
[ 0:00] <- 	}
[ 0:00] <- }
[ 0:00] <- token="filter:1939810257"
[ 0:00] <- update_timeout=10
[ 0:00] <- pid=10906
[ 0:00] <- cmd="lvcreate"
[ 0:00] pv_found pvid y01sNE-hCt0-fNSA-qz5v-kgcf-HfiJ-heL91S on device 65026 matches existing
[ 0:00] -> response = "OK"
[ 0:00] -> status = "complete"
[ 0:00] -> changed = 1
[ 0:00] -> vgid = "wJ86F1-N8ce-oPzu-jLaG-YJ0i-45QT-HJqycg"
[ 0:00] -> vgname = "@PREFIX at vg"
[ 0:00] -> seqno_before = -1
[ 0:00] -> seqno_after = 2
[ 0:00] -> 
[ 0:00] 
[ 0:00] aux lvmetad_dump | tee lvmetad.txt
[ 0:00] #lvmetad-dump.sh:22+ aux lvmetad_dump
[ 0:00] #lvmetad-dump.sh:22+ tee lvmetad.txt
[ 0:00] + test -f DEVICES
[ 0:00] + devs='@TESTDIR@/dev/mapper/@PREFIX at pv1
[ 0:00] @TESTDIR@/dev/mapper/@PREFIX at pv2'
[ 0:00] + test lvmetad_dump = dmsetup
[ 0:00] + lvmetad_dump
[ 0:00] + echo 'request="dump"'
[ 0:00] + echo '##'
[ 0:00] + lvmetad_talk
[ 0:00] + local use=nc
[ 0:00] + type -p socat
[ 0:00] + echo
[ 0:00] + not nc -U @TESTDIR@/lvmetad.socket
[ 0:00] aux teardown
[ 0:28] ##lvmetad-dump.sh:1+ aux teardown
[ 0:28] + test -f DEVICES
[ 0:28] + devs='@TESTDIR@/dev/mapper/@PREFIX at pv1
[ 0:28] @TESTDIR@/dev/mapper/@PREFIX at pv2'
[ 0:28] + test teardown = dmsetup
[ 0:28] + teardown
[ 0:28] + local TEST_LEAKED_DEVICES=
[ 0:28] + echo -n '## teardown...'
[ 0:28] ## teardown...+ unset LVM_LOG_FILE_EPOCH
[ 0:28] + test -f TESTNAME
[ 0:28] + test '!' -f SKIP_THIS_TEST
[ 0:28] ++ dmsetup table
[ 0:28] ++ grep @PREFIX@
[ 0:28] ++ grep -v @PREFIX at pv
[ 0:28] + TEST_LEAKED_DEVICES='@PREFIX at vg-bar: 0 1024 linear 254:3 2048'
[ 0:28] + kill_tagged_processes
[ 0:28] + local pid
[ 0:28] + local wait
[ 0:28] + pids=()
[ 0:28] + local pids
[ 0:28] + read -r pid wait
[ 0:28] ++ print_procs_by_tag_
[ 0:28] ++ ps -o pid,args ehax
[ 0:28] ++ grep -weLVM_TEST_TAG=kill_me_ at PREFIX@
[ 0:28] ++ true
[ 0:28] + test 0 -eq 0
[ 0:28] + return
[ 0:28] + test -n ''
[ 0:28] + kill_sleep_kill_ LOCAL_LVMETAD 0
[ 0:28] + local pidfile=LOCAL_LVMETAD
[ 0:28] + local slow=0
[ 0:28] + test -s LOCAL_LVMETAD
[ 0:28] + pid=10845
[ 0:28] + rm -f LOCAL_LVMETAD
[ 0:28] + kill -TERM 10845
[ 0:28] + test 0 -eq 0
[ 0:28] + sleep .1
[ 0:28] I: lvmetad waiting for client threads to finish
[ 0:28] fini
[ 0:28] I: lvmetad shutting down
[ 0:28] + kill -KILL 10845
[ 0:29] + true
[ 0:29] + local wait=0
[ 0:29] + ps 10845
[ 0:29] + dm_table
[ 0:29] + should dmsetup table
[ 0:29] + not grep -E -q '@PREFIX at vg|@PREFIX at vg1|@PREFIX at vg2|@PREFIX at vg3|@PREFIX at vg4'
[ 0:29] ++ test -s LOCAL_DMEVENTD
[ 0:29] ++ echo '--config activation{monitoring=0}'
[ 0:29] + cfg='--config activation{monitoring=0}'
[ 0:29] + dm_info suspended,name
[ 0:29] + should dmsetup info --noheadings -c -o suspended,name
[ 0:29] + grep -q '^Suspended:.*@PREFIX@'
[ 0:29] + vgremove -ff '--config activation{monitoring=0}' @PREFIX at vg @PREFIX at vg1 @PREFIX at vg2 @PREFIX at vg3 @PREFIX at vg4
[ 0:29] + rm -f debug.log strace.log
[ 0:29] + kill_sleep_kill_ LOCAL_LVMDBUSD 0
[ 0:29] + local pidfile=LOCAL_LVMDBUSD
[ 0:29] + local slow=0
[ 0:29] + test -s LOCAL_LVMDBUSD
[ 0:29] + echo -n .
[ 0:29] .+ kill_sleep_kill_ LOCAL_LVMPOLLD 0
[ 0:29] + local pidfile=LOCAL_LVMPOLLD
[ 0:29] + local slow=0
[ 0:29] + test -s LOCAL_LVMPOLLD
[ 0:29] + echo -n .
[ 0:29] .+ kill_sleep_kill_ LOCAL_CLVMD 0
[ 0:29] + local pidfile=LOCAL_CLVMD
[ 0:29] + local slow=0
[ 0:29] + test -s LOCAL_CLVMD
[ 0:29] + echo -n .
[ 0:29] .+ kill_sleep_kill_ LOCAL_DMEVENTD 0
[ 0:29] + local pidfile=LOCAL_DMEVENTD
[ 0:29] + local slow=0
[ 0:29] + test -s LOCAL_DMEVENTD
[ 0:29] + echo -n .
[ 0:29] .+ test -d @TESTDIR@/dev/mapper
[ 0:29] + teardown_devs
[ 0:29] + teardown_udev_cookies
[ 0:29] + test 1 = 1
[ 0:29] + grep -v '^0 '
[ 0:29] + dmsetup udevcomplete_all -y 10
[ 0:29] + true
[ 0:29] + test '!' -f MD_DEV
[ 0:29] + test '!' -f DEVICES
[ 0:29] + teardown_devs_prefixed @PREFIX@
[ 0:29] + local prefix=@PREFIX@
[ 0:29] + local stray=0
[ 0:29] + local 'IFS=
[ 0:29] '
[ 0:29] + local dm
[ 0:29] + rm -rf '@TESTDIR@/dev/@PREFIX@*'
[ 0:29] ++ dm_info suspended,name
[ 0:29] ++ grep '^Suspended:.*@PREFIX@'
[ 0:29] ++ should dmsetup info --noheadings -c -o suspended,name
[ 0:29] + wait
[ 0:29] + mounts=($(grep "$prefix" /proc/mounts | cut -d' ' -f1))
[ 0:29] ++ grep @PREFIX@ /proc/mounts
[ 0:29] ++ cut '-d ' -f1
[ 0:29] + local mounts
[ 0:29] + test 0 -gt 0
[ 0:29] + rm -f REMOVE_FAILED
[ 0:29] + for i in 0 1
[ 0:29] + local num_remaining_devs=999999
[ 0:29] + local num_devs=0
[ 0:29] + test 0 = 1
[ 0:29] + :
[ 0:29] + local cnt
[ 0:29] + local sortby=name
[ 0:29] + local need_udev_wait=0
[ 0:29] + test 0 = 0
[ 0:29] + dm_info name,open --separator ' ' --sort open,name
[ 0:29] + should dmsetup info --noheadings -c -o name,open --separator ' ' --sort open,name
[ 0:29] + grep @PREFIX@
[ 0:29] ++ wc -l
[ 0:29] + num_devs=3
[ 0:29] + test 3 -lt 999999
[ 0:29] + test 0 = 0
[ 0:29] + IFS=' '
[ 0:29] + read -r dm cnt
[ 0:29] + test 0 = 0
[ 0:29] + test 0 -eq 0
[ 0:29] + need_udev_wait=1
[ 0:29] + IFS=' '
[ 0:29] + read -r dm cnt
[ 0:29] + dmsetup remove @PREFIX at pv2
[ 0:29] + test 0 = 0
[ 0:29] + test 0 -eq 0
[ 0:29] + need_udev_wait=1
[ 0:29] + IFS=' '
[ 0:29] + read -r dm cnt
[ 0:29] + dmsetup remove @PREFIX at vg-bar
[ 0:29] + test 0 = 0
[ 0:29] + test 1 -eq 0
[ 0:29] + break
[ 0:29] + test 1 -eq 1
[ 0:29] + udev_wait
[ 0:29] + pgrep udev
[ 0:29] + which udevadm
[ 0:29] + test -n ''
[ 0:29] + udevadm settle --timeout=15
[ 0:29] + wait
[ 0:29] + num_remaining_devs=3
[ 0:29] + :
[ 0:29] + local cnt
[ 0:29] + local sortby=name
[ 0:29] + local need_udev_wait=0
[ 0:29] + test 0 = 0
[ 0:29] + grep @PREFIX@
[ 0:29] + dm_info name,open --separator ' ' --sort open,name
[ 0:29] + should dmsetup info --noheadings -c -o name,open --separator ' ' --sort open,name
[ 0:29] ++ wc -l
[ 0:29] + num_devs=1
[ 0:29] + test 1 -lt 3
[ 0:29] + test 0 = 0
[ 0:29] + IFS=' '
[ 0:29] + read -r dm cnt
[ 0:29] + test 0 = 0
[ 0:29] + test 0 -eq 0
[ 0:29] + need_udev_wait=1
[ 0:29] + IFS=' '
[ 0:29] + read -r dm cnt
[ 0:29] + dmsetup remove @PREFIX at pv1
[ 0:29] + test 1 -eq 1
[ 0:29] + udev_wait
[ 0:29] + pgrep udev
[ 0:29] + which udevadm
[ 0:29] + test -n ''
[ 0:29] + udevadm settle --timeout=15
[ 0:29] + wait
[ 0:29] + num_remaining_devs=1
[ 0:29] + :
[ 0:29] + local cnt
[ 0:29] + local sortby=name
[ 0:29] + local need_udev_wait=0
[ 0:29] + test 0 = 0
[ 0:29] + dm_info name,open --separator ' ' --sort open,name
[ 0:29] + should dmsetup info --noheadings -c -o name,open --separator ' ' --sort open,name
[ 0:29] + grep @PREFIX@
[ 0:29] + break 2
[ 0:29] + test -f SCSI_DEBUG_DEV
[ 0:29] + test '!' -f LOOP
[ 0:29] + losetup -d /dev/loop0
[ 0:29] + test '!' -f LOOPFILE
[ 0:29] + not diff LOOP BACKING_DEV
[ 0:29] + rm -f BACKING_DEV
[ 0:29] + rm -f DEVICES LOOP
[ 0:29] + test 0 -eq 1
[ 0:29] + test -z LVMTEST
[ 0:29] + stray_loops=($(losetup -a | grep "$COMMON_PREFIX" | cut -d: -f1))
[ 0:29] ++ losetup -a
[ 0:29] ++ grep LVMTEST
[ 0:29] ++ cut -d: -f1
[ 0:29] + local stray_loops
[ 0:29] + test 0 -eq 0
[ 0:29] + echo -n .
[ 0:29] .+ test -z '@PREFIX at vg-bar: 0 1024 linear 254:3 2048'
[ 0:29] + echo '## unexpected devices left dm table:'
[ 0:29] ## unexpected devices left dm table:
[ 0:29] + echo '@PREFIX at vg-bar: 0 1024 linear 254:3 2048'
[ 0:29] @PREFIX at vg-bar: 0 1024 linear 254:3 2048
[ 0:29] + return 1
[ 0:29] set +vx; STACKTRACE; set -vx
[ 0:29] ###lvmetad-dump.sh:1+ set +vx
[ 0:29] ## - /root/lvm2/test/shell/lvmetad-dump.sh:1
[ 0:29] ## 1 STACKTRACE() called from /root/lvm2/test/shell/lvmetad-dump.sh:1
[ 0:29] <======== Script file "lvmetad-dump.sh" ========>
[ 0:29] ## Line: 1 	 #!/usr/bin/env bash
[ 0:29] ## Line: 2 	 
[ 0:29] ## Line: 3 	 # Copyright (C) 2012 Red Hat, Inc. All rights reserved.
[ 0:29] ## Line: 4 	 #
[ 0:29] ## Line: 5 	 # This copyrighted material is made available to anyone wishing to use,
[ 0:29] ## Line: 6 	 # modify, copy, or redistribute it subject to the terms and conditions
[ 0:29] ## Line: 7 	 # of the GNU General Public License v.2.
[ 0:29] ## Line: 8 	 #
[ 0:29] ## Line: 9 	 # You should have received a copy of the GNU General Public License
[ 0:29] ## Line: 10 	 # along with this program; if not, write to the Free Software Foundation,
[ 0:29] ## Line: 11 	 # Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA
[ 0:29] ## Line: 12 	 
[ 0:29] ## Line: 13 	 SKIP_WITH_LVMLOCKD=1
[ 0:29] ## Line: 14 	 SKIP_WITHOUT_LVMETAD=1
[ 0:29] ## Line: 15 	 SKIP_WITH_LVMPOLLD=1
[ 0:29] ## Line: 16 	 
[ 0:29] ## Line: 17 	 . lib/inittest
[ 0:29] ## Line: 18 	 
[ 0:29] ## Line: 19 	 aux prepare_vg 2
[ 0:29] ## Line: 20 	 lvcreate -n bar -l 1 $vg
[ 0:29] ## Line: 21 	 
[ 0:29] ## Line: 22 	 aux lvmetad_dump | tee lvmetad.txt
[ 0:29] ## Line: 23 	 
[ 0:29] ## Line: 24 	 grep $vg lvmetad.txt
[ 0:29] ## Line: 25 	 
[ 0:29] ## Line: 26 	 vgremove -ff $vg
###  interrupted: [ndev-lvmetad] shell/lvmetad-dump.sh

### 1 tests: 0 passed, 0 skipped, 0 timed out, 0 warned, 0 failed
make: *** [Makefile:144: check_lvmetad] Error 1

^ permalink raw reply	[flat|nested] 6+ messages in thread

end of thread, other threads:[~2017-12-14 15:01 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-12-13 11:13 [PATCH] test: lvmetad_dump always timed out when using nc Eric Ren
2017-12-14 10:27 ` Eric Ren
2017-12-14 10:39   ` Zdenek Kabelac
2017-12-14 13:28     ` Eric Ren
2017-12-14 14:07       ` Zdenek Kabelac
2017-12-14 15:01         ` Eric Ren

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.