I tried to run functional tests of nova-compute charm on ServerStack.
gate-basic-bionic-stein and gate-basic-bionic-rocky work. But dev-basic-cosmic-rocky and dev-basic-disco-stein failed
Revision used to reproduce:
ubuntu@nova-compute-tests-approach:~/nova-compute/tests$ git show HEAD
commit 4e9bcbc28b9e7dca66c9b22d886ac5c1979eb73e (HEAD -> master, origin/master, origin/HEAD)
Merge: a076963 599245b
Author: Zuul <email address hidden>
Date: Fri May 3 14:38:09 2019 +0000
Merge "config: add notification-format option"
Local changes to tox.ini:
ubuntu@nova-compute-tests-approach:~/nova-compute$ git diff tox.ini
diff --git a/tox.ini b/tox.ini
index 8b80e0f..6c1a0f3 100644
--- a/tox.ini
+++ b/tox.ini
@@ -5,6 +5,8 @@
envlist = pep8,py27,py35,py36
skipsdist = True
skip_missing_interpreters = True
+toxworkdir=/tmp/.tox
+
[testenv]
setenv = VIRTUAL_ENV={envdir}
@@ -96,7 +98,7 @@ basepython = python2.7
deps = -r{toxinidir}/requirements.txt
-r{toxinidir}/test-requirements.txt
commands =
- bundletester -vl DEBUG -r json -o func-results.json gate-basic-bionic-rocky --no-destroy
+ bundletester -vl DEBUG -r json -o func-results.json dev-basic-disco-stein --no-destroy
[testenv:func27-dfs]
# Charm Functional Test
Then run:
ubuntu@nova-compute-tests-approach:~/nova-compute$ tox -e func27-smoke
...
After a while juju status shows error in nova-compute/0 unit
...
nova-compute/0* error idle 5 10.5.0.19 hook failed: "config-changed"
...
ubuntu@nova-compute-tests-approach:~$ juju debug-log --include nova-compute --lines 50 | grep config-changed
unit-nova-compute-0: 20:04:34 DEBUG unit.nova-compute/0.config-changed ERROR no relation id specified
unit-nova-compute-0: 20:04:34 DEBUG unit.nova-compute/0.config-changed none
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed Setting /etc/apparmor.d/usr.bin.nova-compute to enforce mode.
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed mkfs.xfs: cannot open /dev/vdb: Device or resource busy
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed Traceback (most recent call last):
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed File "/var/lib/juju/agents/unit-nova-compute-0/charm/hooks/config-changed", line 654, in <module>
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed main()
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed File "/var/lib/juju/agents/unit-nova-compute-0/charm/hooks/config-changed", line 647, in main
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed hooks.execute(sys.argv)
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed File "/var/lib/juju/agents/unit-nova-compute-0/charm/hooks/charmhelpers/core/hookenv.py", line 914, in execute
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed self._hooks[hook_name]()
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed File "/var/lib/juju/agents/unit-nova-compute-0/charm/hooks/charmhelpers/contrib/openstack/utils.py", line 1546, in wrapped_f
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed stopstart, restart_functions)
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed File "/var/lib/juju/agents/unit-nova-compute-0/charm/hooks/charmhelpers/core/host.py", line 741, in restart_on_change_helper
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed r = lambda_f()
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed File "/var/lib/juju/agents/unit-nova-compute-0/charm/hooks/charmhelpers/contrib/openstack/utils.py", line 1545, in <lambda>
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed (lambda: f(*args, **kwargs)), __restart_map_cache['cache'],
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed File "/var/lib/juju/agents/unit-nova-compute-0/charm/hooks/charmhelpers/contrib/hardening/harden.py", line 93, in _harden_inner2
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed return f(*args, **kwargs)
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed File "/var/lib/juju/agents/unit-nova-compute-0/charm/hooks/config-changed", line 259, in config_changed
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed configure_local_ephemeral_storage()
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed File "/var/lib/juju/agents/unit-nova-compute-0/charm/hooks/nova_compute_utils.py", line 1002, in configure_local_ephemeral_storage
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed mkfs_xfs(dev, force=True)
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed File "/var/lib/juju/agents/unit-nova-compute-0/charm/hooks/charmhelpers/contrib/storage/linux/utils.py", line 126, in mkfs_xfs
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed check_call(cmd)
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed File "/usr/lib/python3.7/subprocess.py", line 347, in check_call
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed raise CalledProcessError(retcode, cmd)
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed subprocess.CalledProcessError: Command '['mkfs.xfs', '-f', '-i', 'size=1024', '/dev/vdb']' returned non-zero exit status 1.
unit-nova-compute-0: 20:04:37 ERROR juju.worker.uniter.operation hook "config-changed" failed: exit status 1
unit-nova-compute-0: 20:04:37 INFO juju.worker.uniter awaiting error resolution for "config-changed" hook
unit-nova-compute-0: 20:05:15 INFO juju.worker.uniter awaiting error resolution for "config-changed" hook
Now the problem is clearer:
unit-nova-compute-0: 20:04:37 DEBUG unit.nova-compute/0.config-changed mkfs.xfs: cannot open /dev/vdb: Device or resource busy
caused by executing
mkfs.xfs -f -i size=1024 /dev/vdb
Need to go inside and take a closer look:
ubuntu@nova-compute-tests-approach:~$ juju ssh nova-compute/0
ubuntu@juju-12e7f5-default-5:~$ lsblk
NAME MAJ:MIN RM SIZE RO TYPE MOUNTPOINT
loop0 7:0 0 89.3M 1 loop /snap/core/6673
loop1 7:1 0 53.9M 1 loop /snap/lxd/10601
vda 252:0 0 15G 0 disk
├─vda1 252:1 0 14.9G 0 part /
├─vda14 252:14 0 4M 0 part
└─vda15 252:15 0 106M 0 part /boot/efi
vdb 252:16 0 15G 0 disk
vdc 252:32 0 4G 0 disk [SWAP]
We have vdb of 15G in size.
ubuntu@juju-12e7f5-default-5:~$ sudo mkfs.xfs -f -i size=1024 /dev/vdb
mkfs.xfs: cannot open /dev/vdb: Device or resource busy
Command still fails. Checking dmesg: There was an attempt to mount vdb as EXT4 during early boot:
ubuntu@juju-12e7f5-default-5:~$ sudo dmesg -T | grep vdb
[Tue Apr 30 19:43:33 2019] virtio_blk virtio2: [vdb] 31457280 512-byte logical blocks (16.1 GB/15.0 GiB)
[Tue Apr 30 19:43:51 2019] EXT4-fs (vdb): mounted filesystem with ordered data mode. Opts: (null)
ubuntu@juju-12e7f5-default-5:~$ sudo umount /dev/vdb
umount: /dev/vdb: not mounted.
root@juju-12e7f5-default-5:/dev/mapper# lsblk -P
NAME="loop0" MAJ:MIN="7:0" RM="0" SIZE="89.3M" RO="1" TYPE="loop" MOUNTPOINT="/snap/core/6673"
NAME="loop1" MAJ:MIN="7:1" RM="0" SIZE="53.9M" RO="1" TYPE="loop" MOUNTPOINT="/snap/lxd/10601"
NAME="vda" MAJ:MIN="252:0" RM="0" SIZE="15G" RO="0" TYPE="disk" MOUNTPOINT=""
NAME="vda1" MAJ:MIN="252:1" RM="0" SIZE="14.9G" RO="0" TYPE="part" MOUNTPOINT="/"
NAME="vda14" MAJ:MIN="252:14" RM="0" SIZE="4M" RO="0" TYPE="part" MOUNTPOINT=""
NAME="vda15" MAJ:MIN="252:15" RM="0" SIZE="106M" RO="0" TYPE="part" MOUNTPOINT="/boot/efi"
NAME="vdb" MAJ:MIN="252:16" RM="0" SIZE="15G" RO="0" TYPE="disk" MOUNTPOINT=""
NAME="vdc" MAJ:MIN="252:32" RM="0" SIZE="4G" RO="0" TYPE="disk" MOUNTPOINT="[SWAP]"
Though it still seems to be used by kernel:
ubuntu@juju-12e7f5-default-5:/var/log$ sudo lsof | grep vdb
jbd2/vdb- 679 root cwd DIR 252,1 4096 2 /
jbd2/vdb- 679 root rtd DIR 252,1 4096 2 /
jbd2/vdb- 679 root txt unknown /proc/679/exe
Similar (but old) issue: https://bugzilla.redhat.com/show_bug.cgi?id=851970
Tail of tox -e output: 2019-05- 07 13:04:09 Config specifies num units for subordinate: neutron-openvswitch 2019-05- 07 13:09:38 The following units had errors: 2019-05- 07 13:09:38 Deployment stopped. run time: 358.56 Traceback (most recent call last): ter-ms0ttD/ nova-compute/ tests/dev- basic-cosmic- rocky", line 22, in <module> ment(series= 'cosmic' ) ter-ms0ttD/ nova-compute/ tests/basic_ deployment. py", line 63, in __init__ tox/func27- smoke/local/ lib/python2. 7/site- packages/ charmhelpers/ contrib/ amulet/ deployment. py", line 85, in _deploy setup(timeout= timeout) tox/func27- smoke/local/ lib/python2. 7/site- packages/ amulet/ deployer. py", line 714, in setup check_call( shlex.split( cmd)) python2. 7/subprocess. py", line 190, in check_call ror(retcode, cmd) subprocess. CalledProcessEr ror: Command '['juju-deployer', '-W', '-c', '/tmp/amulet- juju-deployer- _BTSPR/ deployer- schema. json', '-e', 'nickv- tenant- serverstack: admin/default' , '-t', '5500', 'nickv- tenant- serverstack: admin/default' ]' returned non-zero exit status 1 ter.utils: Updating JUJU_MODEL: "nickv- tenant- serverstack: admin/default" -> "" ter.fetchers: git rev-parse HEAD: 4e9bcbc28b9e7dc a66c9b22d886ac5 c1979eb73e
....
DEBUG:runner:
DEBUG:runner:
DEBUG:runner: unit: nova-compute/0: machine: 5 agent-state: error details: hook failed: "config-changed"
DEBUG:runner:
DEBUG:runner:
DEBUG:runner: File "/tmp/bundletes
DEBUG:runner: deployment = NovaBasicDeploy
DEBUG:runner: File "/tmp/bundletes
DEBUG:runner: self._deploy()
DEBUG:runner: File "/tmp/.
DEBUG:runner: self.d.
DEBUG:runner: File "/tmp/.
DEBUG:runner: subprocess.
DEBUG:runner: File "/usr/lib/
DEBUG:runner: raise CalledProcessEr
DEBUG:runner:
DEBUG:runner:Exit Code: 1
DEBUG:bundletes
DEBUG:bundletes
ERROR: InvocationError: '/tmp/. tox/func27- smoke/bin/ bundletester -vl DEBUG -r json -o func-results.json dev-basic- cosmic- rocky --no-destroy'