yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1773102] Re: Abnormal request id in logs

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: OpenStack Infra <1773102@xxxxxxxxxxxxxxxxxx>
Date: Mon, 06 Aug 2018 14:49:03 -0000
Reply-to: Bug 1773102 <1773102@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Reviewed:  https://review.openstack.org/587772
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=233ea582f7b58b3188bfa523264e9052eefd00e5
Submitter: Zuul
Branch:    master

commit 233ea582f7b58b3188bfa523264e9052eefd00e5
Author: Radoslav Gerganov <rgerganov@xxxxxxxxxx>
Date:   Wed Aug 1 13:54:31 2018 +0300

    Reload oslo_context after calling monkey_patch()
    
    oslo.context is storing a global thread-local variable which keeps the
    request context for the current thread. If oslo.context is imported
    before calling monkey_patch(), then this thread-local won't be green and
    instead of having one request per green thread, we will have one request
    object which will be overwritten every time when a new context is
    created.
    
    To workaround the problem, always reload oslo_context.context after
    calling monkey_patch() to make sure it uses green thread locals.
    
    Change-Id: Id059e5576c3fc78dd893fde15c963e182f1157f6
    Closes-Bug: #1773102


** Changed in: nova
       Status: In Progress => Fix Released

-- 
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):
  Fix Released
Status in OpenStack Compute (nova) pike series:
  Triaged
Status in OpenStack Compute (nova) queens series:
  Triaged

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
References

[Bug 1773102] [NEW] Abnormal request id in logs
From: yuanyue, 2018-05-24