Error when formatting devices

[Chuck Short]

014-08-29 13:52:58 INFO install 1+0 records out
2014-08-29 13:52:58 INFO install 1048576 bytes (1.0 MB) copied, 0.00161497 s, 649 MB/s
2014-08-29 13:52:58 INFO install 100+0 records in
2014-08-29 13:52:58 INFO install 100+0 records out
2014-08-29 13:52:58 INFO install 51200 bytes (51 kB) copied, 0.00295606 s, 17.3 MB/s
2014-08-29 13:52:58 INFO install mkfs.xfs: /dev/vdb contains a mounted filesystem
2014-08-29 13:52:58 INFO install Usage: mkfs.xfs
2014-08-29 13:52:58 INFO install /* blocksize */ [-b log=n|size=num]
2014-08-29 13:52:58 INFO install /* metadata */ [-m crc=0|1,finobt=0|1]
2014-08-29 13:52:58 INFO install /* data subvol */ [-d agcount=n,agsize=n,file,name=xxx,size=num,
2014-08-29 13:52:58 INFO install (sunit=value,swidth=value|su=num,sw=num|noalign),
2014-08-29 13:52:58 INFO install sectlog=n|sectsize=num
2014-08-29 13:52:58 INFO install /* force overwrite */ [-f]
2014-08-29 13:52:58 INFO install /* inode size */ [-i log=n|perblock=n|size=num,maxpct=n,attr=0|1|2,
2014-08-29 13:52:58 INFO install projid32bit=0|1]
2014-08-29 13:52:58 INFO install /* no discard */ [-K]
2014-08-29 13:52:58 INFO install /* log subvol */ [-l agnum=n,internal,size=num,logdev=xxx,version=n
2014-08-29 13:52:58 INFO install sunit=value|su=num,sectlog=n|sectsize=num,
2014-08-29 13:52:58 INFO install lazy-count=0|1]
2014-08-29 13:52:58 INFO install /* label */ [-L label (maximum 12 characters)]
2014-08-29 13:52:58 INFO install /* naming */ [-n log=n|size=num,version=2|ci,ftype=0|1]
2014-08-29 13:52:58 INFO install /* no-op info only */ [-N]
2014-08-29 13:52:58 INFO install /* prototype file */ [-p fname]
2014-08-29 13:52:58 INFO install /* quiet */ [-q]
2014-08-29 13:52:58 INFO install /* realtime subvol */ [-r extsize=num,size=num,rtdev=xxx]
2014-08-29 13:52:58 INFO install /* sectorsize */ [-s log=n|size=num]
2014-08-29 13:52:58 INFO install /* version */ [-V]
2014-08-29 13:52:58 INFO install devicename
2014-08-29 13:52:58 INFO install <devicename> is required unless -d name=xxx is given.
2014-08-29 13:52:58 INFO install <num> is xxx (bytes), xxxs (sectors), xxxb (fs blocks), xxxk (xxx KiB),
2014-08-29 13:52:58 INFO install xxxm (xxx MiB), xxxg (xxx GiB), xxxt (xxx TiB) or xxxp (xxx PiB).
2014-08-29 13:52:58 INFO install <value> is xxx (512 byte blocks).
2014-08-29 13:52:58 INFO install Traceback (most recent call last):
2014-08-29 13:52:58 INFO install File "/var/lib/juju/agents/unit-swift-storage-z3-0/charm/hooks/install", line 91, in <module>
2014-08-29 13:52:58 INFO install main()
2014-08-29 13:52:58 INFO install File "/var/lib/juju/agents/unit-swift-storage-z3-0/charm/hooks/install", line 85, in main
2014-08-29 13:52:58 INFO install hooks.execute(sys.argv)
2014-08-29 13:52:58 INFO install File "/var/lib/juju/agents/unit-swift-storage-z3-0/charm/hooks/install", line 45, in install
2014-08-29 13:52:58 INFO install setup_storage()
2014-08-29 13:52:58 INFO install File "/var/lib/juju/agents/unit-swift-storage-z3-0/charm/hooks/swift_storage_utils.py", line 185, in setup_storage
2014-08-29 13:52:58 INFO install mkfs_xfs(dev)
2014-08-29 13:52:58 INFO install File "/var/lib/juju/agents/unit-swift-storage-z3-0/charm/hooks/swift_storage_utils.py", line 177, in mkfs_xfs
2014-08-29 13:52:58 INFO install check_call(cmd)
2014-08-29 13:52:58 INFO install File "/usr/lib/python2.7/subprocess.py", line 540, in check_call
2014-08-29 13:52:58 INFO install raise CalledProcessError(retcode, cmd)
2014-08-29 13:52:58 INFO install subprocess.CalledProcessError: Command '['mkfs.xfs', '-f', '-i', 'size=1024', u'/dev/vdb']' returned non-zero exit status 1
2014-08-29 13:52:58 ERROR juju.worker.uniter uniter.go:486 hook failed: exit status 1

[Edward Hope-Morley (hopem)]

Ok, this is easily reproducible if the device being formatted (a) has a filesystem on it and (b) is mounted. Question is, if the charm has been told to "overwrite", do we want the charm to unmount prior to reformat or just error out and notify the user that they need to unmount and re-run.

[Edward Hope-Morley (hopem)]

OK I just hit this error and I dont't think it is directly related to the swift-storage charm (I also saw it is the ceph charm on Utopic with 3.16.0-33-generic kernel when deploying to vms). This seems to be a result of some blockdev badness where by mkfs.xfs is trying to format a device that is not mounted or ostensibly in-use yet we still get an error saying that it is (possibly related to https://bugs.launchpad.net/charms/+source/swift-storage/+bug/1350049). Using /dev/vdb as the storage dev, the charm creates a partition then tries mkfs.xfs which exits with an error and "Device or resource busy" yet that device is not mounted or in use by anyone (according to lsof and fuser). I also tried partprobe which left a message saying that the new partition table could not be loaded since the device was in use. Neither dmesg nor /var/log/kern.log had logs to indicate what had happened and a reboot fixed the issue such that the partion table was loaded properly and I could continue with the install. This needs further investigation...

[Edward Hope-Morley (hopem)]

Another related issue - https://bugs.launchpad.net/charms/+source/ceph/+bug/1421701

[Chris Holcombe (xfactor973)]

I ran into this issue where mkfs.xfs and mount disagreed on whether something was mounted. mkfs doesn't trust mount and issues an ioctl to ask the kernel directly if something is mounted. I was never able to track down why there was a disagreement between mount and the kernel.

[James Page (james-page)]

The underlying problem is normally fairly easy to see:

  sudo lsof | grep vdb (or device causing problems)

One or more kernel procs will be left around for some reason, resulting the the device busy error messages.

[James Page (james-page)]

I'm marking this bug as invalid - I don't believe its actually a charm resolvable issue and relates to some sort of underlying issue in the kernel/xfs/mkfs tooling. I have seen this problem, but its not reliably reproducible and seemed related to a broken kernel at some point in time.

Given the amount of cycles we do without seeing this problem, I think it was a transient issue.