Public bug reported:
Description
===========
After VM creation, the request id related to periodic tasks in nova-compute.log
is changed to the same as the request id related to the VM creation task.
Steps to reproduce
==================
* nova boot xxx
* check the nova-compute.log on the compute node hosting the VM
* search the request id related to VM creation task
Expected result
===============
The request id related to periodic tasks should be different from the request
id related to VM creation task.
Actual result
=============
The request id related to periodic task is changed to the same as the request
id related to VM creation task after VM creation task is handled.
Environment
===========
1. OpenStack version
OS:
CentOS
nova version:
openstack-nova-compute-17.0.2-1.el7.noarch
2. hypervisor
Libvirt + QEMU
2. storage type
LVM
3. Which networking type did you use?
Neutron with Linuxbridge
Logs & Configs
==============
1. before nova-compute handling VM creation task:
2018-05-24 03:08:15.264 27469 DEBUG oslo_service.periodic_task
[req-c63d0555-7bf1-42da-abb7-556cc9eede8c 809cb6c22acc445c843db1a806d4e817
68b078adaf13420391fdb0fde1608816 - default default] Running periodic task
ComputeManager._reclaim_queued_deletes run_periodic_tasks
/usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:215
2018-05-24 03:08:15.265 27469 DEBUG nova.compute.manager
[req-c63d0555-7bf1-42da-abb7-556cc9eede8c 809cb6c22acc445c843db1a806d4e817
68b078adaf13420391fdb0fde1608816 - default default]
CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes
/usr/lib/python2.7/site-packages/nova/compute/manager.py:7238
2018-05-24 03:08:18.269 27469 DEBUG oslo_service.periodic_task
[req-c63d0555-7bf1-42da-abb7-556cc9eede8c 809cb6c22acc445c843db1a806d4e817
68b078adaf13420391fdb0fde1608816 - default default] Running periodic task
ComputeManager._sync_scheduler_instance_info run_periodic_tasks
/usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:215
2. begin to handle VM creation task:
2018-05-24 03:08:26.244 27469 DEBUG oslo_concurrency.lockutils
[req-2d5b3957-9749-40ba-9b94-e8260c7145bf 9de813eb53ba4ac982a37df462783d5d
3ce4f026aed1411baa6e8013b13f9257 - default default] Lock
"a0ded3b0-0e60-4d82-a516-588871c4917c" acquired by
"nova.compute.manager._locked_do_build_and_run_instance" :: waited 0.000s inner
/usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273
2018-05-24 03:08:26.312 27469 DEBUG oslo_service.periodic_task
[req-2d5b3957-9749-40ba-9b94-e8260c7145bf 9de813eb53ba4ac982a37df462783d5d
3ce4f026aed1411baa6e8013b13f9257 - default default] Running periodic task
ComputeManager._heal_instance_info_cache run_periodic_tasks
/usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:215
2018-05-24 03:08:26.312 27469 DEBUG nova.compute.manager
[req-2d5b3957-9749-40ba-9b94-e8260c7145bf 9de813eb53ba4ac982a37df462783d5d
3ce4f026aed1411baa6e8013b13f9257 - default default] Starting heal instance info
cache _heal_instance_info_cache
/usr/lib/python2.7/site-packages/nova/compute/manager.py:6572
2018-05-24 03:08:26.312 27469 DEBUG nova.compute.manager
[req-2d5b3957-9749-40ba-9b94-e8260c7145bf 9de813eb53ba4ac982a37df462783d5d
3ce4f026aed1411baa6e8013b13f9257 - default default] Rebuilding the list of
instances to heal _heal_instance_info_cache
/usr/lib/python2.7/site-packages/nova/compute/manager.py:6576
2018-05-24 03:08:26.334 27469 DEBUG nova.compute.manager
[req-2d5b3957-9749-40ba-9b94-e8260c7145bf 9de813eb53ba4ac982a37df462783d5d
3ce4f026aed1411baa6e8013b13f9257 - default default] Didn't find any instances
for network info cache update. _heal_instance_info_cache
/usr/lib/python2.7/site-packages/nova/compute/manager.py:6648
3. after handling VM creation task (request id is also changed for VM creation
task)
2018-05-24 03:08:40.896 27469 INFO nova.compute.manager
[req-18b1870e-239a-4adc-9962-40e63fffcda7 809cb6c22acc445c843db1a806d4e817
68b078adaf13420391fdb0fde1608816 - default default] [instance:
a0ded3b0-0e60-4d82-a516-588871c4917c] Took 14.34 seconds to build instance.
2018-05-24 03:08:41.278 27469 DEBUG oslo_concurrency.lockutils
[req-18b1870e-239a-4adc-9962-40e63fffcda7 809cb6c22acc445c843db1a806d4e817
68b078adaf13420391fdb0fde1608816 - default default] Lock
"a0ded3b0-0e60-4d82-a516-588871c4917c" released by
"nova.compute.manager._locked_do_build_and_run_instance" :: held 15.033s inner
/usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285
2018-05-24 03:08:42.267 27469 DEBUG oslo_service.periodic_task
[req-18b1870e-239a-4adc-9962-40e63fffcda7 809cb6c22acc445c843db1a806d4e817
68b078adaf13420391fdb0fde1608816 - default default] Running periodic task
ComputeManager._instance_usage_audit run_periodic_tasks
/usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:215
2018-05-24 03:09:04.264 27469 DEBUG oslo_service.periodic_task
[req-18b1870e-239a-4adc-9962-40e63fffcda7 809cb6c22acc445c843db1a806d4e817
68b078adaf13420391fdb0fde1608816 - default default] Running periodic task
ComputeManager.update_available_resource run_periodic_tasks
/usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:215
** Affects: nova
Importance: Undecided
Status: New
--
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1773102
Title:
Abnormal request id in logs
Status in OpenStack Compute (nova):
New
Bug description:
Description
===========
After VM creation, the request id related to periodic tasks in
nova-compute.log is changed to the same as the request id related to the VM
creation task.
Steps to reproduce
==================
* nova boot xxx
* check the nova-compute.log on the compute node hosting the VM
* search the request id related to VM creation task
Expected result
===============
The request id related to periodic tasks should be different from the request
id related to VM creation task.
Actual result
=============
The request id related to periodic task is changed to the same as the request
id related to VM creation task after VM creation task is handled.
Environment
===========
1. OpenStack version
OS:
CentOS
nova version:
openstack-nova-compute-17.0.2-1.el7.noarch
2. hypervisor
Libvirt + QEMU
2. storage type
LVM
3. Which networking type did you use?
Neutron with Linuxbridge
Logs & Configs
==============
1. before nova-compute handling VM creation task:
2018-05-24 03:08:15.264 27469 DEBUG oslo_service.periodic_task
[req-c63d0555-7bf1-42da-abb7-556cc9eede8c 809cb6c22acc445c843db1a806d4e817
68b078adaf13420391fdb0fde1608816 - default default] Running periodic task
ComputeManager._reclaim_queued_deletes run_periodic_tasks
/usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:215
2018-05-24 03:08:15.265 27469 DEBUG nova.compute.manager
[req-c63d0555-7bf1-42da-abb7-556cc9eede8c 809cb6c22acc445c843db1a806d4e817
68b078adaf13420391fdb0fde1608816 - default default]
CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes
/usr/lib/python2.7/site-packages/nova/compute/manager.py:7238
2018-05-24 03:08:18.269 27469 DEBUG oslo_service.periodic_task
[req-c63d0555-7bf1-42da-abb7-556cc9eede8c 809cb6c22acc445c843db1a806d4e817
68b078adaf13420391fdb0fde1608816 - default default] Running periodic task
ComputeManager._sync_scheduler_instance_info run_periodic_tasks
/usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:215
2. begin to handle VM creation task:
2018-05-24 03:08:26.244 27469 DEBUG oslo_concurrency.lockutils
[req-2d5b3957-9749-40ba-9b94-e8260c7145bf 9de813eb53ba4ac982a37df462783d5d
3ce4f026aed1411baa6e8013b13f9257 - default default] Lock
"a0ded3b0-0e60-4d82-a516-588871c4917c" acquired by
"nova.compute.manager._locked_do_build_and_run_instance" :: waited 0.000s inner
/usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273
2018-05-24 03:08:26.312 27469 DEBUG oslo_service.periodic_task
[req-2d5b3957-9749-40ba-9b94-e8260c7145bf 9de813eb53ba4ac982a37df462783d5d
3ce4f026aed1411baa6e8013b13f9257 - default default] Running periodic task
ComputeManager._heal_instance_info_cache run_periodic_tasks
/usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:215
2018-05-24 03:08:26.312 27469 DEBUG nova.compute.manager
[req-2d5b3957-9749-40ba-9b94-e8260c7145bf 9de813eb53ba4ac982a37df462783d5d
3ce4f026aed1411baa6e8013b13f9257 - default default] Starting heal instance info
cache _heal_instance_info_cache
/usr/lib/python2.7/site-packages/nova/compute/manager.py:6572
2018-05-24 03:08:26.312 27469 DEBUG nova.compute.manager
[req-2d5b3957-9749-40ba-9b94-e8260c7145bf 9de813eb53ba4ac982a37df462783d5d
3ce4f026aed1411baa6e8013b13f9257 - default default] Rebuilding the list of
instances to heal _heal_instance_info_cache
/usr/lib/python2.7/site-packages/nova/compute/manager.py:6576
2018-05-24 03:08:26.334 27469 DEBUG nova.compute.manager
[req-2d5b3957-9749-40ba-9b94-e8260c7145bf 9de813eb53ba4ac982a37df462783d5d
3ce4f026aed1411baa6e8013b13f9257 - default default] Didn't find any instances
for network info cache update. _heal_instance_info_cache
/usr/lib/python2.7/site-packages/nova/compute/manager.py:6648
3. after handling VM creation task (request id is also changed for VM
creation task)
2018-05-24 03:08:40.896 27469 INFO nova.compute.manager
[req-18b1870e-239a-4adc-9962-40e63fffcda7 809cb6c22acc445c843db1a806d4e817
68b078adaf13420391fdb0fde1608816 - default default] [instance:
a0ded3b0-0e60-4d82-a516-588871c4917c] Took 14.34 seconds to build instance.
2018-05-24 03:08:41.278 27469 DEBUG oslo_concurrency.lockutils
[req-18b1870e-239a-4adc-9962-40e63fffcda7 809cb6c22acc445c843db1a806d4e817
68b078adaf13420391fdb0fde1608816 - default default] Lock
"a0ded3b0-0e60-4d82-a516-588871c4917c" released by
"nova.compute.manager._locked_do_build_and_run_instance" :: held 15.033s inner
/usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285
2018-05-24 03:08:42.267 27469 DEBUG oslo_service.periodic_task
[req-18b1870e-239a-4adc-9962-40e63fffcda7 809cb6c22acc445c843db1a806d4e817
68b078adaf13420391fdb0fde1608816 - default default] Running periodic task
ComputeManager._instance_usage_audit run_periodic_tasks
/usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:215
2018-05-24 03:09:04.264 27469 DEBUG oslo_service.periodic_task
[req-18b1870e-239a-4adc-9962-40e63fffcda7 809cb6c22acc445c843db1a806d4e817
68b078adaf13420391fdb0fde1608816 - default default] Running periodic task
ComputeManager.update_available_resource run_periodic_tasks
/usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:215
To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1773102/+subscriptions
--
Mailing list: https://launchpad.net/~yahoo-eng-team
Post to : [email protected]
Unsubscribe : https://launchpad.net/~yahoo-eng-team
More help : https://help.launchpad.net/ListHelp
