Servers sometimes fail to startup in the gate with a permission denied

[Christopher Yeoh]

Sometimes servers fail to startup - intermittent gate/check bug

Example error:

2014-01-28 02:14:36.309 ERROR nova.scheduler.filter_scheduler [req-a617cb8a-4f34-42f9-a4a7-e951cf538219 InstanceActionsTestJSON-tempest-857832860-user InstanceActionsTestJSON-tempest-857832860-tenant] [instance: 0f9850c1-b5a8-4d62-98ab-11b04ba41165] Error from last host: devstack-precise-1390529664 (node devstack-precise-1390529664): [u'Traceback (most recent call last):
', u' File "/opt/stack/new/nova/nova/compute/manager.py", line 1068, in _build_instance
    set_access_ip=set_access_ip)
', u' File "/opt/stack/new/nova/nova/compute/manager.py", line 354, in decorated_function
    return function(self, context, *args, **kwargs)
', u' File "/opt/stack/new/nova/nova/compute/manager.py", line 1478, in _spawn
    LOG.exception(_(\'Instance failed to spawn\'), instance=instance)
', u' File "/opt/stack/new/nova/nova/openstack/common/excutils.py", line 68, in __exit__
    six.reraise(self.type_, self.value, self.tb)
', u' File "/opt/stack/new/nova/nova/compute/manager.py", line 1475, in _spawn
    block_device_info)
', u' File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 2187, in spawn
    admin_pass=admin_password)
', u' File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 2490, in _create_image
    project_id=instance[\'project_id\'])
', u' File "/opt/stack/new/nova/nova/virt/libvirt/imagebackend.py", line 180, in cache
    imagecache.refresh_timestamp(base)
', u' File "/opt/stack/new/nova/nova/virt/libvirt/imagecache.py", line 261, in refresh_timestamp
    inner_refresh_timestamp()
', u' File "/opt/stack/new/nova/nova/openstack/common/lockutils.py", line 249, in inner
    return f(*args, **kwargs)
', u' File "/opt/stack/new/nova/nova/virt/libvirt/imagecache.py", line 258, in inner_refresh_timestamp
    os.utime(base_file, None)
', u"OSError: [Errno 13] Permission denied: '/opt/stack/data/nova/instances/_base/307971e863bbda9ebaf13fcfedcb13498a5dbde6'
"]

From here:

http://logs.openstack.org/91/58191/4/check/check-tempest-dsvm-full/0dc8d4d/logs/screen-n-sch.txt.gz#_2014-01-28_02_14_36_309

[Sean Dague (sdague)]

This looks like a new issue that just showed up in the last 48hrs:

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiT1NFcnJvcjogW0Vycm5vIDEzXSBQZXJtaXNzaW9uIGRlbmllZDogJy9vcHQvc3RhY2svZGF0YS9ub3ZhL2luc3RhbmNlcy9fYmFzZVwiIiwiZmllbGRzIjpbXSwib2Zmc2V0IjowLCJ0aW1lZnJhbWUiOiI2MDQ4MDAiLCJncmFwaG1vZGUiOiJjb3VudCIsInRpbWUiOnsidXNlcl9pbnRlcnZhbCI6MH0sInN0YW1wIjoxMzkwOTU3NDQzNTczfQ==

Something changed with instance_cache that might have caused this?

[Sean Dague (sdague)]

Another fail here - http://logs.openstack.org/18/69218/2/check/check-tempest-dsvm-postgres-full/6e9684c/logs/screen-n-cpu.txt.gz#_2014-01-28_12_40_46_377

[Joe Gordon (jogo)]

It looks like this is the patch that introduced the bug:

https://review.openstack.org/#/c/61075/11

http://logs.openstack.org/75/61075/10/check/check-grenade-dsvm/8e06c1c/logs/new/screen-n-cpu.txt.gz?level=TRACE

[Lianhao Lu (lianhao-lu)]

I hit this failure also http://logs.openstack.org/13/62813/10/check/check-tempest-dsvm-full/dd4b617/logs/screen-n-cpu.txt.gz#_2014-01-29_05_34_41_421

[Joe Gordon (jogo)]

Fix: https://review.openstack.org/#/c/69773/