R3.2.1.0-build22:vm creation fails with nova errors

[sundarkh]

1) Provision of targets using SM gets completed successfully R3.2.1.0-build22 centos ;
2) creation of vm fails with following error

nova compute log on compute node
----------------------------------

017-02-08 05:23:30.214 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] image 4ba401b2-901c-4b06-901a-9e3052215023 at (/var/lib/nova/instances/_base/d9422a6e0726be0121bbf63af4875dcbf6dc74f4): checking
2017-02-08 05:23:30.215 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] image 4ba401b2-901c-4b06-901a-9e3052215023 at (/var/lib/nova/instances/_base/d9422a6e0726be0121bbf63af4875dcbf6dc74f4): in use: on this node 1 local, 0 on other nodes sharing this instance storage
2017-02-08 05:23:30.277 3792 WARNING nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Unknown base file: /var/lib/nova/instances/_base/b18bc96dbe73cb24156f0deacf66b9f964ad4fc5
2017-02-08 05:23:30.277 3792 WARNING nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Unknown base file: /var/lib/nova/instances/_base/7029c5b5cbcbc5cbf33060b5cef6ecaedf8cc820
2017-02-08 05:23:30.278 3792 WARNING nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Unknown base file: /var/lib/nova/instances/_base/de48e783d6872c05cfa662f5edc05d200868b4a8
2017-02-08 05:23:30.278 3792 WARNING nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Unknown base file: /var/lib/nova/instances/_base/04279776b86bd2121bf8fb996202a327599fe954
2017-02-08 05:23:30.278 3792 WARNING nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Unknown base file: /var/lib/nova/instances/_base/c0a1fdca392bc19110460c586c31ec708cb181f6
2017-02-08 05:23:30.278 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Active base files: /var/lib/nova/instances/_base/d9422a6e0726be0121bbf63af4875dcbf6dc74f4
2017-02-08 05:23:30.279 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Removable base files: /var/lib/nova/instances/_base/b18bc96dbe73cb24156f0deacf66b9f964ad4fc5 /var/lib/nova/instances/_base/7029c5b5cbcbc5cbf33060b5cef6ecaedf8cc820 /var/lib/nova/instances/_base/de48e783d6872c05cfa662f5edc05d200868b4a8 /var/lib/nova/instances/_base/04279776b86bd2121bf8fb996202a327599fe954 /var/lib/nova/instances/_base/c0a1fdca392bc19110460c586c31ec708cb181f6
2017-02-08 05:23:30.279 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Base or swap file too young to remove: /var/lib/nova/instances/_base/b18bc96dbe73cb24156f0deacf66b9f964ad4fc5
2017-02-08 05:23:30.279 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Base or swap file too young to remove: /var/lib/nova/instances/_base/7029c5b5cbcbc5cbf33060b5cef6ecaedf8cc820
2017-02-08 05:23:30.280 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Base or swap file too young to remove: /var/lib/nova/instances/_base/de48e783d6872c05cfa662f5edc05d200868b4a8
2017-02-08 05:23:30.280 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Base or swap file too young to remove: /var/lib/nova/instances/_base/04279776b86bd2121bf8fb996202a327599fe954
2017-02-08 05:23:30.280 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Base or swap file too young to remove: /var/lib/nova/instances/_base/c0a1fdca392bc19110460c586c31ec708cb181f6
2017-02-08 05:23:36.297 3792 INFO nova.compute.resource_tracker [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Auditing locally available compute resources for node nodec57.englab.juniper.net
2017-02-08 05:23:36.379 3792 INFO nova.compute.resource_tracker [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Total usable vcpus: 4, total allocated vcpus: 0
2017-02-08 05:23:36.379 3792 INFO nova.compute.resource_tracker [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Final resource view: name=nodec57.englab.juniper.net phys_ram=32021MB used_ram=1024MB phys_disk=630GB used_disk=1GB total_vcpus=4 used_vcpus=0 pci_stats=None
2017-02-08 05:23:36.406 3792 INFO nova.compute.resource_tracker [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Compute_service record updated for nodec57:nodec57.englab.juniper.net
2017-02-08 05:24:31.208 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] image 4ba401b2-901c-4b06-901a-9e3052215023 at (/var/lib/nova/instances/_base/d9422a6e0726be0121bbf63af4875dcbf6dc74f4): checking
2017-02-08 05:24:31.209 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] image 4ba401b2-901c-4b06-901a-9e3052215023 at (/var/lib/nova/instances/_base/d9422a6e0726be0121bbf63af4875dcbf6dc74f4): in use: on this node 1 local, 0 on other nodes sharing this instance storage
2017-02-08 05:24:31.269 3792 WARNING nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Unknown base file: /var/lib/nova/instances/_base/b18bc96dbe73cb24156f0deacf66b9f964ad4fc5
2017-02-08 05:24:31.270 3792 WARNING nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Unknown base file: /var/lib/nova/instances/_base/7029c5b5cbcbc5cbf33060b5cef6ecaedf8cc820
2017-02-08 05:24:31.270 3792 WARNING nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Unknown base file: /var/lib/nova/instances/_base/de48e783d6872c05cfa662f5edc05d200868b4a8
2017-02-08 05:24:31.270 3792 WARNING nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Unknown base file: /var/lib/nova/instances/_base/04279776b86bd2121bf8fb996202a327599fe954
2017-02-08 05:24:31.271 3792 WARNING nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Unknown base file: /var/lib/nova/instances/_base/c0a1fdca392bc19110460c586c31ec708cb181f6
2017-02-08 05:24:31.271 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Active base files: /var/lib/nova/instances/_base/d9422a6e0726be0121bbf63af4875dcbf6dc74f4
2017-02-08 05:24:31.271 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Removable base files: /var/lib/nova/instances/_base/b18bc96dbe73cb24156f0deacf66b9f964ad4fc5 /var/lib/nova/instances/_base/7029c5b5cbcbc5cbf33060b5cef6ecaedf8cc820 /var/lib/nova/instances/_base/de48e783d6872c05cfa662f5edc05d200868b4a8 /var/lib/nova/instances/_base/04279776b86bd2121bf8fb996202a327599fe954 /var/lib/nova/instances/_base/c0a1fdca392bc19110460c586c31ec708cb181f6
2017-02-08 05:24:31.272 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Base or swap file too young to remove: /var/lib/nova/instances/_base/b18bc96dbe73cb24156f0deacf66b9f964ad4fc5
2017-02-08 05:24:31.272 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Base or swap file too young to remove: /var/lib/nova/instances/_base/7029c5b5cbcbc5cbf33060b5cef6ecaedf8cc820
2017-02-08 05:24:31.272 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Base or swap file too young to remove: /var/lib/nova/instances/_base/de48e783d6872c05cfa662f5edc05d200868b4a8
2017-02-08 05:24:31.272 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Base or swap file too young to remove: /var/lib/nova/instances/_base/04279776b86bd2121bf8fb996202a327599fe954
2017-02-08 05:24:31.273 3792 INFO nova.virt.libvirt.imagecache [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Base or swap file too young to remove: /var/lib/nova/instances/_base/c0a1fdca392bc19110460c586c31ec708cb181f6
2017-02-08 05:24:36.290 3792 INFO nova.compute.resource_tracker [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Auditing locally available compute resources for node nodec57.englab.juniper.net
2017-02-08 05:24:36.377 3792 INFO nova.compute.resource_tracker [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Total usable vcpus: 4, total allocated vcpus: 0
2017-02-08 05:24:36.378 3792 INFO nova.compute.resource_tracker [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Final resource view: name=nodec57.englab.juniper.net phys_ram=32021MB used_ram=1024MB phys_disk=630GB used_disk=1GB total_vcpus=4 used_vcpus=0 pci_stats=None
2017-02-08 05:24:36.406 3792 INFO nova.compute.resource_tracker [req-a23e6506-eae5-4be0-9ff1-07c09fe3a0c0 - - - - -] Compute_service record updated for nodec57:nodec57.englab.juniper.net
^C
[root@nodec57 ~]#

nova-scheduler log(OPenstack node)
-----------------------------------

2017-02-08 05:14:38.835 1045 DEBUG oslo_service.periodic_task [req-f4407d2d-82b9-4369-9f28-1a1bd5b18a8a - - - - -] Running periodic task SchedulerManager._run_periodic_tasks run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213
2017-02-08 05:14:44.215 1045 DEBUG oslo_concurrency.lockutils [req-b87e7469-3207-44fc-afc3-fb1789f23b1c - - - - -] Lock "host_instance" acquired by "nova.scheduler.host_manager.sync_instance_info" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:253
2017-02-08 05:14:44.215 1045 INFO nova.scheduler.host_manager [req-b87e7469-3207-44fc-afc3-fb1789f23b1c - - - - -] Successfully synced instances from host 'nodec57'.
2017-02-08 05:14:44.215 1045 DEBUG oslo_concurrency.lockutils [req-b87e7469-3207-44fc-afc3-fb1789f23b1c - - - - -] Lock "host_instance" released by "nova.scheduler.host_manager.sync_instance_info" :: held 0.001s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:265
2017-02-08 05:14:55.514 1045 DEBUG oslo_service.periodic_task [req-f4407d2d-82b9-4369-9f28-1a1bd5b18a8a - - - - -] Running periodic task SchedulerManager._expire_reservations run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213
2017-02-08 05:15:04.666 1045 DEBUG oslo.messaging._drivers.impl_rabbit [-] Received recoverable error from kombu: on_error /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/impl_rabbit.py:615
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit Traceback (most recent call last):
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/site-packages/kombu/connection.py", line 436, in _ensured
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit return fun(*args, **kwargs)
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/site-packages/kombu/connection.py", line 508, in __call__
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit return fun(*args, channel=channels[0], **kwargs), channels[0]
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/impl_rabbit.py", line 664, in execute_method
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit method()
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/impl_rabbit.py", line 890, in _consume
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit self.connection.drain_events(timeout=poll_timeout)
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/site-packages/kombu/connection.py", line 275, in drain_events
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit return self.transport.drain_events(self.connection, **kwargs)
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/site-packages/kombu/transport/pyamqp.py", line 95, in drain_events
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit return connection.drain_events(**kwargs)
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/site-packages/amqp/connection.py", line 302, in drain_events
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit chanmap, None, timeout=timeout,
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/site-packages/amqp/connection.py", line 365, in _wait_multiple
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit channel, method_sig, args, content = read_timeout(timeout)
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/site-packages/amqp/connection.py", line 336, in read_timeout
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit return self.method_reader.read_method()
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/site-packages/amqp/method_framing.py", line 189, in read_method
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit raise m
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2017-02-08 05:15:04.666 1045 ERROR oslo.messaging._drivers.impl_rabbit
2017-02-08 05:15:04.667 1045 ERROR oslo.messaging._drivers.impl_rabbit [-] AMQP server 192.168.100.4:5672 closed the connection. Check login credentials: Socket closed
2017-02-08 05:15:05.685 1045 INFO oslo.messaging._drivers.impl_rabbit [-] Reconnected to AMQP server on 192.168.100.4:5672

[Senthilnathan Murugappan (msenthil)]

there are two options to resolve the issue. Both are as below.
Soln1: is the deprecated mode where in admin_auth_url didn’t have v2.0 set under neutron section
Soln2: is the new way going forward where one has to specify auth_plugin to use and username was missing too.

[root@nodeh8 ~]# diff /etc/nova/nova.conf.soln.1 /etc/nova/nova.conf.bk
2715c2715
< admin_auth_url=http://10.204.217.112:35357/v2.0
---
> admin_auth_url=http://10.204.217.112:35357/

[root@nodeh8 ~]# diff /etc/nova/nova.conf.soln.2 /etc/nova/nova.conf.bk
2741c2741
< auth_plugin=password
---
> #auth_plugin=<None>
2805c2805
< username=neutron
---
> #username=<None>
2809a2810
>