flow.rst

Nova server boot flow

openstack server  create --image=u16 --key-name=pub --flavor=m1.small ubuntu1

OpenStack Client looks up flavor id:

May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.api.openstack.wsgi [req-9f6e0ef2-e4ec-4a22-86f8-5a8bf06a55a2 demo demo] Calling method '<bound method FlavorsController.show of <nova.api.openstack.compute.flavors.FlavorsController object at 0x7f4cc683d8d0>>' {{(pid=23378) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:624}}
May 05 14:12:53 os4 nova-api[23142]: INFO nova.api.openstack.wsgi [req-9f6e0ef2-e4ec-4a22-86f8-5a8bf06a55a2 demo demo] HTTP exception thrown: Flavor m1.small could not be found.
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.api.openstack.wsgi [req-9f6e0ef2-e4ec-4a22-86f8-5a8bf06a55a2 demo demo] Returning 404 to user: Flavor m1.small could not be found. {{(pid=23378) __call__ /opt/stack/nova/nova/api/openstack/wsgi.py:1041}}
May 05 14:12:53 os4 nova-api[23142]: INFO nova.osapi_compute.wsgi.server [req-9f6e0ef2-e4ec-4a22-86f8-5a8bf06a55a2 demo demo] 10.42.0.53 "GET /v2.1/flavors/m1.small HTTP/1.1" status: 404 len: 435 time: 0.0426710
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.api.openstack.wsgi [req-a2229ce1-cb03-41af-a1bd-c63227fc2bd5 demo demo] Calling method '<bound method FlavorsController.index of <nova.api.openstack.compute.flavors.FlavorsController object at 0x7f4cc683d0d0>>' {{(pid=23378) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:624}}
May 05 14:12:53 os4 nova-api[23142]: INFO nova.osapi_compute.wsgi.server [req-a2229ce1-cb03-41af-a1bd-c63227fc2bd5 demo demo] 10.42.0.53 "GET /v2.1/flavors HTTP/1.1" status: 200 len: 2455 time: 0.0471120
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.api.openstack.wsgi [req-2c829042-8a1a-440b-81f4-c0f53d745d49 demo demo] Calling method '<bound method FlavorsController.show of <nova.api.openstack.compute.flavors.FlavorsController object at 0x7f4cc683d8d0>>' {{(pid=23378) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:624}}
May 05 14:12:53 os4 nova-api[23142]: INFO nova.osapi_compute.wsgi.server [req-2c829042-8a1a-440b-81f4-c0f53d745d49 demo demo] 10.42.0.53 "GET /v2.1/flavors/2 HTTP/1.1" status: 200 len: 690 time: 0.0364220

OpenStack Client fetches image id from name:

May 05 14:12:53 os4 glance-api[21956]: INFO eventlet.wsgi.server [req-00ffaefd-29ae-4dcb-9139-30494a47a912 demo demo] 10.42.0.53 - - [05/May/2017 14:12:53] "GET /v2/images/efc96458-7cd4-43e3-9a35-93001e98fd1a HTTP/1.1" 200 779 0.032760
May 05 14:12:53 os4 glance-api[21956]: DEBUG glance.api.middleware.version_negotiation [req-00ffaefd-29ae-4dcb-9139-30494a47a912 demo demo] Determining version of request: GET /v2/schemas/image Accept: */* {{(pid=22136) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:45}}
May 05 14:12:53 os4 glance-api[21956]: DEBUG glance.api.middleware.version_negotiation [req-00ffaefd-29ae-4dcb-9139-30494a47a912 demo demo] Using url versioning {{(pid=22136) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:57}}
May 05 14:12:53 os4 glance-api[21956]: DEBUG glance.api.middleware.version_negotiation [req-00ffaefd-29ae-4dcb-9139-30494a47a912 demo demo] Matched version: v2 {{(pid=22136) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:69}}
May 05 14:12:53 os4 glance-api[21956]: DEBUG glance.api.middleware.version_negotiation [req-00ffaefd-29ae-4dcb-9139-30494a47a912 demo demo] new path /v2/schemas/image {{(pid=22136) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:70}}
May 05 14:12:53 os4 glance-api[21956]: INFO eventlet.wsgi.server [req-37549a45-c1fb-4127-a789-a2581c4e787f demo demo] 10.42.0.53 - - [05/May/2017 14:12:53] "GET /v2/schemas/image HTTP/1.1" 200 4369 0.023104

OpenStack Client sends Nova request to boot server:

May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.api.openstack.wsgi [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Action: 'create', calling method: <bound method ServersController.create of <nova.api.openstack.compute.servers.ServersController object at 0x7f4cc6634b10>>, body: {"server": {"name": "ubuntu1", "imageRef": "efc96458-7cd4-43e3-9a35-93001e98fd1a", "key_name": "pub", "flavorRef": "2", "max_count": 1, "min_count": 1}} {{(pid=23378) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:621}}

Nova (nova-api) validates that network is valid on neutron side:

May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.network.neutronv2.api [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] validate_networks() for None {{(pid=23378) validate_networks /opt/stack/nova/nova/network/neutronv2/api.py:1654}}
May 05 14:12:53 os4 neutron-server[24158]: DEBUG neutron.policy [req-420b6ee2-e325-4838-bbe9-938e689876e9 demo demo] Enforcing rules: [u'get_network:provider:physical_network'] {{(pid=24304) log_rule_list /opt/stack/neutron/neutron/policy.py:335}}
May 05 14:12:53 os4 neutron-server[24158]: DEBUG neutron.policy [req-420b6ee2-e325-4838-bbe9-938e689876e9 demo demo] Enforcing rules: [u'get_network:provider:segmentation_id'] {{(pid=24304) log_rule_list /opt/stack/neutron/neutron/policy.py:335}}
May 05 14:12:53 os4 neutron-server[24158]: DEBUG neutron.policy [req-420b6ee2-e325-4838-bbe9-938e689876e9 demo demo] Enforcing rules: [u'get_network:provider:network_type'] {{(pid=24304) log_rule_list /opt/stack/neutron/neutron/policy.py:335}}
May 05 14:12:53 os4 neutron-server[24158]: DEBUG neutron.pecan_wsgi.hooks.notifier [req-420b6ee2-e325-4838-bbe9-938e689876e9 demo demo] No notification will be sent for action: get {{(pid=24304) after /opt/stack/neutron/neutron/pecan_wsgi/hooks/notifier.py:69}}
May 05 14:12:53 os4 neutron-server[24158]: INFO neutron.wsgi [req-420b6ee2-e325-4838-bbe9-938e689876e9 demo demo] 10.42.0.53 "GET /v2.0/networks.json?tenant_id=34e6ec64968a454993eda1a2051483bd&shared=False HTTP/1.1" status: 200  len: 810 time: 0.1623271
May 05 14:12:53 os4 neutron-server[24158]: DEBUG neutron.pecan_wsgi.hooks.notifier [req-1e28a53e-fc5d-4a7d-b026-652306ece516 demo demo] No notification will be sent for action: get {{(pid=24304) after /opt/stack/neutron/neutron/pecan_wsgi/hooks/notifier.py:69}}
May 05 14:12:53 os4 neutron-server[24158]: INFO neutron.wsgi [req-1e28a53e-fc5d-4a7d-b026-652306ece516 demo demo] 10.42.0.53 "GET /v2.0/networks.json?shared=True HTTP/1.1" status: 200  len: 213 time: 0.0593960

Nova (nova-api) ensures there is enough quota on the neutron side to allocate the port:

May 05 14:12:53 os4 neutron-server[24158]: INFO neutron.wsgi [req-bf4b4dea-fc66-47c9-b2f5-8284f0815781 demo demo] 10.42.0.53 "GET /v2.0/quotas/34e6ec64968a454993eda1a2051483bd.json HTTP/1.1" status: 200  len: 373 time: 0.0504410
May 05 14:12:53 os4 neutron-server[24158]: DEBUG neutron.pecan_wsgi.hooks.notifier [req-b502c235-818b-4b93-8157-3e0ebbd9d89e demo demo] No notification will be sent for action: get {{(pid=24304) after /opt/stack/neutron/neutron/pecan_wsgi/hooks/notifier.py:69}}
May 05 14:12:53 os4 neutron-server[24158]: INFO neutron.wsgi [req-b502c235-818b-4b93-8157-3e0ebbd9d89e demo demo] 10.42.0.53 "GET /v2.0/ports.json?fields=id&tenant_id=34e6ec64968a454993eda1a2051483bd HTTP/1.1" status: 200  len: 394 time: 0.0994699

Nova checks it's own quota to ensure this is sufficient:

May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.virt.hardware [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] emulator threads policy constraint: None {{(pid=23378) get_emulator_threads_constraint /opt/stack/nova/nova/virt/hardware.py:1286}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.quota [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Getting quotas for project 34e6ec64968a454993eda1a2051483bd. Resources: ['metadata_items'] {{(pid=23378) _get_quotas /opt/stack/nova/nova/quota.py:369}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.quota [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Getting quotas for user 7589bd4b8d2f46bea84bb5b5cbed9933 and project 34e6ec64968a454993eda1a2051483bd. Resources: ['metadata_items'] {{(pid=23378) _get_quotas /opt/stack/nova/nova/quota.py:361}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.quota [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Getting quotas for project 34e6ec64968a454993eda1a2051483bd. Resources: ['injected_files'] {{(pid=23378) _get_quotas /opt/stack/nova/nova/quota.py:369}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.quota [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Getting quotas for user 7589bd4b8d2f46bea84bb5b5cbed9933 and project 34e6ec64968a454993eda1a2051483bd. Resources: ['injected_files'] {{(pid=23378) _get_quotas /opt/stack/nova/nova/quota.py:361}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.quota [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Getting quotas for project 34e6ec64968a454993eda1a2051483bd. Resources: ['injected_file_content_bytes', 'injected_file_path_bytes'] {{(pid=23378) _get_quotas /opt/stack/nova/nova/quota.py:369}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.quota [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Getting quotas for user 7589bd4b8d2f46bea84bb5b5cbed9933 and project 34e6ec64968a454993eda1a2051483bd. Resources: ['injected_file_content_bytes', 'injected_file_path_bytes'] {{(pid=23378) _get_quotas /opt/stack/nova/nova/quota.py:361}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.quota [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Reserving resources using context.project_id: 34e6ec64968a454993eda1a2051483bd {{(pid=23378) reserve /opt/stack/nova/nova/quota.py:500}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.quota [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Reserving resources using context.user_id: 7589bd4b8d2f46bea84bb5b5cbed9933 {{(pid=23378) reserve /opt/stack/nova/nova/quota.py:505}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.quota [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Attempting to reserve resources for project 34e6ec64968a454993eda1a2051483bd and user 7589bd4b8d2f46bea84bb5b5cbed9933. Deltas: {'instances': 1, 'ram': 2048, 'cores': 1} {{(pid=23378) reserve /opt/stack/nova/nova/quota.py:510}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.quota [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Quota limits for project 34e6ec64968a454993eda1a2051483bd: {'project_id': u'34e6ec64968a454993eda1a2051483bd'} {{(pid=23378) reserve /opt/stack/nova/nova/quota.py:519}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.quota [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Getting quotas for project 34e6ec64968a454993eda1a2051483bd. Resources: ['instances', 'ram', 'cores'] {{(pid=23378) _get_quotas /opt/stack/nova/nova/quota.py:369}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.quota [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Quotas for project 34e6ec64968a454993eda1a2051483bd after resource sync: {'instances': 10, 'ram': 51200, 'cores': 20} {{(pid=23378) reserve /opt/stack/nova/nova/quota.py:525}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.quota [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Getting quotas for user 7589bd4b8d2f46bea84bb5b5cbed9933 and project 34e6ec64968a454993eda1a2051483bd. Resources: ['instances', 'ram', 'cores'] {{(pid=23378) _get_quotas /opt/stack/nova/nova/quota.py:361}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.quota [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Quotas for project 34e6ec64968a454993eda1a2051483bd and user 7589bd4b8d2f46bea84bb5b5cbed9933 after resource sync: {'instances': 10, 'ram': 51200, 'cores': 20} {{(pid=23378) reserve /opt/stack/nova/nova/quota.py:533}}

Nova (nova-api) creates a reservation, which includes an allocated instance uuid:

May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.quota [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Created reservations ['1b56a2e5-8a77-4bff-bb89-0d15c32a233f', '8550c1db-225c-4af2-afbf-714395f6f707', '7ba7a6d5-adbb-4342-bf40-2ca7abffde45'] {{(pid=23378) reserve /opt/stack/nova/nova/quota.py:1383}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.compute.api [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Going to run 1 instances... {{(pid=23378) _provision_instances /opt/stack/nova/nova/compute/api.py:1002}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.compute.api [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] block_device_mapping [BlockDeviceMapping(attachment_id=<?>,boot_index=0,connection_info=None,created_at=<?>,delete_on_termination=True,deleted=<?>,deleted_at=<?>,destination_type='local',device_name=None,device_type='disk',disk_bus=None,guest_format=None,id=<?>,image_id='efc96458-7cd4-43e3-9a35-93001e98fd1a',instance=<?>,instance_uuid=<?>,no_device=False,snapshot_id=None,source_type='image',tag=None,updated_at=<?>,volume_id=None,volume_size=None)] {{(pid=23378) _bdm_validate_set_size_and_instance /opt/stack/nova/nova/compute/api.py:1335}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.quota [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Committed reservations [u'1b56a2e5-8a77-4bff-bb89-0d15c32a233f', u'8550c1db-225c-4af2-afbf-714395f6f707', u'7ba7a6d5-adbb-4342-bf40-2ca7abffde45'] {{(pid=23378) commit /opt/stack/nova/nova/quota.py:1409}}

Nova (nova-api) returns API request back to user with allocated uuid and 202 return code:

May 05 14:12:53 os4 nova-api[23142]: INFO nova.osapi_compute.wsgi.server [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] 10.42.0.53 "POST /v2.1/servers HTTP/1.1" status: 202 len: 795 time: 0.6249380

OpenStack client calls "GET /servers" for more info (there are some glance and flavor calls intermixed later because it's still doing this):

May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.api.openstack.wsgi [req-a66af9b7-00ab-41b3-9637-d6a86cb6e0c3 demo demo] Calling method '<bound method ServersController.show of <nova.api.openstack.compute.servers.ServersController object at 0x7f4cc6566110>>' {{(pid=23378) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:624}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.compute.api [req-a66af9b7-00ab-41b3-9637-d6a86cb6e0c3 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Fetching instance by UUID {{(pid=23378) get /opt/stack/nova/nova/compute/api.py:2435}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.policy [req-a66af9b7-00ab-41b3-9637-d6a86cb6e0c3 demo demo] Policy check for os_compute_api:os-extended-server-attributes failed with credentials {'service_roles': [], 'user_id': u'7589bd4b8d2f46bea84bb5b5cbed9933', 'roles': [u'anotherrole', u'Member'], 'user_domain_id': u'default', 'service_project_id': None, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_domain_id': None, 'is_admin_project': True, 'is_admin': False, 'project_id': u'34e6ec64968a454993eda1a2051483bd', 'project_domain_id': u'default'} {{(pid=23378) authorize /opt/stack/nova/nova/policy.py:168}}
May 05 14:12:53 os4 neutron-server[24158]: DEBUG neutron.pecan_wsgi.hooks.notifier [req-b3732fd4-5744-4df8-a7fc-3951d2b41df9 demo demo] No notification will be sent for action: get {{(pid=24304) after /opt/stack/neutron/neutron/pecan_wsgi/hooks/notifier.py:69}}
May 05 14:12:53 os4 neutron-server[24158]: INFO neutron.wsgi [req-b3732fd4-5744-4df8-a7fc-3951d2b41df9 demo demo] 10.42.0.53 "GET /v2.0/ports.json?device_id=339dc23b-d7bd-4856-b17f-ae5b19ca12eb HTTP/1.1" status: 200  len: 210 time: 0.0809729
May 05 14:12:53 os4 nova-api[23142]: INFO nova.osapi_compute.wsgi.server [req-a66af9b7-00ab-41b3-9637-d6a86cb6e0c3 demo demo] 10.42.0.53 "GET /v2.1/servers/339dc23b-d7bd-4856-b17f-ae5b19ca12eb HTTP/1.1" status: 200 len: 1490 time: 0.1472769
May 05 14:12:53 os4 glance-api[21956]: DEBUG glance.api.middleware.version_negotiation [req-5f7dac4a-c8ef-4c3e-b650-51e78302aa04 demo demo] Determining version of request: GET /v2/images/efc96458-7cd4-43e3-9a35-93001e98fd1a Accept: */* {{(pid=22135) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:45}}
May 05 14:12:53 os4 glance-api[21956]: DEBUG glance.api.middleware.version_negotiation [req-5f7dac4a-c8ef-4c3e-b650-51e78302aa04 demo demo] Using url versioning {{(pid=22135) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:57}}
May 05 14:12:53 os4 glance-api[21956]: DEBUG glance.api.middleware.version_negotiation [req-5f7dac4a-c8ef-4c3e-b650-51e78302aa04 demo demo] Matched version: v2 {{(pid=22135) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:69}}
May 05 14:12:53 os4 glance-api[21956]: DEBUG glance.api.middleware.version_negotiation [req-5f7dac4a-c8ef-4c3e-b650-51e78302aa04 demo demo] new path /v2/images/efc96458-7cd4-43e3-9a35-93001e98fd1a {{(pid=22135) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:70}}

nova-api has passed control to conductor / scheduler to pick a host:

May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.scheduler.host_manager [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Getting compute nodes and services for cell 00000000-0000-0000-0000-000000000000(cell0) {{(pid=31143) _get_computes_for_cells /opt/stack/nova/nova/scheduler/host_manager.py:605}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG oslo_db.sqlalchemy.engines [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION {{(pid=31143) _check_effective_sql_mode /usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:260}}
May 05 14:12:53 os4 glance-api[21956]: INFO eventlet.wsgi.server [req-534603fd-5780-47a3-924f-564acc46fbfd demo demo] 10.42.0.53 - - [05/May/2017 14:12:53] "GET /v2/images/efc96458-7cd4-43e3-9a35-93001e98fd1a HTTP/1.1" 200 779 0.037941
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.scheduler.host_manager [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Getting compute nodes and services for cell eba37e59-6a9f-45f6-a7bf-d11b5a0a4e90(cell1) {{(pid=31143) _get_computes_for_cells /opt/stack/nova/nova/scheduler/host_manager.py:605}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG oslo_db.sqlalchemy.engines [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION {{(pid=31143) _check_effective_sql_mode /usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:260}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "(u'os4', u'os4')" acquired by "nova.scheduler.host_manager._locked_update" :: waited 0.000s {{(pid=31143) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270}}
May 05 14:12:53 os4 nova-api[23142]: DEBUG nova.api.openstack.wsgi [req-58e69592-1b87-491a-a6f3-3d5ecc12da68 demo demo] Calling method '<bound method FlavorsController.show of <nova.api.openstack.compute.flavors.FlavorsController object at 0x7f4cc683d8d0>>' {{(pid=23378) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:624}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.scheduler.host_manager [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Update host state from compute node: ComputeNode(cpu_allocation_ratio=16.0,cpu_info='{"vendor": "Intel", "model": "Broadwell", "arch": "x86_64", "features": ["pge", "avx", "vmx", "clflush", "sep", "rtm", "tsc_adjust", "vme", "dtes64", "invpcid", "msr", "sse", "xsave", "smap", "xsaveopt", "erms", "xtpr", "cmov", "hle", "smep", "nx", "est", "pat", "monitor", "smx", "pbe", "lm", "tsc", "adx", "3dnowprefetch", "fpu", "fxsr", "syscall", "tm", "sse4.1", "pae", "sse4.2", "pclmuldq", "pcid", "fma", "tsc-deadline", "mmx", "osxsave", "cx8", "mce", "de", "tm2", "ht", "pse", "pni", "abm", "rdseed", "popcnt", "mca", "pdpe1gb", "apic", "fsgsbase", "f16c", "ds", "invtsc", "lahf_lm", "aes", "avx2", "sse2", "ss", "ds_cpl", "arat", "bmi1", "bmi2", "acpi", "ssse3", "rdtscp", "cx16", "pse36", "mtrr", "movbe", "pdcm", "rdrand", "x2apic"], "topology": {"cores": 2, "cells": 1, "threads": 2, "sockets": 1}}',created_at=2017-05-05T16:06:02Z,current_workload=0,deleted=False,deleted_at=None,disk_allocation_ratio=1.0,disk_available_least=194,free_disk_gb=217,free_ram_mb=14923,host='os4',host_ip=10.42.0.53,hypervisor_hostname='os4',hypervisor_type='QEMU',hypervisor_version=2008000,id=1,local_gb=218,local_gb_used=1,mapped=0,memory_mb=15947,memory_mb_used=1024,metrics='[]',numa_topology='{"nova_object.version": "1.2", "nova_object.changes": ["cells"], "nova_object.name": "NUMATopology", "nova_object.data": {"cells": [{"nova_object.version": "1.2", "nova_object.changes": ["cpu_usage", "memory_usage", "cpuset", "pinned_cpus", "siblings", "memory", "mempages", "id"], "nova_object.name": "NUMACell", "nova_object.data": {"cpu_usage": 0, "memory_usage": 0, "cpuset": [0, 1, 2, 3], "pinned_cpus": [], "siblings": [[1, 3], [0, 2]], "memory": 15947, "mempages": [{"nova_object.version": "1.1", "nova_object.changes": ["used", "total", "reserved", "size_kb"], "nova_object.name": "NUMAPagesTopology", "nova_object.data": {"used": 0, "total": 4082545, "reserved": 0, "size_kb"
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.scheduler.host_manager [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Update host state with aggregates: [] {{(pid=31143) _locked_update /opt/stack/nova/nova/scheduler/host_manager.py:174}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.scheduler.host_manager [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Update host state with service dict: {'binary': u'nova-compute', 'uuid': '25830ebe-03ca-4ded-a420-78d3acbfb459', 'deleted': False, 'created_at': datetime.datetime(2017, 5, 5, 16, 6, 2, tzinfo=<iso8601.Utc>), 'updated_at': datetime.datetime(2017, 5, 5, 18, 12, 48, tzinfo=<iso8601.Utc>), 'report_count': 761, 'topic': u'compute', 'host': u'os4', 'version': 17, 'disabled': False, 'forced_down': False, 'last_seen_up': datetime.datetime(2017, 5, 5, 18, 12, 48, tzinfo=<iso8601.Utc>), 'deleted_at': None, 'disabled_reason': None, 'id': 7} {{(pid=31143) _locked_update /opt/stack/nova/nova/scheduler/host_manager.py:177}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.scheduler.host_manager [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Update host state with instances: {'36d32c20-a91d-4c93-a7ee-0fb60ebe2b5a': Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone='nova',cell_name=None,cleaned=False,config_drive='',created_at=2017-05-05T16:08:31Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,device_metadata=None,disable_terminate=False,display_description='myserver2',display_name='myserver2',ec2_ids=EC2Ids,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(6),host='os4',hostname='myserver2',id=1,image_ref='ee82fb25-0c6b-41e9-96f9-a0e0d95056c6',info_cache=InstanceInfoCache,instance_type_id=6,kernel_id='',key_data=None,key_name=None,keypairs=KeyPairList,launch_index=0,launched_at=2017-05-05T16:08:40Z,launched_on='os4',locked=False,locked_by=None,memory_mb=512,metadata={},migration_context=<?>,new_flavor=None,node='os4',numa_topology=None,old_flavor=None,os_type=None,pci_devices=PciDeviceList,pci_requests=InstancePCIRequests,power_state=1,progress=0,project_id='34e6ec64968a454993eda1a2051483bd',ramdisk_id='',reservation_id='r-0zjss2pw',root_device_name='/dev/vda',root_gb=1,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={boot_roles='anotherrole,Member',image_base_image_ref='ee82fb25-0c6b-41e9-96f9-a0e0d95056c6',image_container_format='bare',image_disk_format='qcow2',image_min_disk='1',image_min_ram='0',owner_project_name='demo',owner_user_name='demo'},tags=<?>,task_state=None,terminated_at=None,updated_at=2017-05-05T16:08:33Z,user_data=None,user_id='7589bd4b8d2f46bea84bb5b5cbed9933',uuid=36d32c20-a91d-4c93-a7ee-0fb60ebe2b5a,vcpu_model=VirtCPUModel,vcpus=1,vm_mode=None,vm_state='active')} {{(pid=31143) _locked_update /opt/stack/nova/nova/scheduler/host_manager.py:180}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "(u'os4', u'os4')" released by "nova.scheduler.host_manager._locked_update" :: held 0.004s {{(pid=31143) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282}}

Nova scheduler found one valid host and is starting to filter on it:

May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.filters [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Starting with 1 host(s) {{(pid=31143) get_filtered_objects /opt/stack/nova/nova/filters.py:70}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.scheduler.filters.retry_filter [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Re-scheduling is disabled {{(pid=31143) host_passes /opt/stack/nova/nova/scheduler/filters/retry_filter.py:34}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.filters [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Filter RetryFilter returned 1 host(s) {{(pid=31143) get_filtered_objects /opt/stack/nova/nova/filters.py:104}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.filters [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Filter AvailabilityZoneFilter returned 1 host(s) {{(pid=31143) get_filtered_objects /opt/stack/nova/nova/filters.py:104}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.filters [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Filter RamFilter returned 1 host(s) {{(pid=31143) get_filtered_objects /opt/stack/nova/nova/filters.py:104}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.filters [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Filter DiskFilter returned 1 host(s) {{(pid=31143) get_filtered_objects /opt/stack/nova/nova/filters.py:104}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.filters [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Filter ComputeFilter returned 1 host(s) {{(pid=31143) get_filtered_objects /opt/stack/nova/nova/filters.py:104}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.filters [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Filter ComputeCapabilitiesFilter returned 1 host(s) {{(pid=31143) get_filtered_objects /opt/stack/nova/nova/filters.py:104}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.filters [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Filter ImagePropertiesFilter returned 1 host(s) {{(pid=31143) get_filtered_objects /opt/stack/nova/nova/filters.py:104}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.filters [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Filter ServerGroupAntiAffinityFilter returned 1 host(s) {{(pid=31143) get_filtered_objects /opt/stack/nova/nova/filters.py:104}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.filters [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Filter ServerGroupAffinityFilter returned 1 host(s) {{(pid=31143) get_filtered_objects /opt/stack/nova/nova/filters.py:104}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.filters [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Filter SameHostFilter returned 1 host(s) {{(pid=31143) get_filtered_objects /opt/stack/nova/nova/filters.py:104}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.filters [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Filter DifferentHostFilter returned 1 host(s) {{(pid=31143) get_filtered_objects /opt/stack/nova/nova/filters.py:104}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.scheduler.filter_scheduler [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Filtered [(os4, os4) ram: 14923MB disk: 198656MB io_ops: 0 instances: 1] {{(pid=31143) _schedule /opt/stack/nova/nova/scheduler/filter_scheduler.py:114}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.scheduler.filter_scheduler [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Weighed [WeighedHost [host: (os4, os4) ram: 14923MB disk: 198656MB io_ops: 0 instances: 1, weight: 0.0]] {{(pid=31143) _schedule /opt/stack/nova/nova/scheduler/filter_scheduler.py:119}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.scheduler.filter_scheduler [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Selected host: WeighedHost [host: (os4, os4) ram: 14923MB disk: 198656MB io_ops: 0 instances: 1, weight: 0.0] {{(pid=31143) _schedule /opt/stack/nova/nova/scheduler/filter_scheduler.py:126}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "(u'os4', u'os4')" acquired by "nova.scheduler.host_manager._locked" :: waited 0.000s {{(pid=31143) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG nova.virt.hardware [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Require both a host and instance NUMA topology to fit instance on host. {{(pid=31143) numa_fit_instance_to_host /opt/stack/nova/nova/virt/hardware.py:1466}}
May 05 14:12:53 os4 nova-scheduler[31143]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "(u'os4', u'os4')" released by "nova.scheduler.host_manager._locked" :: held 0.002s {{(pid=31143) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282}}

End of openstack client doing a show on the server and flavor:

May 05 14:12:53 os4 nova-api[23142]: INFO nova.osapi_compute.wsgi.server [req-58e69592-1b87-491a-a6f3-3d5ecc12da68 demo demo] 10.42.0.53 "GET /v2.1/flavors/2 HTTP/1.1" status: 200 len: 690 time: 0.0438941
May 05 14:12:54 os4 nova-conductor[30057]: DEBUG oslo_db.sqlalchemy.engines [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION {{(pid=32501) _check_effective_sql_mode /usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:260}}
May 05 14:12:54 os4 nova-conductor[30057]: DEBUG oslo_db.sqlalchemy.engines [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION {{(pid=32501) _check_effective_sql_mode /usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:260}}

Conductor creates block device mapping and tells nova-compute to start the boot:

May 05 14:12:54 os4 nova-conductor[30057]: DEBUG nova.conductor.manager [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] block_device_mapping [BlockDeviceMapping(attachment_id=<?>,boot_index=0,connection_info=None,created_at=<?>,delete_on_termination=True,deleted=<?>,deleted_at=<?>,destination_type='local',device_name=None,device_type='disk',disk_bus=None,guest_format=None,id=<?>,image_id='efc96458-7cd4-43e3-9a35-93001e98fd1a',instance=<?>,instance_uuid=<?>,no_device=False,snapshot_id=None,source_type='image',tag=None,updated_at=<?>,volume_id=None,volume_size=None)] {{(pid=32501) _create_block_device_mapping /opt/stack/nova/nova/conductor/manager.py:841}}

Boot started on nova-compute:

May 05 14:12:54 os4 nova-compute[811]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "339dc23b-d7bd-4856-b17f-ae5b19ca12eb" acquired by "nova.compute.manager._locked_do_build_and_run_instance" :: waited 0.000s {{(pid=811) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270}}
May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.compute.manager [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Starting instance... {{(pid=811) _do_build_and_run_instance /opt/stack/nova/nova/compute/manager.py:1747}}
May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.notifications.objects.base [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Defaulting the value of the field 'projects' to None in FlavorPayload due to 'Cannot call _load_projects on orphaned Flavor object' {{(pid=811) populate_schema /opt/stack/nova/nova/notifications/objects/base.py:119}}

nova-compute resource tracker claims the required resources:

May 05 14:12:54 os4 nova-compute[811]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "compute_resources" acquired by "nova.compute.resource_tracker.instance_claim" :: waited 0.000s {{(pid=811) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270}}
May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.compute.resource_tracker [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Memory overhead for 2048 MB instance; 0 MB {{(pid=811) instance_claim /opt/stack/nova/nova/compute/resource_tracker.py:148}}
May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.compute.resource_tracker [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Disk overhead for 20 GB instance; 0 GB {{(pid=811) instance_claim /opt/stack/nova/nova/compute/resource_tracker.py:151}}
May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.compute.resource_tracker [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] CPU overhead for 1 vCPUs instance; 0 vCPU(s) {{(pid=811) instance_claim /opt/stack/nova/nova/compute/resource_tracker.py:154}}
May 05 14:12:54 os4 nova-compute[811]: INFO nova.compute.claims [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Attempting claim on node os4: memory 2048 MB, disk 20 GB, vcpus 1 CPU
May 05 14:12:54 os4 nova-compute[811]: INFO nova.compute.claims [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Total memory: 15947 MB, used: 1024.00 MB
May 05 14:12:54 os4 nova-compute[811]: INFO nova.compute.claims [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] memory limit: 23920.50 MB, free: 22896.50 MB
May 05 14:12:54 os4 nova-compute[811]: INFO nova.compute.claims [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Total disk: 218 GB, used: 1.00 GB
May 05 14:12:54 os4 nova-compute[811]: INFO nova.compute.claims [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] disk limit: 218.00 GB, free: 217.00 GB
May 05 14:12:54 os4 nova-compute[811]: INFO nova.compute.claims [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Total vcpu: 4 VCPU, used: 1.00 VCPU
May 05 14:12:54 os4 nova-compute[811]: INFO nova.compute.claims [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] vcpu limit not specified, defaulting to unlimited
May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.virt.hardware [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Require both a host and instance NUMA topology to fit instance on host. {{(pid=811) numa_fit_instance_to_host /opt/stack/nova/nova/virt/hardware.py:1466}}
May 05 14:12:54 os4 nova-compute[811]: INFO nova.compute.claims [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Claim successful on node os4

nova-compute tells scheduler and placement what it allocated:

May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.scheduler.client.report [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Sending allocation for instance {'MEMORY_MB': 2048, 'VCPU': 1, 'DISK_GB': 20} {{(pid=811) _allocate_for_instance /opt/stack/nova/nova/scheduler/client/report.py:844}}
May 05 14:12:54 os4 nova-compute[811]: INFO nova.scheduler.client.report [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Submitted allocation for instance
May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.scheduler.client.report [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Refreshing aggregate associations for resource provider 000a7316-841e-4fad-bc72-e3fe4d0efc03 {{(pid=811) _ensure_resource_provider /opt/stack/nova/nova/scheduler/client/report.py:438}}
May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.scheduler.client.report [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Updating our resource provider generation from 2 to 3 {{(pid=811) _get_inventory_and_update_provider_generation /opt/stack/nova/nova/scheduler/client/report.py:481}}
May 05 14:12:54 os4 nova-compute[811]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "compute_resources" released by "nova.compute.resource_tracker.instance_claim" :: held 0.257s {{(pid=811) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282}}

nova-compute calls to neutron to allocate network resources:

May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.compute.manager [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Start building networks asynchronously for instance. {{(pid=811) _build_resources /opt/stack/nova/nova/compute/manager.py:2062}}
May 05 14:12:54 os4 nova-compute[811]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "compute_resources" acquired by "nova.compute.resource_tracker.update_usage" :: waited 0.000s {{(pid=811) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270}}
May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.scheduler.client.report [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Refreshing aggregate associations for resource provider 000a7316-841e-4fad-bc72-e3fe4d0efc03 {{(pid=811) _ensure_resource_provider /opt/stack/nova/nova/scheduler/client/report.py:438}}
May 05 14:12:54 os4 nova-compute[811]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "compute_resources" released by "nova.compute.resource_tracker.update_usage" :: held 0.086s {{(pid=811) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282}}
May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.compute.manager [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Allocating IP information in the background. {{(pid=811) _allocate_network_async /opt/stack/nova/nova/compute/manager.py:1384}}
May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.network.neutronv2.api [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] allocate_for_instance() {{(pid=811) allocate_for_instance /opt/stack/nova/nova/network/neutronv2/api.py:828}}
May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.block_device [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] block_device_list [] {{(pid=811) volume_in_mapping /opt/stack/nova/nova/block_device.py:585}}
May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.compute.manager [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Start building block device mappings for instance. {{(pid=811) _build_resources /opt/stack/nova/nova/compute/manager.py:2088}}

neutron-server starts building that network:

May 05 14:12:54 os4 neutron-server[24158]: DEBUG neutron.policy [req-17c1f043-c537-4b5b-9587-4444d7d1e230 demo demo] Enforcing rules: [u'get_network:provider:physical_network'] {{(pid=24305) log_rule_list /opt/stack/neutron/neutron/policy.py:335}}
May 05 14:12:54 os4 neutron-server[24158]: DEBUG neutron.policy [req-17c1f043-c537-4b5b-9587-4444d7d1e230 demo demo] Enforcing rules: [u'get_network:provider:segmentation_id'] {{(pid=24305) log_rule_list /opt/stack/neutron/neutron/policy.py:335}}
May 05 14:12:54 os4 neutron-server[24158]: DEBUG neutron.policy [req-17c1f043-c537-4b5b-9587-4444d7d1e230 demo demo] Enforcing rules: [u'get_network:provider:network_type'] {{(pid=24305) log_rule_list /opt/stack/neutron/neutron/policy.py:335}}
May 05 14:12:54 os4 neutron-server[24158]: DEBUG neutron.pecan_wsgi.hooks.notifier [req-17c1f043-c537-4b5b-9587-4444d7d1e230 demo demo] No notification will be sent for action: get {{(pid=24305) after /opt/stack/neutron/neutron/pecan_wsgi/hooks/notifier.py:69}}
May 05 14:12:54 os4 neutron-server[24158]: INFO neutron.wsgi [req-17c1f043-c537-4b5b-9587-4444d7d1e230 demo demo] 10.42.0.53 "GET /v2.0/networks.json?tenant_id=34e6ec64968a454993eda1a2051483bd&shared=False HTTP/1.1" status: 200  len: 810 time: 0.1637640

nova-compute actually triggers virt driver create:

May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.compute.manager [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Start spawning the instance on the hypervisor. {{(pid=811) _build_and_run_instance /opt/stack/nova/nova/compute/manager.py:1921}}
May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.block_device [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] block_device_list [] {{(pid=811) volume_in_mapping /opt/stack/nova/nova/block_device.py:585}}

nova-compute virt driver calls out to glance to pull the image:

May 05 14:12:54 os4 nova-compute[811]: INFO nova.virt.libvirt.driver [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Creating image
May 05 14:12:54 os4 nova-compute[811]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "/opt/stack/data/nova/instances/339dc23b-d7bd-4856-b17f-ae5b19ca12eb/disk.info" acquired by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: waited 0.000s {{(pid=811) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270}}
May 05 14:12:54 os4 nova-compute[811]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "/opt/stack/data/nova/instances/339dc23b-d7bd-4856-b17f-ae5b19ca12eb/disk.info" released by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: held 0.000s {{(pid=811) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282}}
May 05 14:12:54 os4 nova-compute[811]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "71e3784636393bd59c86544533ba3cf90216a389" acquired by "nova.virt.libvirt.imagebackend.fetch_func_sync" :: waited 0.000s {{(pid=811) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270}}

glance responding...:

May 05 14:12:54 os4 glance-api[21956]: DEBUG glance_store._drivers.filesystem [req-8e392d4a-efa3-472a-9d6c-56d11f449c71 demo demo] Found image at /opt/stack/data/glance/images/efc96458-7cd4-43e3-9a35-93001e98fd1a. Returning in ChunkedFile. {{(pid=22135) get /usr/local/lib/python2.7/dist-packages/glance_store/_drivers/filesystem.py:553}}
May 05 14:12:54 os4 glance-api[21956]: DEBUG oslo_policy._cache_handler [req-8e392d4a-efa3-472a-9d6c-56d11f449c71 demo demo] Reloading cached file /etc/glance/policy.json {{(pid=22135) read_cached_file /usr/local/lib/python2.7/dist-packages/oslo_policy/_cache_handler.py:40}}
May 05 14:12:54 os4 glance-api[21956]: DEBUG oslo_policy.policy [req-8e392d4a-efa3-472a-9d6c-56d11f449c71 demo demo] Reloaded policy file: /etc/glance/policy.json {{(pid=22135) _load_policy_file /usr/local/lib/python2.7/dist-packages/oslo_policy/policy.py:684}}
May 05 14:12:54 os4 neutron-server[24158]: DEBUG neutron.pecan_wsgi.hooks.notifier [req-3aa6b440-0d98-414f-ac17-ca528588d42e demo demo] No notification will be sent for action: get {{(pid=24305) after /opt/stack/neutron/neutron/pecan_wsgi/hooks/notifier.py:69}}
May 05 14:12:54 os4 glance-api[21956]: DEBUG glance.image_cache [req-8e392d4a-efa3-472a-9d6c-56d11f449c71 demo demo] Tee'ing image 'efc96458-7cd4-43e3-9a35-93001e98fd1a' into cache {{(pid=22135) get_caching_iter /opt/stack/glance/glance/image_cache/__init__.py:343}}

Neutron still processing the network request:

May 05 14:12:54 os4 neutron-server[24158]: INFO neutron.wsgi [req-3aa6b440-0d98-414f-ac17-ca528588d42e demo demo] 10.42.0.53 "GET /v2.0/networks.json?shared=True HTTP/1.1" status: 200  len: 213 time: 0.0513141
May 05 14:12:54 os4 nova-compute[811]: DEBUG nova.policy [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Policy check for network:attach_external_network failed with credentials {'service_roles': [], 'user_id': u'7589bd4b8d2f46bea84bb5b5cbed9933', 'roles': [u'anotherrole', u'Member'], 'user_domain_id': None, 'service_project_id': None, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_domain_id': None, 'is_admin_project': True, 'is_admin': False, 'project_id': u'34e6ec64968a454993eda1a2051483bd', 'project_domain_id': None} {{(pid=811) authorize /opt/stack/nova/nova/policy.py:168}}
May 05 14:12:54 os4 neutron-server[24158]: DEBUG neutron.api.v2.base [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Request body: {u'port': {u'network_id': u'8356212e-f122-4dfc-9846-adecc23b4f34', u'tenant_id': u'34e6ec64968a454993eda1a2051483bd', u'device_id': u'339dc23b-d7bd-4856-b17f-ae5b19ca12eb', u'admin_state_up': True}} {{(pid=24305) prepare_request_body /opt/stack/neutron/neutron/api/v2/base.py:695}}
May 05 14:12:55 os4 neutron-server[24158]: DEBUG neutron.db.quota.driver [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Resources subnetpool have unlimited quota limit. It is not required to calculate headroom  {{(pid=24305) make_reservation /opt/stack/neutron/neutron/db/quota/driver.py:185}}
May 05 14:12:55 os4 neutron-server[24158]: DEBUG neutron.quota.resource [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Usage tracker for resource:port and tenant:34e6ec64968a454993eda1a2051483bd is out of sync, need to count used quota {{(pid=24305) count /opt/stack/neutron/neutron/quota/resource.py:270}}
May 05 14:12:55 os4 neutron-server[24158]: DEBUG neutron.quota.resource [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Quota usage for port was recalculated. Used quota:4. {{(pid=24305) count /opt/stack/neutron/neutron/quota/resource.py:289}}
May 05 14:12:55 os4 neutron-server[24158]: DEBUG neutron.db.quota.driver [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Attempting to reserve 1 items for resource port. Total usage: 4; quota limit: 500; headroom:496 {{(pid=24305) make_reservation /opt/stack/neutron/neutron/db/quota/driver.py:217}}
May 05 14:12:55 os4 neutron-server[24158]: DEBUG neutron.pecan_wsgi.hooks.quota_enforcement [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Made reservation on behalf of 34e6ec64968a454993eda1a2051483bd for: {'port': 1} {{(pid=24305) before /opt/stack/neutron/neutron/pecan_wsgi/hooks/quota_enforcement.py:55}}
May 05 14:12:55 os4 neutron-server[24158]: DEBUG neutron_lib.callbacks.manager [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Notify callbacks ['neutron.plugins.ml2.plugin.Ml2Plugin._ensure_default_security_group_handler--9223372036852795311'] for port, before_create {{(pid=24305) _notify_loop /usr/local/lib/python2.7/dist-packages/neutron_lib/callbacks/manager.py:167}}
May 05 14:12:55 os4 neutron-server[24158]: DEBUG neutron.ipam.driver [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Loading ipam driver: internal {{(pid=24305) get_instance /opt/stack/neutron/neutron/ipam/driver.py:51}}
May 05 14:12:55 os4 neutron-server[24158]: DEBUG neutron.db.db_base_plugin_common [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Allocated IP 10.0.0.13 (8356212e-f122-4dfc-9846-adecc23b4f34/5f336ac0-5947-40fc-885d-aff4b6320714/08268814-29e2-4719-b417-8832395e5e3e) {{(pid=24305) _store_ip_allocation /opt/stack/neutron/neutron/db/db_base_plugin_common.py:121}}
May 05 14:12:55 os4 neutron-server[24158]: DEBUG neutron.db.db_base_plugin_common [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Allocated IP fdfe:8380:b8e:0:f816:3eff:fe77:5f94 (8356212e-f122-4dfc-9846-adecc23b4f34/89886708-d999-4df8-8f43-68e47b3b0fe3/08268814-29e2-4719-b417-8832395e5e3e) {{(pid=24305) _store_ip_allocation /opt/stack/neutron/neutron/db/db_base_plugin_common.py:121}}

Image downloaded fully from glance into image cache:

May 05 14:12:55 os4 glance-api[21956]: DEBUG glance.image_cache.drivers.sqlite [req-8e392d4a-efa3-472a-9d6c-56d11f449c71 demo demo] Fetch finished, moving '/opt/stack/data/glance/cache/incomplete/efc96458-7cd4-43e3-9a35-93001e98fd1a' to '/opt/stack/data/glance/cache/efc96458-7cd4-43e3-9a35-93001e98fd1a' {{(pid=22135) commit /opt/stack/glance/glance/image_cache/drivers/sqlite.py:322}}
May 05 14:12:55 os4 glance-api[21956]: INFO eventlet.wsgi.server [req-8e392d4a-efa3-472a-9d6c-56d11f449c71 demo demo] 10.42.0.53 - - [05/May/2017 14:12:55] "GET /v2/images/efc96458-7cd4-43e3-9a35-93001e98fd1a/file HTTP/1.1" 200 286759594 1.113239

Neutron port is now allocated and put into DHCP (and lots more neutron work):

May 05 14:12:55 os4 neutron-server[24158]: DEBUG neutron_lib.callbacks.manager [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Notify callbacks [] for port, precommit_create {{(pid=24305) _notify_loop /usr/local/lib/python2.7/dist-packages/neutron_lib/callbacks/manager.py:167}}
May 05 14:12:55 os4 neutron-server[24158]: DEBUG neutron.db.provisioning_blocks [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Transition to ACTIVE for port object 08268814-29e2-4719-b417-8832395e5e3e will not be triggered until provisioned by entity DHCP. {{(pid=24305) add_provisioning_component /opt/stack/neutron/neutron/db/provisioning_blocks.py:74}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron_lib.callbacks.manager [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Notify callbacks ['neutron.api.rpc.agentnotifiers.dhcp_rpc_agent_api.DhcpAgentNotifyAPI._native_event_send_dhcp_notification-1248566', 'neutron.db.l3_dvrscheduler_db._notify_l3_agent_new_port-8759109805904', 'neutron.plugins.ml2.plugin.Ml2Plugin.notify_sg_on_port_change-1980418', 'neutron.plugins.ml2.ovo_rpc._ObjectChangeHandler.handle_event-637050'] for port, after_create {{(pid=24305) _notify_loop /usr/local/lib/python2.7/dist-packages/neutron_lib/callbacks/manager.py:167}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.scheduler.dhcp_agent_scheduler [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Network 8356212e-f122-4dfc-9846-adecc23b4f34 is already hosted by enough agents. {{(pid=24305) _get_dhcp_agents_hosting_network /opt/stack/neutron/neutron/scheduler/dhcp_agent_scheduler.py:245}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.db.l3_dvrscheduler_db [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Received port after_create {{(pid=24305) _notify_l3_agent_new_port /opt/stack/neutron/neutron/db/l3_dvrscheduler_db.py:372}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.policy [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Enforcing rules: [u'get_port:binding:profile'] {{(pid=24305) log_rule_list /opt/stack/neutron/neutron/policy.py:335}}
May 05 14:12:56 os4 neutron-dhcp-agent[25320]: DEBUG oslo_concurrency.lockutils [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Acquired semaphore "dhcp-agent-network-lock-8356212e-f122-4dfc-9846-adecc23b4f34" {{(pid=25320) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212}}
May 05 14:12:56 os4 neutron-dhcp-agent[25320]: INFO neutron.agent.dhcp.agent [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Trigger reload_allocations for port admin_state_up=True, allowed_address_pairs=[], binding:host_id=, binding:profile=, binding:vif_details=, binding:vif_type=unbound, binding:vnic_type=normal, created_at=2017-05-05T18:12:55Z, description=, device_id=339dc23b-d7bd-4856-b17f-ae5b19ca12eb, device_owner=, extra_dhcp_opts=[], fixed_ips=[{u'subnet_id': u'5f336ac0-5947-40fc-885d-aff4b6320714', u'ip_address': u'10.0.0.13'}, {u'subnet_id': u'89886708-d999-4df8-8f43-68e47b3b0fe3', u'ip_address': u'fdfe:8380:b8e:0:f816:3eff:fe77:5f94'}], id=08268814-29e2-4719-b417-8832395e5e3e, mac_address=fa:16:3e:77:5f:94, name=, network_id=8356212e-f122-4dfc-9846-adecc23b4f34, port_security_enabled=True, project_id=34e6ec64968a454993eda1a2051483bd, revision_number=8, security_groups=[u'977b31dc-8a64-4708-9a7b-d9c1f3f9040b'], status=DOWN, tags=[], tenant_id=34e6ec64968a454993eda1a2051483bd, updated_at=2017-05-05T18:12:55Z
May 05 14:12:56 os4 neutron-dhcp-agent[25320]: DEBUG neutron.agent.dhcp.agent [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Calling driver for network: 8356212e-f122-4dfc-9846-adecc23b4f34 action: reload_allocations {{(pid=25320) call_driver /opt/stack/neutron/neutron/agent/dhcp/agent.py:132}}
May 05 14:12:56 os4 neutron-openvswitch-agent[24846]: DEBUG neutron.api.rpc.handlers.securitygroups_rpc [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Security group member updated on remote: [u'977b31dc-8a64-4708-9a7b-d9c1f3f9040b'] {{(pid=24846) security_groups_member_updated /opt/stack/neutron/neutron/api/rpc/handlers/securitygroups_rpc.py:212}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.policy [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Enforcing rules: [u'get_port:binding:vif_details'] {{(pid=24305) log_rule_list /opt/stack/neutron/neutron/policy.py:335}}
May 05 14:12:56 os4 neutron-openvswitch-agent[24846]: INFO neutron.agent.securitygroups_rpc [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Security group member updated [u'977b31dc-8a64-4708-9a7b-d9c1f3f9040b']
May 05 14:12:56 os4 neutron-dhcp-agent[25320]: DEBUG neutron.agent.linux.dhcp [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Building host file: /opt/stack/data/neutron/dhcp/8356212e-f122-4dfc-9846-adecc23b4f34/host {{(pid=25320) _output_hosts_file /opt/stack/neutron/neutron/agent/linux/dhcp.py:676}}
May 05 14:12:56 os4 neutron-openvswitch-agent[24846]: DEBUG neutron.agent.securitygroups_rpc [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Adding [u'2536a477-eac0-44a1-add9-31a22b847538'] devices to the list of devices for which firewall needs to be refreshed {{(pid=24846) _security_group_updated /opt/stack/neutron/neutron/agent/securitygroups_rpc.py:183}}
May 05 14:12:56 os4 neutron-dhcp-agent[25320]: DEBUG neutron.agent.linux.dhcp [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Done building host file /opt/stack/data/neutron/dhcp/8356212e-f122-4dfc-9846-adecc23b4f34/host {{(pid=25320) _output_hosts_file /opt/stack/neutron/neutron/agent/linux/dhcp.py:714}}
May 05 14:12:56 os4 neutron-dhcp-agent[25320]: DEBUG neutron.agent.linux.utils [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Running command (rootwrap daemon): ['kill', '-HUP', '27774'] {{(pid=25320) execute_rootwrap_daemon /opt/stack/neutron/neutron/agent/linux/utils.py:108}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.policy [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Enforcing rules: [u'get_port:binding:vif_type'] {{(pid=24305) log_rule_list /opt/stack/neutron/neutron/policy.py:335}}
May 05 14:12:56 os4 neutron-dhcp-agent[25320]: DEBUG neutron.agent.linux.utils [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Exit code: 0 {{(pid=25320) execute /opt/stack/neutron/neutron/agent/linux/utils.py:153}}
May 05 14:12:56 os4 neutron-dhcp-agent[25320]: DEBUG neutron.agent.linux.dhcp [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Reloading allocations for network: 8356212e-f122-4dfc-9846-adecc23b4f34 {{(pid=25320) reload_allocations /opt/stack/neutron/neutron/agent/linux/dhcp.py:507}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.policy [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Enforcing rules: [u'get_port:binding:host_id'] {{(pid=24305) log_rule_list /opt/stack/neutron/neutron/policy.py:335}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron_lib.callbacks.manager [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Notify callbacks ['neutron.api.rpc.agentnotifiers.dhcp_rpc_agent_api.DhcpAgentNotifyAPI._send_dhcp_notification-1248551'] for port, before_response {{(pid=24305) _notify_loop /usr/local/lib/python2.7/dist-packages/neutron_lib/callbacks/manager.py:167}}
May 05 14:12:56 os4 neutron-dhcp-agent[25320]: DEBUG neutron.agent.linux.utils [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Running command (rootwrap daemon): ['ip', 'netns', 'exec', 'qdhcp-8356212e-f122-4dfc-9846-adecc23b4f34', 'ip', 'route', 'list', 'dev', 'tapbddd0c50-a0'] {{(pid=25320) execute_rootwrap_daemon /opt/stack/neutron/neutron/agent/linux/utils.py:108}}
May 05 14:12:56 os4 neutron-dhcp-agent[25320]: DEBUG neutron.agent.linux.utils [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Exit code: 0 {{(pid=25320) execute /opt/stack/neutron/neutron/agent/linux/utils.py:153}}
May 05 14:12:56 os4 neutron-dhcp-agent[25320]: DEBUG oslo_concurrency.lockutils [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Releasing semaphore "dhcp-agent-network-lock-8356212e-f122-4dfc-9846-adecc23b4f34" {{(pid=25320) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:225}}

nova-compute interogates the image we just pulled so we can actually build hypervisor boot command:

May 05 14:12:56 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Running cmd (subprocess): /usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=8 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389.part {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355}}

Port creation is finished in neutron:

May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.quota.resource [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Persisted dirty status for tenant:34e6ec64968a454993eda1a2051483bd on resource:port {{(pid=24305) mark_dirty /opt/stack/neutron/neutron/quota/resource.py:193}}
May 05 14:12:56 os4 neutron-server[24158]: INFO neutron.wsgi [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] 10.42.0.53 "POST /v2.0/ports.json HTTP/1.1" status: 201  len: 1036 time: 2.0031881
May 05 14:12:56 os4 nova-compute[811]: DEBUG nova.network.neutronv2.api [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Successfully created port: 08268814-29e2-4719-b417-8832395e5e3e {{(pid=811) _create_port_minimal /opt/stack/nova/nova/network/neutronv2/api.py:396}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.plugins.ml2.ovo_rpc [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Dispatching RPC callback event updated for port 08268814-29e2-4719-b417-8832395e5e3e. {{(pid=24305) dispatch_events /opt/stack/neutron/neutron/plugins/ml2/ovo_rpc.py:109}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.api.rpc.handlers.resources_rpc [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] neutron.api.rpc.handlers.resources_rpc.ResourcesPushRpcApi method push called with arguments (<neutron_lib.context.Context object at 0x7f7638f8ae50>, [Port(admin_state_up=True,allowed_address_pairs=[],binding=PortBinding,binding_levels=[],created_at=2017-05-05T18:12:55Z,data_plane_status=<?>,description='',device_id='339dc23b-d7bd-4856-b17f-ae5b19ca12eb',device_owner='',dhcp_options=[],distributed_binding=None,dns=None,fixed_ips=[IPAllocation,IPAllocation],id=08268814-29e2-4719-b417-8832395e5e3e,mac_address=fa:16:3e:77:5f:94,name='',network_id=8356212e-f122-4dfc-9846-adecc23b4f34,project_id='34e6ec64968a454993eda1a2051483bd',qos_policy_id=None,revision_number=8,security=PortSecurity(08268814-29e2-4719-b417-8832395e5e3e),security_group_ids=set([977b31dc-8a64-4708-9a7b-d9c1f3f9040b]),status='DOWN',updated_at=2017-05-05T18:12:55Z)], 'updated') {} {{(pid=24305) wrapper /usr/local/lib/python2.7/dist-packages/oslo_log/helpers.py:47}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.db.agents_db [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Update consumer L3 agent@os4 versions to: {} {{(pid=24305) get_agents_resource_versions /opt/stack/neutron/neutron/db/agents_db.py:405}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.db.agents_db [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Update consumer DHCP agent@os4 versions to: {} {{(pid=24305) get_agents_resource_versions /opt/stack/neutron/neutron/db/agents_db.py:405}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.db.agents_db [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Update consumer Open vSwitch agent@os4 versions to: {u'Subnet': u'1.0', u'Network': u'1.0', u'SubPort': u'1.0', u'SecurityGroup': u'1.0', u'SecurityGroupRule': u'1.0', u'Trunk': u'1.1', u'QosPolicy': u'1.5', u'Port': u'1.1'} {{(pid=24305) get_agents_resource_versions /opt/stack/neutron/neutron/db/agents_db.py:405}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.api.rpc.callbacks.version_manager [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Version for resource type Subnet changed None to 1.0 on consumer Open vSwitch agent@os4 {{(pid=24305) _set_version /opt/stack/neutron/neutron/api/rpc/callbacks/version_manager.py:119}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.api.rpc.callbacks.version_manager [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Version for resource type Network changed None to 1.0 on consumer Open vSwitch agent@os4 {{(pid=24305) _set_version /opt/stack/neutron/neutron/api/rpc/callbacks/version_manager.py:119}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.api.rpc.callbacks.version_manager [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Version for resource type SubPort changed None to 1.0 on consumer Open vSwitch agent@os4 {{(pid=24305) _set_version /opt/stack/neutron/neutron/api/rpc/callbacks/version_manager.py:119}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.api.rpc.callbacks.version_manager [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Version for resource type SecurityGroup changed None to 1.0 on consumer Open vSwitch agent@os4 {{(pid=24305) _set_version /opt/stack/neutron/neutron/api/rpc/callbacks/version_manager.py:119}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.api.rpc.callbacks.version_manager [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Version for resource type SecurityGroupRule changed None to 1.0 on consumer Open vSwitch agent@os4 {{(pid=24305) _set_version /opt/stack/neutron/neutron/api/rpc/callbacks/version_manager.py:119}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.api.rpc.callbacks.version_manager [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Version for resource type Trunk changed None to 1.1 on consumer Open vSwitch agent@os4 {{(pid=24305) _set_version /opt/stack/neutron/neutron/api/rpc/callbacks/version_manager.py:119}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.api.rpc.callbacks.version_manager [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Version for resource type QosPolicy changed None to 1.5 on consumer Open vSwitch agent@os4 {{(pid=24305) _set_version /opt/stack/neutron/neutron/api/rpc/callbacks/version_manager.py:119}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.api.rpc.callbacks.version_manager [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Version for resource type Port changed None to 1.1 on consumer Open vSwitch agent@os4 {{(pid=24305) _set_version /opt/stack/neutron/neutron/api/rpc/callbacks/version_manager.py:119}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.db.agents_db [req-8b4ccea7-1462-43cc-9a21-f0013b797999 demo demo] Update consumer Metadata agent@os4 versions to: {} {{(pid=24305) get_agents_resource_versions /opt/stack/neutron/neutron/db/agents_db.py:405}}
May 05 14:12:56 os4 neutron-server[24158]: DEBUG
oslo_concurrency.lockutils [req-8b4ccea7-1462-43cc-9a21-f0013b797999
demo demo] Lock "event-dispatch" released by
"neutron.plugins.ml2.ovo_rpc.dispatch_events" :: held 0.191s
{{(pid=24305) inner
/usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282}}

In the nova-compute virt driver we start to convert the image from qcow2 to raw:

May 05 14:12:56 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] CMD "/usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=8 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389.part" returned: 0 in 0.073s {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385}}
May 05 14:12:56 os4 nova-compute[811]: DEBUG nova.virt.images [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] efc96458-7cd4-43e3-9a35-93001e98fd1a was qcow2, converting to raw {{(pid=811) fetch_to_raw /opt/stack/nova/nova/virt/images.py:146}}
May 05 14:12:56 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Running cmd (subprocess): qemu-img convert -O raw -f qcow2 /opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389.part /opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389.converted {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355}}

Neutron port is bound to our host:

May 05 14:12:56 os4 neutron-server[24158]: DEBUG neutron.wsgi [req-a75a4ec8-e81f-48e1-9569-a8fb90809f3f demo demo] http://10.42.0.53:9696/v2.0/extensions.json returned with HTTP 200 {{(pid=24305) __call__ /opt/stack/neutron/neutron/wsgi.py:715}}
May 05 14:12:56 os4 neutron-server[24158]: INFO neutron.wsgi [req-a75a4ec8-e81f-48e1-9569-a8fb90809f3f demo demo] 10.42.0.53 "GET /v2.0/extensions.json HTTP/1.1" status: 200  len: 7503 time: 0.0548379
May 05 14:12:57 os4 nova-compute[811]: DEBUG nova.network.neutronv2.api [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Successfully updated port: 08268814-29e2-4719-b417-8832395e5e3e {{(pid=811) _update_port /opt/stack/nova/nova/network/neutronv2/api.py:433}}
May 05 14:12:57 os4 nova-compute[811]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Acquired semaphore "refresh_cache-339dc23b-d7bd-4856-b17f-ae5b19ca12eb" {{(pid=811) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212}}
May 05 14:12:57 os4 nova-compute[811]: DEBUG nova.network.neutronv2.api [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] _get_instance_nw_info() {{(pid=811) _get_instance_nw_info /opt/stack/nova/nova/network/neutronv2/api.py:1283}}
May 05 14:12:57 os4 nova-compute[811]: DEBUG nova.network.neutronv2.api [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Instance cache missing network info. {{(pid=811) _get_preexisting_port_ids /opt/stack/nova/nova/network/neutronv2/api.py:2191}}

nova-compute fetched network info for the instance:

May 05 14:12:58 os4 nova-compute[811]: DEBUG nova.network.base_api [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Updating instance_info_cache with network_info: [{"profile": {}, "ovs_interfaceid": "08268814-29e2-4719-b417-8832395e5e3e", "preserve_on_delete": false, "network": {"bridge": "br-int", "subnets": [{"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "10.0.0.13"}], "version": 4, "meta": {"dhcp_server": "10.0.0.2"}, "dns": [], "routes": [], "cidr": "10.0.0.0/26", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "10.0.0.1"}}, {"ips": [{"meta": {}, "version": 6, "type": "fixed", "floating_ips": [], "address": "fdfe:8380:b8e:0:f816:3eff:fe77:5f94"}], "version": 6, "meta": {"ipv6_address_mode": "slaac", "dhcp_server": "fdfe:8380:b8e:0:f816:3eff:fee4:604"}, "dns": [], "routes": [], "cidr": "fdfe:8380:b8e::/64", "gateway": {"meta": {}, "version": 6, "type": "gateway", "address": "fdfe:8380:b8e::1"}}], "meta": {"injected": false, "tenant_id": "34e6ec64968a454993eda1a2051483bd", "mtu": 1450}, "id": "8356212e-f122-4dfc-9846-adecc23b4f34", "label": "private"}, "devname": "tap08268814-29", "vnic_type": "normal", "qbh_params": null, "meta": {}, "details": {"port_filter": true, "ovs_hybrid_plug": true}, "address": "fa:16:3e:77:5f:94", "active": false, "type": "ovs", "id": "08268814-29e2-4719-b417-8832395e5e3e", "qbg_params": null}] {{(pid=811) update_instance_cache_with_nw_info /opt/stack/nova/nova/network/base_api.py:43}}
May 05 14:12:58 os4 nova-compute[811]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Releasing semaphore "refresh_cache-339dc23b-d7bd-4856-b17f-ae5b19ca12eb" {{(pid=811) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:225}}
May 05 14:12:58 os4 nova-compute[811]: DEBUG nova.compute.manager [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Instance network_info: |[{"profile": {}, "ovs_interfaceid": "08268814-29e2-4719-b417-8832395e5e3e", "preserve_on_delete": false, "network": {"bridge": "br-int", "subnets": [{"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "10.0.0.13"}], "version": 4, "meta": {"dhcp_server": "10.0.0.2"}, "dns": [], "routes": [], "cidr": "10.0.0.0/26", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "10.0.0.1"}}, {"ips": [{"meta": {}, "version": 6, "type": "fixed", "floating_ips": [], "address": "fdfe:8380:b8e:0:f816:3eff:fe77:5f94"}], "version": 6, "meta": {"ipv6_address_mode": "slaac", "dhcp_server": "fdfe:8380:b8e:0:f816:3eff:fee4:604"}, "dns": [], "routes": [], "cidr": "fdfe:8380:b8e::/64", "gateway": {"meta": {}, "version": 6, "type": "gateway", "address": "fdfe:8380:b8e::1"}}], "meta": {"injected": false, "tenant_id": "34e6ec64968a454993eda1a2051483bd", "mtu": 1450}, "id": "8356212e-f122-4dfc-9846-adecc23b4f34", "label": "private"}, "devname": "tap08268814-29", "vnic_type": "normal", "qbh_params": null, "meta": {}, "details": {"port_filter": true, "ovs_hybrid_plug": true}, "address": "fa:16:3e:77:5f:94", "active": false, "type": "ovs", "id": "08268814-29e2-4719-b417-8832395e5e3e", "qbg_params": null}]| {{(pid=811) _allocate_network_async /opt/stack/nova/nova/compute/manager.py:1399}}

image finished converting (5s) (also apparently we love qemu-img info:

May 05 14:13:01 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] CMD "qemu-img convert -O raw -f qcow2 /opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389.part /opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389.converted" returned: 0 in 4.886s {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385}}
May 05 14:13:01 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Running cmd (subprocess): /usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=8 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389.converted {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355}}
May 05 14:13:01 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] CMD "/usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=8 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389.converted" returned: 0 in 0.043s {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385}}
May 05 14:13:01 os4 nova-compute[811]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "71e3784636393bd59c86544533ba3cf90216a389" released by "nova.virt.libvirt.imagebackend.fetch_func_sync" :: held 7.091s {{(pid=811) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282}}
May 05 14:13:01 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf touch -c /opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389 {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf touch -c /opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389" returned: 0 in 0.130s {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Running cmd (subprocess): /usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=8 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389 {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] CMD "/usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=8 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389" returned: 0 in 0.045s {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "71e3784636393bd59c86544533ba3cf90216a389" acquired by "nova.virt.libvirt.imagebackend.copy_qcow2_image" :: waited 0.000s {{(pid=811) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Running cmd (subprocess): /usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=8 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389 {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] CMD "/usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=8 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389" returned: 0 in 0.043s {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385}}

We create a qcow2 file to actually boot with a raw backing file:

May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Running cmd (subprocess): qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389 /opt/stack/data/nova/instances/339dc23b-d7bd-4856-b17f-ae5b19ca12eb/disk {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] CMD "qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389 /opt/stack/data/nova/instances/339dc23b-d7bd-4856-b17f-ae5b19ca12eb/disk" returned: 0 in 0.020s {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.disk.api [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Checking if we can resize image /opt/stack/data/nova/instances/339dc23b-d7bd-4856-b17f-ae5b19ca12eb/disk. size=21474836480 {{(pid=811) can_resize_image /opt/stack/nova/nova/virt/disk/api.py:214}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Running cmd (subprocess): /usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=8 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/339dc23b-d7bd-4856-b17f-ae5b19ca12eb/disk {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] CMD "/usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=8 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/339dc23b-d7bd-4856-b17f-ae5b19ca12eb/disk" returned: 0 in 0.043s {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385}}

And resize the image (if it was supposed to be bigger than the image we download):

May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Running cmd (subprocess): qemu-img resize /opt/stack/data/nova/instances/339dc23b-d7bd-4856-b17f-ae5b19ca12eb/disk 21474836480 {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] CMD "qemu-img resize /opt/stack/data/nova/instances/339dc23b-d7bd-4856-b17f-ae5b19ca12eb/disk 21474836480" returned: 0 in 0.024s {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "71e3784636393bd59c86544533ba3cf90216a389" released by "nova.virt.libvirt.imagebackend.copy_qcow2_image" :: held 0.134s {{(pid=811) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Running cmd (subprocess): /usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=8 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389 {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] CMD "/usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=8 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/_base/71e3784636393bd59c86544533ba3cf90216a389" returned: 0 in 0.043s {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.disk.api [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Checking if we can resize image /opt/stack/data/nova/instances/339dc23b-d7bd-4856-b17f-ae5b19ca12eb/disk. size=21474836480 {{(pid=811) can_resize_image /opt/stack/nova/nova/virt/disk/api.py:214}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Running cmd (subprocess): /usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=8 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/339dc23b-d7bd-4856-b17f-ae5b19ca12eb/disk {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.processutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] CMD "/usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=8 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/339dc23b-d7bd-4856-b17f-ae5b19ca12eb/disk" returned: 0 in 0.043s {{(pid=811) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.disk.api [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Cannot resize image /opt/stack/data/nova/instances/339dc23b-d7bd-4856-b17f-ae5b19ca12eb/disk to a smaller size. {{(pid=811) can_resize_image /opt/stack/nova/nova/virt/disk/api.py:220}}

nova-compute libvirt driver pre-creates the console for the instance so libvirt doesn't (else we can't read it):

May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.libvirt.driver [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Ensure instance console log exists: /opt/stack/data/nova/instances/339dc23b-d7bd-4856-b17f-ae5b19ca12eb/console.log {{(pid=811) _ensure_console_log_for_instance /opt/stack/nova/nova/virt/libvirt/driver.py:2963}}

nova-compute libvirt driver starts building libvirt config for the instance:

May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.libvirt.driver [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Start _get_guest_xml network_info=[{"profile": {}, "ovs_interfaceid": "08268814-29e2-4719-b417-8832395e5e3e", "preserve_on_delete": false, "network": {"bridge": "br-int", "subnets": [{"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "10.0.0.13"}], "version": 4, "meta": {"dhcp_server": "10.0.0.2"}, "dns": [], "routes": [], "cidr": "10.0.0.0/26", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "10.0.0.1"}}, {"ips": [{"meta": {}, "version": 6, "type": "fixed", "floating_ips": [], "address": "fdfe:8380:b8e:0:f816:3eff:fe77:5f94"}], "version": 6, "meta": {"ipv6_address_mode": "slaac", "dhcp_server": "fdfe:8380:b8e:0:f816:3eff:fee4:604"}, "dns": [], "routes": [], "cidr": "fdfe:8380:b8e::/64", "gateway": {"meta": {}, "version": 6, "type": "gateway", "address": "fdfe:8380:b8e::1"}}], "meta": {"injected": false, "tenant_id": "34e6ec64968a454993eda1a2051483bd", "mtu": 1450}, "id": "8356212e-f122-4dfc-9846-adecc23b4f34", "label": "private"}, "devname": "tap08268814-29", "vnic_type": "normal", "qbh_params": null, "meta": {}, "details": {"port_filter": true, "ovs_hybrid_plug": true}, "address": "fa:16:3e:77:5f:94", "active": false, "type": "ovs", "id": "08268814-29e2-4719-b417-8832395e5e3e", "qbg_params": null}] disk_info={'disk_bus': 'virtio', 'cdrom_bus': 'ide', 'mapping': {'disk': {'bus': 'virtio', 'boot_index': '1', 'type': 'disk', 'dev': u'vda'}, 'root': {'bus': 'virtio', 'boot_index': '1', 'type': 'disk', 'dev': u'vda'}}} image_meta=ImageMeta(checksum='9952833a08a5f5550e24b8c80bfb1c6a',container_format='bare',created_at=2017-05-05T18:10:16Z,direct_url=<?>,disk_format='raw',id=efc96458-7cd4-43e3-9a35-93001e98fd1a,min_disk=0,min_ram=0,name='u16',owner='7873b5dd5a014e0eb53b3a06cf71cd1e',properties=ImageMetaProps,protected=<?>,size=286720000,status='active',tags=<?>,updated_at=2017-05-05T18:10:17Z,virtual_size=<?>,visibility=<?>) rescue=Non
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.hardware [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Getting desirable topologies for flavor Flavor(created_at=2017-05-05T16:06:15Z,deleted=False,deleted_at=None,disabled=False,ephemeral_gb=0,extra_specs={},flavorid='2',id=7,is_public=True,memory_mb=2048,name='m1.small',projects=<?>,root_gb=20,rxtx_factor=1.0,swap=0,updated_at=None,vcpu_weight=0,vcpus=1) and image_meta ImageMeta(checksum='9952833a08a5f5550e24b8c80bfb1c6a',container_format='bare',created_at=2017-05-05T18:10:16Z,direct_url=<?>,disk_format='raw',id=efc96458-7cd4-43e3-9a35-93001e98fd1a,min_disk=0,min_ram=0,name='u16',owner='7873b5dd5a014e0eb53b3a06cf71cd1e',properties=ImageMetaProps,protected=<?>,size=286720000,status='active',tags=<?>,updated_at=2017-05-05T18:10:17Z,virtual_size=<?>,visibility=<?>), allow threads: True {{(pid=811) _get_desirable_cpu_topologies /opt/stack/nova/nova/virt/hardware.py:560}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.hardware [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Flavor limits 65536:65536:65536 {{(pid=811) _get_cpu_topology_constraints /opt/stack/nova/nova/virt/hardware.py:306}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.hardware [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Image limits 65536:65536:65536 {{(pid=811) _get_cpu_topology_constraints /opt/stack/nova/nova/virt/hardware.py:317}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.hardware [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Flavor pref -1:-1:-1 {{(pid=811) _get_cpu_topology_constraints /opt/stack/nova/nova/virt/hardware.py:340}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.hardware [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Image pref -1:-1:-1 {{(pid=811) _get_cpu_topology_constraints /opt/stack/nova/nova/virt/hardware.py:359}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.hardware [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Chosen -1:-1:-1 limits 65536:65536:65536 {{(pid=811) _get_cpu_topology_constraints /opt/stack/nova/nova/virt/hardware.py:388}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.hardware [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Topology preferred VirtCPUTopology(cores=-1,sockets=-1,threads=-1), maximum VirtCPUTopology(cores=65536,sockets=65536,threads=65536) {{(pid=811) _get_desirable_cpu_topologies /opt/stack/nova/nova/virt/hardware.py:564}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.hardware [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Build topologies for 1 vcpu(s) 1:1:1 {{(pid=811) _get_possible_cpu_topologies /opt/stack/nova/nova/virt/hardware.py:427}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.hardware [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Got 1 possible topologies {{(pid=811) _get_possible_cpu_topologies /opt/stack/nova/nova/virt/hardware.py:454}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.hardware [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Possible topologies [VirtCPUTopology(cores=1,sockets=1,threads=1)] {{(pid=811) _get_desirable_cpu_topologies /opt/stack/nova/nova/virt/hardware.py:569}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.hardware [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Sorted desired topologies [VirtCPUTopology(cores=1,sockets=1,threads=1)] {{(pid=811) _get_desirable_cpu_topologies /opt/stack/nova/nova/virt/hardware.py:594}}

nova-compute builds virtual interface object with network info:

May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.libvirt.vif [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] vif_type=ovs instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone='nova',cell_name=None,cleaned=False,config_drive='',created_at=2017-05-05T18:12:53Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,device_metadata=None,disable_terminate=False,display_description='ubuntu1',display_name='ubuntu1',ec2_ids=EC2Ids,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(7),host='os4',hostname='ubuntu1',id=2,image_ref='efc96458-7cd4-43e3-9a35-93001e98fd1a',info_cache=InstanceInfoCache,instance_type_id=7,kernel_id='',key_data='ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDcfMqWOU0bPsFuIdnXHaxqjxSsTOf0IAeAySYUUDsM+8Qo2bmd4oDzcdSRBnaEt2oIbyA6OVlZ9Ir5PNV+rhhutqwx0mJiPmmbqcE8nsCqa8mxahCED0NpGTi3uTuJcj+IXsr6kDqxoWXfVq+awZv/vHaGQP+oLTIDM0cPVrT1gTCYknqMeyLUCeehSVeCQM39jdyMt/+7TR9OMCiPPsv0vc0WR8jNMYvBVsv+7qpfZG5LLG+QMl5Vfe5kKG0cIZwrYeYnrhEJ7E1AXgPjaa38MqlQxoM1vCTAMGvqETEbJQBLFD9O+xGWsqXkDFHH8zfT6lw2F8CZwvh3FkyU7J+p sdague@kosh',key_name='pub',keypairs=KeyPairList,launch_index=0,launched_at=None,launched_on='os4',locked=False,locked_by=None,memory_mb=2048,metadata={},migration_context=<?>,new_flavor=None,node='os4',numa_topology=None,old_flavor=None,os_type=None,pci_devices=<?>,pci_requests=InstancePCIRequests,power_state=0,progress=0,project_id='34e6ec64968a454993eda1a2051483bd',ramdisk_id='',reservation_id='r-ax2kld90',root_device_name='/dev/vda',root_gb=20,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={boot_roles='anotherrole,Member',image_base_image_ref='efc96458-7cd4-43e3-9a35-93001e98fd1a',image_container_format='bare',image_disk_format='raw',image_min_disk='20',image_min_ram='0',network_allocated='True',owner_project_name='demo',owner_user_name='demo'},tags=<?>,task_state='spawning',terminated_at=None,updated_at=2017-05-05T18:12:55Z,user_data=None,user_id='7589bd4b8d2f46bea84bb5b5cbed9933',uuid=339dc23b-d7b
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.network.os_vif_util [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Converting VIF {"profile": {}, "ovs_interfaceid": "08268814-29e2-4719-b417-8832395e5e3e", "preserve_on_delete": false, "network": {"bridge": "br-int", "subnets": [{"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "10.0.0.13"}], "version": 4, "meta": {"dhcp_server": "10.0.0.2"}, "dns": [], "routes": [], "cidr": "10.0.0.0/26", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "10.0.0.1"}}, {"ips": [{"meta": {}, "version": 6, "type": "fixed", "floating_ips": [], "address": "fdfe:8380:b8e:0:f816:3eff:fe77:5f94"}], "version": 6, "meta": {"ipv6_address_mode": "slaac", "dhcp_server": "fdfe:8380:b8e:0:f816:3eff:fee4:604"}, "dns": [], "routes": [], "cidr": "fdfe:8380:b8e::/64", "gateway": {"meta": {}, "version": 6, "type": "gateway", "address": "fdfe:8380:b8e::1"}}], "meta": {"injected": false, "tenant_id": "34e6ec64968a454993eda1a2051483bd", "mtu": 1450}, "id": "8356212e-f122-4dfc-9846-adecc23b4f34", "label": "private"}, "devname": "tap08268814-29", "vnic_type": "normal", "qbh_params": null, "meta": {}, "details": {"port_filter": true, "ovs_hybrid_plug": true}, "address": "fa:16:3e:77:5f:94", "active": false, "type": "ovs", "id": "08268814-29e2-4719-b417-8832395e5e3e", "qbg_params": null} {{(pid=811) nova_to_osvif_vif /opt/stack/nova/nova/network/os_vif_util.py:413}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.network.os_vif_util [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Converted object VIFBridge(active=False,address=fa:16:3e:77:5f:94,bridge_name='qbr08268814-29',has_traffic_filtering=True,id=08268814-29e2-4719-b417-8832395e5e3e,network=Network(8356212e-f122-4dfc-9846-adecc23b4f34),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=False,vif_name='tap08268814-29') {{(pid=811) nova_to_osvif_vif /opt/stack/nova/nova/network/os_vif_util.py:425}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.objects.instance [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lazy-loading 'pci_devices' on Instance uuid 339dc23b-d7bd-4856-b17f-ae5b19ca12eb {{(pid=811) obj_load_attr /opt/stack/nova/nova/objects/instance.py:1034}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.libvirt.driver [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] End _get_guest_xml xml=<domain type="kvm">

nova-compute libvirt driver registers an expected callback from neutron for when the network is up and ready to answer DHCP:

May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.compute.manager [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Preparing to wait for external event network-vif-plugged-08268814-29e2-4719-b417-8832395e5e3e {{(pid=811) prepare_for_instance_event /opt/stack/nova/nova/compute/manager.py:326}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "339dc23b-d7bd-4856-b17f-ae5b19ca12eb-events" acquired by "nova.compute.manager._create_or_get_event" :: waited 0.000s {{(pid=811) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "339dc23b-d7bd-4856-b17f-ae5b19ca12eb-events" released by "nova.compute.manager._create_or_get_event" :: held 0.000s {{(pid=811) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282}}

nova-compute libvirt driver starts the guest paused and makes the request to neutron to plug the network:

May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.virt.libvirt.vif [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] vif_type=ovs instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone='nova',cell_name=None,cleaned=False,config_drive='',created_at=2017-05-05T18:12:53Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,device_metadata=None,disable_terminate=False,display_description='ubuntu1',display_name='ubuntu1',ec2_ids=EC2Ids,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(7),host='os4',hostname='ubuntu1',id=2,image_ref='efc96458-7cd4-43e3-9a35-93001e98fd1a',info_cache=InstanceInfoCache,instance_type_id=7,kernel_id='',key_data='ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDcfMqWOU0bPsFuIdnXHaxqjxSsTOf0IAeAySYUUDsM+8Qo2bmd4oDzcdSRBnaEt2oIbyA6OVlZ9Ir5PNV+rhhutqwx0mJiPmmbqcE8nsCqa8mxahCED0NpGTi3uTuJcj+IXsr6kDqxoWXfVq+awZv/vHaGQP+oLTIDM0cPVrT1gTCYknqMeyLUCeehSVeCQM39jdyMt/+7TR9OMCiPPsv0vc0WR8jNMYvBVsv+7qpfZG5LLG+QMl5Vfe5kKG0cIZwrYeYnrhEJ7E1AXgPjaa38MqlQxoM1vCTAMGvqETEbJQBLFD9O+xGWsqXkDFHH8zfT6lw2F8CZwvh3FkyU7J+p sdague@kosh',key_name='pub',keypairs=KeyPairList,launch_index=0,launched_at=None,launched_on='os4',locked=False,locked_by=None,memory_mb=2048,metadata={},migration_context=<?>,new_flavor=None,node='os4',numa_topology=None,old_flavor=None,os_type=None,pci_devices=PciDeviceList,pci_requests=InstancePCIRequests,power_state=0,progress=0,project_id='34e6ec64968a454993eda1a2051483bd',ramdisk_id='',reservation_id='r-ax2kld90',root_device_name='/dev/vda',root_gb=20,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={boot_roles='anotherrole,Member',image_base_image_ref='efc96458-7cd4-43e3-9a35-93001e98fd1a',image_container_format='bare',image_disk_format='raw',image_min_disk='20',image_min_ram='0',network_allocated='True',owner_project_name='demo',owner_user_name='demo'},tags=<?>,task_state='spawning',terminated_at=None,updated_at=2017-05-05T18:12:55Z,user_data=None,user_id='7589bd4b8d2f46bea84bb5b5cbed9933',uuid=33
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.network.os_vif_util [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Converting VIF {"profile": {}, "ovs_interfaceid": "08268814-29e2-4719-b417-8832395e5e3e", "preserve_on_delete": false, "network": {"bridge": "br-int", "subnets": [{"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "10.0.0.13"}], "version": 4, "meta": {"dhcp_server": "10.0.0.2"}, "dns": [], "routes": [], "cidr": "10.0.0.0/26", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "10.0.0.1"}}, {"ips": [{"meta": {}, "version": 6, "type": "fixed", "floating_ips": [], "address": "fdfe:8380:b8e:0:f816:3eff:fe77:5f94"}], "version": 6, "meta": {"ipv6_address_mode": "slaac", "dhcp_server": "fdfe:8380:b8e:0:f816:3eff:fee4:604"}, "dns": [], "routes": [], "cidr": "fdfe:8380:b8e::/64", "gateway": {"meta": {}, "version": 6, "type": "gateway", "address": "fdfe:8380:b8e::1"}}], "meta": {"injected": false, "tenant_id": "34e6ec64968a454993eda1a2051483bd", "mtu": 1450}, "id": "8356212e-f122-4dfc-9846-adecc23b4f34", "label": "private"}, "devname": "tap08268814-29", "vnic_type": "normal", "qbh_params": null, "meta": {}, "details": {"port_filter": true, "ovs_hybrid_plug": true}, "address": "fa:16:3e:77:5f:94", "active": false, "type": "ovs", "id": "08268814-29e2-4719-b417-8832395e5e3e", "qbg_params": null} {{(pid=811) nova_to_osvif_vif /opt/stack/nova/nova/network/os_vif_util.py:413}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG nova.network.os_vif_util [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Converted object VIFBridge(active=False,address=fa:16:3e:77:5f:94,bridge_name='qbr08268814-29',has_traffic_filtering=True,id=08268814-29e2-4719-b417-8832395e5e3e,network=Network(8356212e-f122-4dfc-9846-adecc23b4f34),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=False,vif_name='tap08268814-29') {{(pid=811) nova_to_osvif_vif /opt/stack/nova/nova/network/os_vif_util.py:425}}
May 05 14:13:02 os4 nova-compute[811]: DEBUG os_vif [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Plugging vif VIFBridge(active=False,address=fa:16:3e:77:5f:94,bridge_name='qbr08268814-29',has_traffic_filtering=True,id=08268814-29e2-4719-b417-8832395e5e3e,network=Network(8356212e-f122-4dfc-9846-adecc23b4f34),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=False,vif_name='tap08268814-29') {{(pid=811) plug /usr/local/lib/python2.7/dist-packages/os_vif/__init__.py:79}}
May 05 14:13:02 os4 nova-compute[811]: INFO os_vif [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Successfully plugged vif VIFBridge(active=False,address=fa:16:3e:77:5f:94,bridge_name='qbr08268814-29',has_traffic_filtering=True,id=08268814-29e2-4719-b417-8832395e5e3e,network=Network(8356212e-f122-4dfc-9846-adecc23b4f34),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=False,vif_name='tap08268814-29')

Plug event comes back from neutron, nova-compute libvirt driver unpauses the guest:

< trust me on this >


[nova-api] LOG.info(_LI('Creating event %(name)s:%(tag)s for '
                        'instance %(instance_uuid)s'),

[nova-compute]  LOG.debug('Received event %(event)s',
                          {'event': event.key},

[nova-compute]  LOG.debug('Processing event %(event)s',
                          {'event': event.key}, instance=instance)

nova-compute instance started:

May 05 14:13:04 os4 nova-compute[811]: DEBUG nova.virt.libvirt.driver [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Instance is running {{(pid=811) spawn /opt/stack/nova/nova/virt/libvirt/driver.py:2701}}
May 05 14:13:04 os4 nova-compute[811]: INFO nova.compute.manager [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Took 10.17 seconds to spawn the instance on the hypervisor.
May 05 14:13:04 os4 nova-compute[811]: DEBUG nova.compute.manager [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Checking state {{(pid=811) _get_power_state /opt/stack/nova/nova/compute/manager.py:1169}}
May 05 14:13:05 os4 nova-compute[811]: DEBUG nova.notifications.objects.base [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Defaulting the value of the field 'projects' to None in FlavorPayload due to 'Cannot call _load_projects on orphaned Flavor object' {{(pid=811) populate_schema /opt/stack/nova/nova/notifications/objects/base.py:119}}
May 05 14:13:05 os4 nova-scheduler[31143]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "host_instance" acquired by "nova.scheduler.host_manager.update_instance_info" :: waited 0.000s {{(pid=31143) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270}}
May 05 14:13:05 os4 nova-scheduler[31143]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "host_instance" released by "nova.scheduler.host_manager.update_instance_info" :: held 0.001s {{(pid=31143) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282}}
May 05 14:13:05 os4 nova-compute[811]: INFO nova.compute.manager [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] [instance: 339dc23b-d7bd-4856-b17f-ae5b19ca12eb] Took 10.90 seconds to build instance.
May 05 14:13:05 os4 nova-compute[811]: DEBUG oslo_concurrency.lockutils [req-692d7939-4dca-4fc6-b8ff-95e68d752575 demo demo] Lock "339dc23b-d7bd-4856-b17f-ae5b19ca12eb" released by "nova.compute.manager._locked_do_build_and_run_instance" :: held 10.990s {{(pid=811) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282}}