2nd compute node can not start instances from shared nfs

[suibinz]

1) initially setup an all-in-one node that stores instance from an OpenIndiana ZFS sharnfs - works fine; (mount nfs on /var/lib/nova/instances)
2) start 2nd compute node to join the above node, with its own nfs storage, it works fine; (mounted a separate nfs on /var/lib/nova/instances)
3) but when changed 2nd node to mount the 1st node's shared nfs (with rw and root access), and start the instance, there seems to be some lock issue that cause permission denied:

(the set up of the nodes were according the to the "migration configuration" from the Grizzly admin guide (except that the shared nfs not running on the 1st node, but rather on an nfs share external to both nodes)

error from /var/lib/nova/nova-compute.log:

_________________________________________

013-07-11 10:17:45.204 AUDIT nova.compute.manager [req-6268bffe-cc09-47ed-a173-bb681645e34f 24477163d7ca46a38b9d45360a395d59 8db3509086494bc3a0a5174c26392bb1] [instance: 1e8a4a
80-fc46-4d67-ac51-7c3200494e37] Starting instance...
2013-07-11 10:17:45.532 AUDIT nova.compute.claims [req-6268bffe-cc09-47ed-a173-bb681645e34f 24477163d7ca46a38b9d45360a395d59 8db3509086494bc3a0a5174c26392bb1] [instance: 1e8a4a8
0-fc46-4d67-ac51-7c3200494e37] Attempting claim: memory 4096 MB, disk 40 GB, VCPUs 2
2013-07-11 10:17:45.533 AUDIT nova.compute.claims [req-6268bffe-cc09-47ed-a173-bb681645e34f 24477163d7ca46a38b9d45360a395d59 8db3509086494bc3a0a5174c26392bb1] [instance: 1e8a4a8
0-fc46-4d67-ac51-7c3200494e37] Total Memory: 32173 MB, used: 31232 MB
2013-07-11 10:17:45.534 AUDIT nova.compute.claims [req-6268bffe-cc09-47ed-a173-bb681645e34f 24477163d7ca46a38b9d45360a395d59 8db3509086494bc3a0a5174c26392bb1] [instance: 1e8a4a8
0-fc46-4d67-ac51-7c3200494e37] Memory limit: 48259 MB, free: 17027 MB
2013-07-11 10:17:45.534 AUDIT nova.compute.claims [req-6268bffe-cc09-47ed-a173-bb681645e34f 24477163d7ca46a38b9d45360a395d59 8db3509086494bc3a0a5174c26392bb1] [instance: 1e8a4a8
0-fc46-4d67-ac51-7c3200494e37] Total Disk: 400 GB, used: 210 GB
2013-07-11 10:17:45.534 AUDIT nova.compute.claims [req-6268bffe-cc09-47ed-a173-bb681645e34f 24477163d7ca46a38b9d45360a395d59 8db3509086494bc3a0a5174c26392bb1] [instance: 1e8a4a8
0-fc46-4d67-ac51-7c3200494e37] Disk limit not specified, defaulting to unlimited
2013-07-11 10:17:45.535 AUDIT nova.compute.claims [req-6268bffe-cc09-47ed-a173-bb681645e34f 24477163d7ca46a38b9d45360a395d59 8db3509086494bc3a0a5174c26392bb1] [instance: 1e8a4a8
0-fc46-4d67-ac51-7c3200494e37] Total CPU: 16 VCPUs, used: 24 VCPUs
2013-07-11 10:17:45.535 AUDIT nova.compute.claims [req-6268bffe-cc09-47ed-a173-bb681645e34f 24477163d7ca46a38b9d45360a395d59 8db3509086494bc3a0a5174c26392bb1] [instance: 1e8a4a8
0-fc46-4d67-ac51-7c3200494e37] CPU limit not specified, defaulting to unlimited
2013-07-11 10:17:45.536 AUDIT nova.compute.claims [req-6268bffe-cc09-47ed-a173-bb681645e34f 24477163d7ca46a38b9d45360a395d59 8db3509086494bc3a0a5174c26392bb1] [instance: 1e8a4a8
0-fc46-4d67-ac51-7c3200494e37] Claim successful
2013-07-11 10:18:21.587 INFO nova.virt.libvirt.driver [req-6268bffe-cc09-47ed-a173-bb681645e34f 24477163d7ca46a38b9d45360a395d59 8db3509086494bc3a0a5174c26392bb1] [instance: 1e8
a4a80-fc46-4d67-ac51-7c3200494e37] Creating image
2013-07-11 10:18:21.643 ERROR nova.compute.manager [req-6268bffe-cc09-47ed-a173-bb681645e34f 24477163d7ca46a38b9d45360a395d59 8db3509086494bc3a0a5174c26392bb1] [instance: 1e8a4a
80-fc46-4d67-ac51-7c3200494e37] Instance failed to spawn
2013-07-11 10:18:21.643 5035 TRACE nova.compute.manager [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] Traceback (most recent call last):
2013-07-11 10:18:21.643 5035 TRACE nova.compute.manager [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line
1103, in _spawn
2013-07-11 10:18:21.643 5035 TRACE nova.compute.manager [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] block_device_info)
2013-07-11 10:18:21.643 5035 TRACE nova.compute.manager [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", l
ine 1521, in spawn
2013-07-11 10:18:21.643 5035 TRACE nova.compute.manager [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] admin_pass=admin_password)
2013-07-11 10:18:21.643 5035 TRACE nova.compute.manager [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", l
ine 1807, in _create_image
2013-07-11 10:18:21.643 5035 TRACE nova.compute.manager [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] project_id=instance['project_id'])
2013-07-11 10:18:21.643 5035 TRACE nova.compute.manager [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/imagebackend.
py", line 158, in cache
2013-07-11 10:18:21.643 5035 TRACE nova.compute.manager [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] *args, **kwargs)
2013-07-11 10:18:21.643 5035 TRACE nova.compute.manager [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/imagebackend.
py", line 268, in create_image
2013-07-11 10:18:21.643 5035 TRACE nova.compute.manager [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] copy_qcow2_image(base, self.path, size)
2013-07-11 10:18:21.643 5035 TRACE nova.compute.manager [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] File "/usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils
.py", line 221, in inner
2013-07-11 10:18:21.643 5035 TRACE nova.compute.manager [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] with lock:
2013-07-11 10:18:21.643 5035 TRACE nova.compute.manager [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] File "/usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils
.py", line 75, in __enter__
2013-07-11 10:18:21.643 5035 TRACE nova.compute.manager [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] self.lockfile = open(self.fname, 'w')
2013-07-11 10:18:21.643 5035 TRACE nova.compute.manager [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] IOError: [Errno 13] Permission denied: '/var/lib/nova/instances/locks/no
va-_var_lib_nova_instances__base_d999ce594902d400ad6dd53cde02760823176f48'
2013-07-11 10:18:21.643 5035 TRACE nova.compute.manager [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37]
2013-07-11 10:18:21.820 AUDIT nova.compute.manager [req-6268bffe-cc09-47ed-a173-bb681645e34f 24477163d7ca46a38b9d45360a395d59 8db3509086494bc3a0a5174c26392bb1] [instance: 1e8a4a
80-fc46-4d67-ac51-7c3200494e37] Terminating instance
2013-07-11 10:18:36.123 5035 ERROR nova.virt.libvirt.driver [-] [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] During wait destroy, instance disappeared.
2013-07-11 10:18:36.261 ERROR nova.virt.libvirt.vif [req-6268bffe-cc09-47ed-a173-bb681645e34f 24477163d7ca46a38b9d45360a395d59 8db3509086494bc3a0a5174c26392bb1] [instance: 1e8a4
a80-fc46-4d67-ac51-7c3200494e37] Failed while unplugging vif
2013-07-11 10:18:36.261 5035 TRACE nova.virt.libvirt.vif [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] Traceback (most recent call last):
2013-07-11 10:18:36.261 5035 TRACE nova.virt.libvirt.vif [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/vif.py", lin
e 442, in unplug_ovs_hybrid
2013-07-11 10:18:36.261 5035 TRACE nova.virt.libvirt.vif [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] utils.execute('brctl', 'delif', br_name, v1_name, run_as_root=True)
2013-07-11 10:18:36.261 5035 TRACE nova.virt.libvirt.vif [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] File "/usr/lib/python2.7/dist-packages/nova/utils.py", line 239, in e
xecute
2013-07-11 10:18:36.261 5035 TRACE nova.virt.libvirt.vif [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] cmd=' '.join(cmd))
2013-07-11 10:18:36.261 5035 TRACE nova.virt.libvirt.vif [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] ProcessExecutionError: Unexpected error while running command.
2013-07-11 10:18:36.261 5035 TRACE nova.virt.libvirt.vif [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] Command: sudo nova-rootwrap /etc/nova/rootwrap.conf brctl delif qbr2723
e4a7-a3 qvb2723e4a7-a3
2013-07-11 10:18:36.261 5035 TRACE nova.virt.libvirt.vif [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] Exit code: 1
2013-07-11 10:18:36.261 5035 TRACE nova.virt.libvirt.vif [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] Stdout: ''
2013-07-11 10:18:36.261 5035 TRACE nova.virt.libvirt.vif [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37] Stderr: 'interface qvb2723e4a7-a3 does not exist!\n'
2013-07-11 10:18:36.261 5035 TRACE nova.virt.libvirt.vif [instance: 1e8a4a80-fc46-4d67-ac51-7c3200494e37]
2013-07-11 10:18:36.265 INFO nova.virt.libvirt.driver [req-6268bffe-cc09-47ed-a173-bb681645e34f 24477163d7ca46a38b9d45360a395d59 8db3509086494bc3a0a5174c26392bb1] [instance: 1e8
a4a80-fc46-4d67-ac51-7c3200494e37] Deleting instance files /var/lib/nova/instances/1e8a4a80-fc46-4d67-ac51-7c3200494e37
2013-07-11 10:18:36.606 ERROR nova.compute.manager [req-6268bffe-cc09-47ed-a173-bb681645e34f 24477163d7ca46a38b9d45360a395d59 8db3509086494bc3a0a5174c26392bb1] [instance: 1e8a4a
80-fc46-4d67-ac51-7c3200494e37] Error: ['Traceback (most recent call last):\n', ' File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 848, in _run_instance\n
   set_access_ip=set_access_ip)\n', ' File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 1107, in _spawn\n LOG.exception(_(\'Instance failed to spawn\'),
instance=instance)\n', ' File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__\n self.gen.next()\n', ' File "/usr/lib/python2.7/dist-packages/nova/compute/manager.p
y", line 1103, in _spawn\n block_device_info)\n', ' File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 1521, in spawn\n admin_pass=admin_password)\
n', ' File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 1807, in _create_image\n project_id=instance[\'project_id\'])\n', ' File "/usr/lib/python2.7
/dist-packages/nova/virt/libvirt/imagebackend.py", line 158, in cache\n *args, **kwargs)\n', ' File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/imagebackend.py", lin
e 268, in create_image\n copy_qcow2_image(base, self.path, size)\n', ' File "/usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py", line 221, in inner\n wi
th lock:\n', ' File "/usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py", line 75, in __enter__\n self.lockfile = open(self.fname, \'w\')\n', "IOError: [Err
no 13] Permission denied: '/var/lib/nova/instances/locks/nova-_var_lib_nova_instances__base_d999ce594902d400ad6dd53cde02760823176f48'\n"]

[Michael Still (mikal)]

Can you please confirm that the "locks" subdirectory for /var/lib/nova/instances exists and has permissions that allow files to be created by the nova user? Perhaps try using "touch" to test?

Thanks.

[suibinz (suibin)]

here is the permission on /var/lib/nova/instances/locks:
drwxr-xr-x+ 2 nova nova 37 Jul 23 14:05 locks

the files permissions in locks sub-directory are
rw-r--r--

[Jeremy Brisko (jeremy-brisko)]

I am having this same issue. Just upgraded a working Folsom environment to Grizzly. Everything is working great on my main node, however the 2nd node cannot create or migrate VM's receiving the same error accessing files in the locks directory. I have tried to adjust permissions on the directory with no luck. Did you solve this problem? Is there something I'm overlooking?

Thanks!

[Matt Riedemann (mriedem)]

One thing I've seen before (working with installing rpms via yum on RHEL/CentOS/Fedora type systems) and following the admin guide is that if the database migration logs anything and the log files don't exist, they will get created by the root user and then when you run the nova services the nova user (created by the rpms) doesn't have write access to the log files and it bombs out. I've seen that on other components too like glance and keystone.

[Rafael Folco (rafaelfolco)]

Ownership has changed. Check these two directories:

/var/lib/nova/instances
/var/log/nova

You can fix this by changing ownership to nova.nova.
e.g.: # chown nova.nova /var/log/nova/nova-manage.log

In my case I've noticed that nova-manage.log had 0 bytes and root owned it. My locks dir was also belonging to root as well.

Credits to mriedem for the tip.

[Mohamed (melshabka)]

I have the same problem and checked issue for:

/var/lib/nova/instances/locks
/var/lib/nova/instances
/var/log/nova

it still gives
Unable to acquire lock on `/var/lib/nova/instances/locks/nova-cec2749287b7ac885d353d348d5ab713141c4d36` due to [Errno 37] No locks available