RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1330290 - docker-storage-setup frequently fails when lvm2 not initially installed in system
Summary: docker-storage-setup frequently fails when lvm2 not initially installed in sy...
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: docker
Version: 7.2
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: rc
: ---
Assignee: Vivek Goyal
QA Contact: atomic-bugs@redhat.com
URL:
Whiteboard:
Depends On:
Blocks: 1330706 1330714
TreeView+ depends on / blocked
 
Reported: 2016-04-25 19:29 UTC by Erik M Jacobs
Modified: 2020-06-09 21:11 UTC (History)
10 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
: 1330706 1330714 (view as bug list)
Environment:
Last Closed: 2020-06-09 21:11:09 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)
docker log when using +x and pvscan (22.12 KB, text/x-vhdl)
2016-04-25 20:39 UTC, Erik M Jacobs 		no flags Details
tweaked docker-storage-setup (25.89 KB, application/x-shellscript)
2016-04-25 20:45 UTC, Erik M Jacobs 		no flags Details
no pvscan, pvcreate -vvvv -f (8.32 KB, text/plain)
2016-04-26 13:06 UTC, Erik M Jacobs 		no flags Details
another tweak to docker-storage-setup for more output (12.95 KB, text/plain)
2016-04-26 15:44 UTC, Erik M Jacobs 		no flags Details
View All

Description Erik M Jacobs 2016-04-25 19:29:14 UTC 
Description of problem:
docker-storage-setup is run when the docker daemon is started. It will attempt to create the various partitions, pvs, vgs, and lvs for the docker storage pool. For whatever reason, sometimes pvcreate inside docker-storage-setup will fail to detect the partition that was created even though the rest of the system thinks it is there.

Perhaps this is related to the fact that Amazon AMIs do not have LVM installed out of the box (installation of docker pulls in the lvm2 package).

We have been fussing with various patches to try to fix this issue with docker-storage-setup but it may actually be an underlying LVM issue.

Relevant log information follows where we have patched docker-storage-setup to include a wait function as well as increase its verbosity:

Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: Starting Docker Storage Setup...                                                                                                   [105/326]
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + POOL_LV_NAME=docker-pool
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + DATA_LV_NAME=docker-pool
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + META_LV_NAME=docker-poolmeta
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + DOCKER_STORAGE=/etc/sysconfig/docker-storage
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + STORAGE_DRIVERS='devicemapper overlay'
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + '[' 0 -gt 0 ']'
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + '[' -e /usr/lib/docker-storage-setup/libdss.sh ']'
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + source /usr/lib/docker-storage-setup/libdss.sh
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + '[' -e /usr/lib/docker-storage-setup/docker-storage-setup ']'
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + source /usr/lib/docker-storage-setup/docker-storage-setup
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ STORAGE_DRIVER=devicemapper
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ DATA_SIZE=40%FREE
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ MIN_DATA_SIZE=2G
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ CHUNK_SIZE=512K
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ GROWPART=false
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ AUTO_EXTEND_POOL=yes
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ POOL_AUTOEXTEND_THRESHOLD=60
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ POOL_AUTOEXTEND_PERCENT=20
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + '[' -e /etc/sysconfig/docker-storage-setup ']'
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + source /etc/sysconfig/docker-storage-setup
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ DEVS=/dev/xvdb
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ VG=docker_vg
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ DEVICE_WAIT_TIMEOUT=60
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ awk '$2 ~ /^\/$/ && $1 !~ /rootfs/ { print $1 }' /proc/mounts
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + ROOT_DEV=/dev/xvda2
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ lvs --noheadings -o vg_name /dev/xvda2
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: Volume group "xvda2" not found
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: Cannot process volume group xvda2
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + ROOT_VG=
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + ROOT_VG=
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ pvs --noheadings -o pv_name,vg_name
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ awk '$2 ~ /^$/ { print $1 }'
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + ROOT_PVS=
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + VG_EXISTS=
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + '[' -z docker_vg ']'
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ vgs --noheadings -o vg_name
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + '[' -n /dev/xvdb ']'
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + create_disk_partitions
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + for dev in '$DEVS'
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + expr match /dev/xvdb '.*[0-9]'
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + [[ /dev/xvdb != /dev/* ]]
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: +++ basename /dev/xvdb
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ awk '$4 ~ /xvdb[0-9]/ { print $4 }' /proc/partitions
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + PARTS=
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + '[' -n '' ']'
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: +++ basename /dev/xvdb
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: ++ awk '$4 ~ /xvdb/ { print $3 }' /proc/partitions
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + size=52426752
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + cat
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + sfdisk /dev/xvdb
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: Checking that no-one is using this disk right now ...
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: OK
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: sfdisk:  /dev/xvdb: unrecognized partition table type
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: sfdisk: No partitions found
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: Disk /dev/xvdb: 3263 cylinders, 255 heads, 63 sectors/track
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: Old situation:
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: New situation:
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: Units: sectors of 512 bytes, counting from 0
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: Device Boot    Start       End   #sectors  Id  System
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: /dev/xvdb1          2048  52428799   52426752  8e  Linux LVM
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: /dev/xvdb2             0         -          0   0  Empty
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: /dev/xvdb3             0         -          0   0  Empty
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: /dev/xvdb4             0         -          0   0  Empty
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: Warning: partition 1 does not end at a cylinder boundary
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: Warning: no primary partition is marked bootable (active)
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: This does not matter for LILO, but the DOS MBR will not boot this disk.
Apr 25 12:15:53 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: Successfully wrote the new partition table
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: Re-reading the partition table ...
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: If you created or changed a DOS partition, /dev/foo7, say, then use dd(1)
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: to zero the first 512 bytes:  dd if=/dev/zero of=/dev/foo7 bs=512 count=1
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: (See fdisk(8).)
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + wait_for_dev /dev/xvdb1
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + local devpath=/dev/xvdb1
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + local timeout=60
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + '[' -z 60 ']'
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + '[' 60 == 0 ']'
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + '[' -b /dev/xvdb1 ']'
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + return 0
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: + pvcreate /dev/xvdb1
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: Device /dev/xvdb1 not found (or ignored by filtering).
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: docker-storage-setup.service: main process exited, code=exited, status=5/NOTINSTALLED
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: Failed to start Docker Storage Setup.
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: Unit docker-storage-setup.service entered failed state.
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: docker-storage-setup.service failed.
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: Starting Docker Application Container Engine...
Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal docker[10966]: time="2016-04-25T12:15:56.896674629-04:00" level=info msg="Listening for HTTP on unix (/var/run/docker.sock)"
Apr 25 12:15:57 ip-172-18-0-177.us-west-2.compute.internal docker[10966]: time="2016-04-25T12:15:57.145739199-04:00" level=error msg="WARNING: No --storage-opt dm.thinpooldev specified, using loopback; this conf
iguration is strongly discouraged for production use"
Apr 25 12:16:56 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: docker.service start operation timed out. Terminating.
Apr 25 12:16:56 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: docker.service: main process exited, code=exited, status=2/INVALIDARGUMENT
Apr 25 12:16:56 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: Failed to start Docker Application Container Engine.
Apr 25 12:16:56 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: Unit docker.service entered failed state.
Apr 25 12:16:56 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: docker.service failed.
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: docker.service holdoff time over, scheduling restart.
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: Starting Docker Storage Setup...
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + POOL_LV_NAME=docker-pool
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + DATA_LV_NAME=docker-pool
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + META_LV_NAME=docker-poolmeta
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + DOCKER_STORAGE=/etc/sysconfig/docker-storage
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + STORAGE_DRIVERS='devicemapper overlay'
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + '[' 0 -gt 0 ']'
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + '[' -e /usr/lib/docker-storage-setup/libdss.sh ']'
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + source /usr/lib/docker-storage-setup/libdss.sh
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + '[' -e /usr/lib/docker-storage-setup/docker-storage-setup ']'
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + source /usr/lib/docker-storage-setup/docker-storage-setup
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: ++ STORAGE_DRIVER=devicemapper
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: ++ DATA_SIZE=40%FREE
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: ++ MIN_DATA_SIZE=2G
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: ++ CHUNK_SIZE=512K
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: ++ GROWPART=false
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: ++ AUTO_EXTEND_POOL=yes
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: ++ POOL_AUTOEXTEND_THRESHOLD=60
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: ++ POOL_AUTOEXTEND_PERCENT=20
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + '[' -e /etc/sysconfig/docker-storage-setup ']'
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + source /etc/sysconfig/docker-storage-setup
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: ++ DEVS=/dev/xvdb
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: ++ VG=docker_vg
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: ++ DEVICE_WAIT_TIMEOUT=60
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: ++ awk '$2 ~ /^\/$/ && $1 !~ /rootfs/ { print $1 }' /proc/mounts
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + ROOT_DEV=/dev/xvda2
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: ++ lvs --noheadings -o vg_name /dev/xvda2
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: Volume group "xvda2" not found
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: Cannot process volume group xvda2
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + ROOT_VG=
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + ROOT_VG=
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: ++ awk '$2 ~ /^$/ { print $1 }'
Apr 25 12:16:57 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: ++ pvs --noheadings -o pv_name,vg_name
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + ROOT_PVS=
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + VG_EXISTS=
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + '[' -z docker_vg ']'
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: ++ vgs --noheadings -o vg_name
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + '[' -n /dev/xvdb ']'
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + create_disk_partitions
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + for dev in '$DEVS'
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + expr match /dev/xvdb '.*[0-9]'
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + [[ /dev/xvdb != /dev/* ]]
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: +++ basename /dev/xvdb
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: ++ awk '$4 ~ /xvdb[0-9]/ { print $4 }' /proc/partitions
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + PARTS=xvdb1
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + '[' -n xvdb1 ']'
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + echo '/dev/xvdb has partitions: xvdb1'
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: /dev/xvdb has partitions: xvdb1
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[11002]: + exit 1
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: docker-storage-setup.service: main process exited, code=exited, status=1/FAILURE
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: Failed to start Docker Storage Setup.
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: Unit docker-storage-setup.service entered failed state.
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: docker-storage-setup.service failed.
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal systemd[1]: Starting Docker Application Container Engine...
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker[11019]: time="2016-04-25T12:18:04.231071471-04:00" level=info msg="Listening for HTTP on unix (/var/run/docker.sock)"
Apr 25 12:18:04 ip-172-18-0-177.us-west-2.compute.internal docker[11019]: time="2016-04-25T12:18:04.283149831-04:00" level=error msg="WARNING: No --storage-opt dm.thinpooldev specified, using loopback; this conf
iguration is strongly discouraged for production use"
Comment 1 Erik M Jacobs 2016-04-25 19:32:20 UTC 
openshift-ansible will force installation of docker 1.8.2
Comment 2 Vivek Goyal 2016-04-25 19:56:21 UTC 
So following is the real problem.

Apr 25 12:15:56 ip-172-18-0-177.us-west-2.compute.internal docker-storage-setup[10943]: Device /dev/xvdb1 not found (or ignored by filtering).

pvcreate decided to not convert device into physical volume. Error message is confusing. Initially we thought that for some reason /dev/xvdb1 is not available yet after creation. So I put in a patch to wait for device in loop after partition creation. But even with that docker-storage-setup fails sometime.

So now we are sure that /dev/xvdb1 is present and that's not the error.
Comment 3 Vivek Goyal 2016-04-25 19:57:19 UTC 
Also, lvm2 is not installed in the image to begin with. docker has a dependency on lvm2 and it pulls it in when installed. After that user starts docker service.

Are lvm2 services in proper shape after installation or some user intervention required?
Comment 4 David Teigland 2016-04-25 20:12:38 UTC 
If lvmetad is being used, and if lvmetad has not been notified about /dev/xvdb1, then that would explain the error.  There are different reasons why lvmetad might not be notified about that device.

Once guess is that doing: 'rpm -i lvm2; pvcreate /dev/xvdb1' is missing some lvmetad service start or initialization.  You should verify that lvmetad is running and manually run 'pvscan --cache' after rpm install.  Or, you could disable lvmetad (use_lvmetad=0 in lvm.conf) since it may not be a benefit in this environment.
Comment 5 Vivek Goyal 2016-04-25 20:15:29 UTC 
I installed lvm2 after booting an rhel7.2 AMI in amazon and lvm2-lvmetad started running automatically.

# systemctl status lvm2-lvmetad
● lvm2-lvmetad.service - LVM2 metadata daemon
   Loaded: loaded (/usr/lib/systemd/system/lvm2-lvmetad.service; disabled; vendor preset: enabled)
   Active: active (running) since Mon 2016-04-25 16:12:01 EDT; 18s ago
     Docs: man:lvmetad(8)
 Main PID: 9403 (lvmetad)
   CGroup: /system.slice/lvm2-lvmetad.service
           └─9403 /usr/sbin/lvmetad -f
Comment 7 Erik M Jacobs 2016-04-25 20:39:08 UTC 
Created attachment 1150633 [details]
docker log when using +x and pvscan

after adding "set +x" and a "pvscan --cache" to the docker-storage-setup and using the latest master (https://github.com/projectatomic/docker-storage-setup) here is the log output.
Comment 8 Erik M Jacobs 2016-04-25 20:44:17 UTC 
lvm2-libs-2.02.130-5.el7_2.1.x86_64
lvm2-2.02.130-5.el7_2.1.x86_64
Comment 9 Erik M Jacobs 2016-04-25 20:45:00 UTC 
Created attachment 1150634 [details]
tweaked docker-storage-setup
Comment 10 Erik M Jacobs 2016-04-25 22:20:04 UTC 
Removing "-vvv" from pvcreate and removing the pvscan I was able to get the error again:

-- Logs begin at Mon 2016-04-25 18:14:36 EDT, end at Mon 2016-04-25 18:18:36 EDT. --
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal systemd[1]: Starting Docker Storage Setup...
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: INFO: Volume group backing root filesystem could not be determined
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: Checking that no-one is using this disk right now ...
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: OK
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: sfdisk:  /dev/xvdb: unrecognized partition table type
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: sfdisk: No partitions found
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: Disk /dev/xvdb: 3263 cylinders, 255 heads, 63 sectors/track
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: Old situation:
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: New situation:
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: Units: sectors of 512 bytes, counting from 0
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: Device Boot    Start       End   #sectors  Id  System
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: /dev/xvdb1          2048  52428799   52426752  8e  Linux LVM
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: /dev/xvdb2             0         -          0   0  Empty
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: /dev/xvdb3             0         -          0   0  Empty
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: /dev/xvdb4             0         -          0   0  Empty
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: Warning: partition 1 does not end at a cylinder boundary
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: Warning: no primary partition is marked bootable (active)
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: This does not matter for LILO, but the DOS MBR will not boot this disk.
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: Successfully wrote the new partition table
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: Re-reading the partition table ...
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: If you created or changed a DOS partition, /dev/foo7, say, then use dd(1)
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: to zero the first 512 bytes:  dd if=/dev/zero of=/dev/foo7 bs=512 count=1
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal docker-storage-setup[10904]: (See fdisk(8).)
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal systemd[1]: docker-storage-setup.service: main process exited, code=exited, status=5/NOTINSTALLED
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal systemd[1]: Failed to start Docker Storage Setup.
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal systemd[1]: Unit docker-storage-setup.service entered failed state.
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal systemd[1]: docker-storage-setup.service failed.
Apr 25 18:17:16 ip-172-18-0-149.ec2.internal systemd[1]: Starting Docker Application Container Engine...

I will now try to include the pvscan but not the -vvv on pvcreate.
Comment 11 Erik M Jacobs 2016-04-26 00:51:15 UTC 
OK, I've done several (4+) tests now with the addition of pvscan and had zero failures.

I am thinking that adding the pvscan is a valuable step.
Comment 12 Zdenek Kabelac 2016-04-26 08:51:07 UTC 
(In reply to Erik M Jacobs from comment #11)
> OK, I've done several (4+) tests now with the addition of pvscan and had
> zero failures.
> 
> I am thinking that adding the pvscan is a valuable step.

Hi

Please attach 'pvcreate -vvvv /dev/xvdb1'  trace from the 'failing' case.

'pvscan --cache' is not correct fix here - lvmetad should be doing this in background - so adding it 'extra' should not be needed.

Also:

ls -la /lib/udev/rules
Comment 13 Zdenek Kabelac 2016-04-26 08:56:41 UTC 
Note: if your formated device has an 'existing' signature - pvcreate may refuse to use unless forced -  in this case - please open RFE to handle such case more user-friendly.
Comment 14 Erik M Jacobs 2016-04-26 12:04:18 UTC 
Comment #1 has pvcreate output from a failure with -vvv (not 4 vs). I will try again.

These should be new/clean EBS volumes but who knows with Amazon...

I'll try to get the needinfo. I can't predictably produce the failures.
Comment 15 Vivek Goyal 2016-04-26 12:47:02 UTC 
Zdenek,

- In latest patches we are using pvcreate with option -f. So that if there are signatures on disk, they should be overwritten. So this is not the case of
bailing out because signatures are already there.

- How do we take care of races with lvmetad. If a partition is created and
  while pvscan is going on, one could try to do "pvcreate" in the mean time
  and fail. I suspect that we are hitting this race window. Because if docker-storage-setup is re-run after the failure, it succeeds.
Comment 16 Zdenek Kabelac 2016-04-26 12:55:33 UTC 
Startup pvscan is meant to be handled by lvmetad -  whoever is 1st. user of lvmetad is supposed to fill it with complete device scan.

That's why it's important to see full 'pvcreate -vvvv' trace.
Comment 17 Erik M Jacobs 2016-04-26 13:06:24 UTC 
Created attachment 1150969 [details]
no pvscan, pvcreate -vvvv -f
Comment 18 Erik M Jacobs 2016-04-26 13:09:21 UTC 
Just to make sure we're on the same page:

1) lvm2 is not installed when the OS comes up
2) installation of docker starts lvm2 services because it pulls in the lvm2 package(s)
3) startup of docker involves running docker-storage-setup
4) docker-storage-setup creates a partition and then runs pvcreate
5) OS thinks that partition/device exists, pvcreate *does not*

If you add a pvscan --cache before running pvcreate, the problem goes away.

So something is "wrong" with lvm in that pvcreate is not detecting a device even though the rest of the system "sees" the device. pvscan makes the lvm subsystem know about the device.

Perhaps this bz should be transitioned to the lvm2 package?
Comment 19 David Teigland 2016-04-26 15:42:22 UTC 
What I wrote in comment 4 (about pvscan notifying lvmetad about the device), now seems wrong.  lvmetad is only notified about *PVs* and only caches info about PVs.
In this case, a PV does not exist on /dev/xvdb1 prior to the pvcreate.  So, we don't expect xvdb1 to exist in lvmetad prior to that.  If pvscan seemed to help, it was because of some side effect.  Sorry for that misdirection.
Comment 20 Erik M Jacobs 2016-04-26 15:44:45 UTC 
Created attachment 1150999 [details]
another tweak to docker-storage-setup for more output
Comment 21 Vivek Goyal 2016-04-26 15:49:49 UTC 
Above is a good log message. It shows clearly that partition device was present before pvcreate was called.

INFO: Device node /dev/xvdb1 exists.

And after that pvcreate failed. This time we did not get "stat" node does not exist error. Looks like device got filtered.

filters/filter-sysfs.c:274         /dev/xvdb1: Skipping (sysfs)
Comment 22 Zdenek Kabelac 2016-04-26 17:12:47 UTC 
Link for device is created by devtmpfs.
Unfortunately sysfs is not created in sync - though this should be more closely explored - it should not be possibly to easily trigger such race on unloaded machine.

Anyway - as long as the even is not fully processed - any tool (included) lvm2 is 'free' to not see a device  - this is  'built-in' race in the whole udev logic.   The only 'weapon' available to a user to fight with such issue - is to wait for result of   'udevadm settle'

lvm2 validate devices in number of ways - and in this case  the missing 'sysfs' entry 'kills' such device from lvm2 usable devices (as validation filter).

Solution is - to no pass devices which have 'creation of device node' in progress.


TODO: explore why it's actually so slow, lvm2 command is even able to spot this race after shell loop..
Comment 23 Zdenek Kabelac 2016-04-27 14:52:22 UTC 
It's unclear to me how it could be possible that 'sfdisk'  ends with  BLKRRPART ioctl -  and there is actually not available /sysfs matching entry.
Comment 25 Daniel Walsh 2017-06-30 15:06:04 UTC 
Vivek do we still have this issue?  Do we have this issue with container-storage-setup?
Comment 26 Daniele Pasquini 2017-11-27 00:05:06 UTC 
Configure direct-lvm mode manually

https://docs.docker.com/engine/userguide/storagedriver/device-mapper-driver/#configure-direct-lvm-mode-for-production
Comment 27 Tom Sweeney 2020-06-09 21:11:09 UTC 
We have no plans to ship another version of Docker at this time. RHEL7 is in final support stages where only security fixes will get released.  Customers should move to use Podman which is available starting in RHEL 7.6.
Note You need to log in before you can comment on or make changes to this bug.