dib fails with error creating loopback file system

Bug #1698337 reported by Amrith Kumar
18
This bug affects 4 people
Affects Status Importance Assigned to Milestone
diskimage-builder
Fix Released
High
Ian Wienand

Bug Description

Error log snippet is attached, the relevant lines are also shown below.

2017-06-16 04:26:05.784026 | 2017-06-16 04:26:05.783 | 2017-06-16 04:26:05.753 INFO diskimage_builder.block_device.utils [-] Calling [sudo kpartx -avs /dev/loop3]
2017-06-16 04:26:05.785293 | 2017-06-16 04:26:05.784 | 2017-06-16 04:26:05.761 DEBUG diskimage_builder.block_device.level2.mkfs [-] Creating fs command [['mkfs', '-t', u'ext4', u'-i', u'4096', u'-J', u'size=64', '-L', u'cloudimg-rootfs', '-U', 'a0bacc98-e041-4114-94d3-b3f776065ba6', '-q', u'/dev/mapper/loop3p1']] create /usr/local/lib/python2.7/dist-packages/diskimage_builder/block_device/level2/mkfs.py:130
2017-06-16 04:26:05.787201 | 2017-06-16 04:26:05.786 | 2017-06-16 04:26:05.761 INFO diskimage_builder.block_device.utils [-] Calling [sudo mkfs -t ext4 -i 4096 -J size=64 -L cloudimg-rootfs -U a0bacc98-e041-4114-94d3-b3f776065ba6 -q /dev/mapper/loop3p1]
2017-06-16 04:26:05.788505 | 2017-06-16 04:26:05.788 | 2017-06-16 04:26:05.774 DEBUG diskimage_builder.block_device.utils [-] exec_sudo: The file /dev/mapper/loop3p1 does not exist and no size was specified. exec_sudo /usr/local/lib/python2.7/dist-packages/diskimage_builder/block_device/utils.py:120
2017-06-16 04:26:05.789624 | 2017-06-16 04:26:05.789 | 2017-06-16 04:26:05.775 ERROR diskimage_builder.block_device.blockdevice [-] Create failed; rollback initiated
2017-06-16 04:26:05.790794 | 2017-06-16 04:26:05.790 | Traceback (most recent call last):
2017-06-16 04:26:05.792530 | 2017-06-16 04:26:05.792 | File "/usr/local/lib/python2.7/dist-packages/diskimage_builder/block_device/blockdevice.py", line 385, in cmd_create
2017-06-16 04:26:05.793738 | 2017-06-16 04:26:05.793 | node.create()
2017-06-16 04:26:05.794954 | 2017-06-16 04:26:05.794 | File "/usr/local/lib/python2.7/dist-packages/diskimage_builder/block_device/level2/mkfs.py", line 131, in create
2017-06-16 04:26:05.796104 | 2017-06-16 04:26:05.795 | exec_sudo(cmd)
2017-06-16 04:26:05.797612 | 2017-06-16 04:26:05.797 | File "/usr/local/lib/python2.7/dist-packages/diskimage_builder/block_device/utils.py", line 125, in exec_sudo
2017-06-16 04:26:05.798710 | 2017-06-16 04:26:05.798 | ' '.join(sudo_cmd))
2017-06-16 04:26:05.799892 | 2017-06-16 04:26:05.799 | CalledProcessError: Command 'sudo mkfs -t ext4 -i 4096 -J size=64 -L cloudimg-rootfs -U a0bacc98-e041-4114-94d3-b3f776065ba6 -q /dev/mapper/loop3p1' returned non-zero exit status 1

Revision history for this message
Amrith Kumar (amrith) wrote :
Revision history for this message
Ian Wienand (iwienand) wrote :

Thanks, we had a report of this in the morning, but this captures that the device isn't there.

Clearly the synchronous option to kpartx isn't all we want it to be. I think a sleep after the call might be the quickest solution here. Or maybe a udevadm settle call ... But maybe that is just a placebo for a sleep.

I'm on a phone so can't propose a change, but I think that will help

Changed in diskimage-builder:
status: New → Confirmed
importance: Undecided → High
Revision history for this message
Michael Johnson (johnsom) wrote :

2017-06-16 08:41:51.441 | 2017-06-16 08:41:51.441 INFO diskimage_builder.block_device.utils [-] Calling [sudo kpartx -avs /dev/loop0]
2017-06-16 08:41:51.450 | 2017-06-16 08:41:51.450 DEBUG diskimage_builder.block_device.level2.mkfs [-] Creating fs command [['mkfs', '-t', 'ext4', '-i', '4096', '-J', 'size=64', '-L', 'cloudimg-rootfs', '-U', 'c5ba0122-3b42-463c-8b9e-03a00992ec4d', '-q', '/dev/mapper/loop0p1']] create /opt/stack/new/diskimage-builder/diskimage_builder/block_device/level2/mkfs.py:130
2017-06-16 08:41:51.450 | 2017-06-16 08:41:51.450 INFO diskimage_builder.block_device.utils [-] Calling [sudo mkfs -t ext4 -i 4096 -J size=64 -L cloudimg-rootfs -U c5ba0122-3b42-463c-8b9e-03a00992ec4d -q /dev/mapper/loop0p1]
2017-06-16 08:41:51.459 | 2017-06-16 08:41:51.459 DEBUG diskimage_builder.block_device.utils [-] exec_sudo: b'The file /dev/mapper/loop0p1 does not exist and no size was specified.' exec_sudo /opt/stack/new/diskimage-builder/diskimage_builder/block_device/utils.py:120

Revision history for this message
Michael Johnson (johnsom) wrote :

This is impacting octavia as well.

Changed in diskimage-builder:
assignee: nobody → Michael Johnson (johnsom)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to diskimage-builder (master)

Fix proposed to branch: master
Review: https://review.openstack.org/475022

Changed in diskimage-builder:
status: Confirmed → In Progress
Changed in diskimage-builder:
assignee: Michael Johnson (johnsom) → Ian Wienand (iwienand)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to diskimage-builder (master)

Reviewed: https://review.openstack.org/475022
Committed: https://git.openstack.org/cgit/openstack/diskimage-builder/commit/?id=250aeb5d219db1a0fc01033168a55f7f61e60c74
Submitter: Jenkins
Branch: master

commit 250aeb5d219db1a0fc01033168a55f7f61e60c74
Author: Michael Johnson <email address hidden>
Date: Fri Jun 16 09:26:06 2017 -0700

    Fix mkfs failure when loop device is not ready

    There was a race in diskimage-builder where the mkfs call after a
    kpartx -avs for the loop device would fail because the device was
    not yet ready. This adds a udevadm settle call after the kpartx
    to make sure the udev event queue has cleared.

    Change-Id: I90103b59357edebbac7a641e8980cb282d37561b
    Closes-Bug: #1698337

Changed in diskimage-builder:
status: In Progress → Fix Released
Revision history for this message
Michael Johnson (johnsom) wrote :

This fix did not work:
http://logs.openstack.org/72/472872/13/check/gate-octavia-v1-dsvm-scenario-multinode/170affe/logs/devstacklog.txt.gz#_2017-06-17_20_28_14_429

2017-06-17 20:28:14.421 | 2017-06-17 20:28:14.421 INFO diskimage_builder.block_device.utils [-] Calling [sudo kpartx -avs /dev/loop0]
2017-06-17 20:28:14.429 | 2017-06-17 20:28:14.429 INFO diskimage_builder.block_device.utils [-] Calling [sudo udevadm settle]
2017-06-17 20:28:14.444 | 2017-06-17 20:28:14.444 DEBUG diskimage_builder.block_device.level2.mkfs [-] Creating fs command [['mkfs', '-t', u'ext4', u'-i', u'4096', u'-J', u'size=64', '-L', u'cloudimg-rootfs', '-U', 'b66194c0-3491-4dfa-9545-4fd1c614c5f4', '-q', u'/dev/mapper/loop0p1']] create /opt/stack/new/diskimage-builder/diskimage_builder/block_device/level2/mkfs.py:130
2017-06-17 20:28:14.444 | 2017-06-17 20:28:14.444 INFO diskimage_builder.block_device.utils [-] Calling [sudo mkfs -t ext4 -i 4096 -J size=64 -L cloudimg-rootfs -U b66194c0-3491-4dfa-9545-4fd1c614c5f4 -q /dev/mapper/loop0p1]
2017-06-17 20:28:14.464 | 2017-06-17 20:28:14.464 DEBUG diskimage_builder.block_device.utils [-] exec_sudo: The file /dev/mapper/loop0p1 does not exist and no size was specified. exec_sudo /opt/stack/new/diskimage-builder/diskimage_builder/block_device/utils.py:120

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to diskimage-builder (master)

Fix proposed to branch: master
Review: https://review.openstack.org/475203

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to diskimage-builder (master)

Reviewed: https://review.openstack.org/475203
Committed: https://git.openstack.org/cgit/openstack/diskimage-builder/commit/?id=5d5fa06e5c53ca8dc857d1700b57c2336ac62db1
Submitter: Jenkins
Branch: master

commit 5d5fa06e5c53ca8dc857d1700b57c2336ac62db1
Author: Ian Wienand <email address hidden>
Date: Mon Jun 19 10:29:53 2017 +1000

    Sync after writing partition table

    We introduced the "settle" in
    I90103b59357edebbac7a641e8980cb282d37561b thinking that maybe kpartx
    had not finished writing the partition. This probably wasn't a bad
    first assumption, since we used to have this -- but is seems
    insufficient.

    The other failiure here seems to be if kpartx hasn't actually seen the
    updated partition table in the image, so it has correctly (in it's
    mind) not mounted the partition.

    Looking at strace of fdisk run manually on a loopback, it will do a
    fsync on the raw device after writing and then a global sync as it
    exits.

    This replicates this; we flush and fsync in mbr.py in the exit handler
    after writing the partition, before closing the file (i've updated one
    of the unit tests to double-check the call). In the partitioning.py
    caller we execute a sync call too.

    Since it does seem unlikely the "-s" option of kpartx is not working,
    I've removed the udev settle work-around too.

    Change-Id: Ia77a0ffe4c76854b326ed76490479d9c691b49aa
    Partial-Bug: #1698337

Revision history for this message
Amrith Kumar (amrith) wrote :
Download full text (4.8 KiB)

I just cloned the tip of master, still hitting this problem.

Do you want me to turn up debug and try this again?

2018-07-15 22:00:16.448 | dib-run-parts 95-package-uninstalls completed
2018-07-15 22:00:16.453 | dib-run-parts ----------------------- PROFILING -----------------------
2018-07-15 22:00:16.453 | dib-run-parts
2018-07-15 22:00:16.465 | dib-run-parts Target: post-install.d
2018-07-15 22:00:16.465 | dib-run-parts
2018-07-15 22:00:16.466 | dib-run-parts Script Seconds
2018-07-15 22:00:16.467 | dib-run-parts --------------------------------------- ----------
2018-07-15 22:00:16.468 | dib-run-parts
2018-07-15 22:00:16.532 | dib-run-parts 00-package-installs 0.374
2018-07-15 22:00:16.570 | dib-run-parts 95-package-uninstalls 0.452
2018-07-15 22:00:16.583 | dib-run-parts
2018-07-15 22:00:16.583 | dib-run-parts --------------------- END PROFILING ---------------------
2018-07-15 22:00:16.653 | Unmount /tmp/dib_build.iWopQLuO/mnt/var/cache/apt/archives
2018-07-15 22:00:16.683 | Unmount /tmp/dib_build.iWopQLuO/mnt/sys
2018-07-15 22:00:16.715 | Unmount /tmp/dib_build.iWopQLuO/mnt/proc
2018-07-15 22:00:16.739 | Unmount /tmp/dib_build.iWopQLuO/mnt/dev/pts
2018-07-15 22:00:16.779 | Unmount /tmp/dib_build.iWopQLuO/mnt/dev
2018-07-15 22:00:16.813 | Calculating image size (this may take a minute)...
2018-07-15 22:00:17.030 | INFO diskimage_builder.block_device.blockdevice [-] Wrote final block device config to [/tmp/dib_build.iWopQLuO/states/block-device/config.json]
2018-07-15 22:00:17.179 | INFO diskimage_builder.block_device.blockdevice [-] create() called
2018-07-15 22:00:17.179 | INFO diskimage_builder.block_device.level0.localloop [-] Create image file [/tmp/dib_image.aO8wYmAy/image0.raw]
2018-07-15 22:00:17.179 | INFO diskimage_builder.block_device.level0.localloop [-] loopdev attach
2018-07-15 22:00:17.219 | INFO diskimage_builder.block_device.level0.localloop [-] New block device [/dev/loop9]
2018-07-15 22:00:17.219 | INFO diskimage_builder.block_device.level1.partitioning [-] Creating partition on [image0] [/tmp/dib_image.aO8wYmAy/image0.raw]
2018-07-15 22:00:17.219 | INFO diskimage_builder.block_device.level1.mbr [-] Create MBR disk partitioning object
2018-07-15 22:00:17.219 | INFO diskimage_builder.block_device.level1.mbr [-] Partition absolute [2048] relative [0] length [204800] absolute end [206848]
2018-07-15 22:00:17.219 | INFO diskimage_builder.block_device.level1.mbr [-] Write partition entry blockno [0] entry [0] start [2048] length [204800]
2018-07-15 22:00:17.219 | INFO diskimage_builder.block_device.level1.mbr [-] Partition absolute [206848] relative [204800] length [3985408] absolute end [4192256]
2018-07-15 22:00:17.219 | INFO diskimage_builder.block_device.level1.mbr [-] Write partition entry blockno [0] entry [1] start [206848] length [3985408]
2018-07-15 22:00:17.220 | INFO diskimage_builder.block_device.utils [-] Calling [sudo sync]
2018-07-15 22:00:17.254 | INFO diskimage_builder.block_device.utils [-] Calling [sudo kpartx -avs /dev/loop9]
2018-07-15 22:00:17.259 | INFO diskimage_builder.block_device.level1.partitioning [-] Not...

Read more...

Revision history for this message
Amrith Kumar (amrith) wrote :
Download full text (4.6 KiB)

Re-ran with -x (to dib) and got this:

2018-07-16 19:54:31.858 | dib-run-parts 60-untrim-dpkg completed
2018-07-16 19:54:31.858 | dib-run-parts Running /tmp/dib_build.zUcm27Y7/hooks/cleanup.d/90-copy-boot-part
2018-07-16 19:54:32.069 | cp: cannot stat '/tmp/tmp.V5YWpxVTsG/boot/*': No such file or directory
2018-07-16 19:54:32.071 | + /usr/local/lib/python2.7/dist-packages/diskimage_builder/lib/common-functions:run_d:1 : trap_cleanup
2018-07-16 19:54:32.072 | + /usr/local/lib/python2.7/dist-packages/diskimage_builder/lib/img-functions:trap_cleanup:36 : exitval=1
2018-07-16 19:54:32.074 | + /usr/local/lib/python2.7/dist-packages/diskimage_builder/lib/img-functions:trap_cleanup:37 : cleanup
2018-07-16 19:54:32.075 | + /usr/local/lib/python2.7/dist-packages/diskimage_builder/lib/img-functions:cleanup:42 : dib-block-device umount
2018-07-16 19:54:32.210 | DEBUG diskimage_builder.block_device.blockdevice [-] Creating BlockDevice object __init__ /usr/local/lib/python2.7/dist-packages/diskimage_builder/block_device/blockdevice.py:228
2018-07-16 19:54:32.210 | DEBUG diskimage_builder.block_device.blockdevice [-] Params [{'root-fs-type': 'ext4', 'root-fs-opts': '-i 4096 -J size=64 ', 'root-label': None, 'build-dir': '/tmp/dib_build.zUcm27Y7', 'image-size': '1664256KiB', 'image-dir': '/tmp/dib_image.ltHT91DC', 'config': '/tmp/dib_build.zUcm27Y7/block-device/config.yaml', 'mount-base': '/tmp/dib_build.zUcm27Y7/mnt'}] __init__ /usr/local/lib/python2.7/dist-packages/diskimage_builder/block_device/blockdevice.py:231
2018-07-16 19:54:32.216 | INFO diskimage_builder.block_device.level3.mount [-] Called for [mount_mkfs_boot]
2018-07-16 19:54:32.216 | INFO diskimage_builder.block_device.utils [-] Calling [sudo sync]
2018-07-16 19:54:32.236 | INFO diskimage_builder.block_device.utils [-] Calling [sudo umount /tmp/dib_build.zUcm27Y7/mnt/boot]
2018-07-16 19:54:32.264 | INFO diskimage_builder.block_device.level3.mount [-] Called for [mount_mkfs_root]
2018-07-16 19:54:32.264 | INFO diskimage_builder.block_device.utils [-] Calling [sudo sync]
2018-07-16 19:54:32.275 | INFO diskimage_builder.block_device.utils [-] Calling [sudo fstrim --verbose /tmp/dib_build.zUcm27Y7/mnt/]
2018-07-16 19:54:32.283 | DEBUG diskimage_builder.block_device.utils [-] exec_sudo: /tmp/dib_build.zUcm27Y7/mnt/: 924.7 MiB (969633792 bytes) trimmed exec_sudo /usr/local/lib/python2.7/dist-packages/diskimage_builder/block_device/utils.py:120
2018-07-16 19:54:32.283 | INFO diskimage_builder.block_device.utils [-] Calling [sudo umount /tmp/dib_build.zUcm27Y7/mnt/]
2018-07-16 19:54:32.287 | DEBUG diskimage_builder.block_device.utils [-] exec_sudo: umount: /tmp/dib_build.zUcm27Y7/mnt/: target is busy exec_sudo /usr/local/lib/python2.7/dist-packages/diskimage_builder/block_device/utils.py:120
2018-07-16 19:54:32.287 | DEBUG diskimage_builder.block_device.utils [-] exec_sudo: (In some cases useful info about processes that exec_sudo /usr/local/lib/python2.7/dist-packages/diskimage_builder/block_device/utils.py:120
2018-07-16 19:54:32.287 | DEBUG diskimage_builder.block_device.utils [-] exec_sudo: use the device is found by lsof(8) or fuser(1).) exec_sudo /usr/local/lib/python2.7...

Read more...

Revision history for this message
Amrith Kumar (amrith) wrote :

Easier to read - dib-error.txt

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix merged to diskimage-builder (master)
Download full text (3.9 KiB)

Reviewed: https://review.opendev.org/728824
Committed: https://git.openstack.org/cgit/openstack/diskimage-builder/commit/?id=4a424ecabbb14e230be45864ee7eeca3722d49e8
Submitter: Zuul
Branch: master

commit 4a424ecabbb14e230be45864ee7eeca3722d49e8
Author: Simon Westphahl <email address hidden>
Date: Wed May 13 07:56:16 2020 +0200

    Use kpartx option to update partition mappings

    Fix cases of 'mkfs' failing because the partitions never showed up. Partition
    mappings will now be updated instead of just adding them with 'kpartx'. That
    means that 'kpartx' will also remove devmappings for deleted partitions.

    Traceback of failing mkfs call:

    2020-05-11 22:03:25.523 | INFO diskimage_builder.block_device.utils [-] Calling [sudo sync]
    2020-05-11 22:03:25.539 | INFO diskimage_builder.block_device.utils [-] Calling [sudo kpartx -avs /dev/loop0]
    2020-05-11 22:03:25.581 | INFO diskimage_builder.block_device.utils [-] Calling [sudo mkfs -t ext4 -i 4096 -J size=64 -L cloudimg-rootfs -U 21c6f9eb-4d52-4e5c-b9b7-796735de8909 -q /dev/mapper/loop0p1]
    2020-05-11 22:03:25.700 | ERROR diskimage_builder.block_device.blockdevice [-] Create failed; rollback initiated
    2020-05-11 22:03:25.700 | Traceback (most recent call last):
    2020-05-11 22:03:25.700 | File "/home/zuul/dib/lib/python3.6/site-packages/diskimage_builder/block_device/blockdevice.py", line 406, in cmd_create
    2020-05-11 22:03:25.700 | node.create()
    2020-05-11 22:03:25.700 | File "/home/zuul/dib/lib/python3.6/site-packages/diskimage_builder/block_device/level2/mkfs.py", line 133, in create
    2020-05-11 22:03:25.700 | exec_sudo(cmd)
    2020-05-11 22:03:25.700 | File "/home/zuul/dib/lib/python3.6/site-packages/diskimage_builder/block_device/utils.py", line 143, in exec_sudo
    2020-05-11 22:03:25.700 | raise e
    2020-05-11 22:03:25.700 | diskimage_builder.block_device.exception.BlockDeviceSetupException: exec_sudo failed
    2020-05-11 22:03:25.700 | INFO diskimage_builder.block_device.level0.localloop [-] loopdev detach
    2020-05-11 22:03:25.701 | INFO diskimage_builder.block_device.utils [-] Calling [sudo losetup -d /dev/loop0]
    2020-05-11 22:03:25.732 | INFO diskimage_builder.block_device.level0.localloop [-] Remove image file [/tmp/dib_image.muyw7t1h/image0.raw]
    2020-05-11 22:03:25.734 | ERROR diskimage_builder.block_device.blockdevice [-] Rollback complete, exiting
    2020-05-11 22:03:25.740 | Traceback (most recent call last):
    2020-05-11 22:03:25.740 | File "/home/zuul/dib/bin/dib-block-device", line 8, in <module>
    2020-05-11 22:03:25.740 | sys.exit(main())
    2020-05-11 22:03:25.740 | File "/home/zuul/dib/lib/python3.6/site-packages/diskimage_builder/block_device/cmd.py", line 120, in main
    2020-05-11 22:03:25.740 | return bdc.main()
    2020-05-11 22:03:25.740 | File "/home/zuul/dib/lib/python3.6/site-packages/diskimage_builder/block_device/cmd.py", line 115, in main
    2020-05-11 22:03:25.740 | self.args.func()
    2020-05-11 22:03:25.740 | File "/home/zuul/dib/lib/python3.6/site-packages/diskimage_builder/block_device/cmd.py", line 36, in cmd_create
    2020-05-11 2...

Read more...

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.