In praise of systemd

There was definitely a lot of hate around systemd in the Linux community over the last few years as all the Linux distros moved over to it. Things change all the time, and I personally never understood this one. It wasn’t like the random collection of just barely working shell scripts that may or may not have implemented “status” was really a technical superior solution.

Recently I’ve been plumbing more native systemd support into DevStack (OpenStack‘s development environment setup tool). Personally systemd is just another way to start services, it does a few things better at the cost of having to learn a new interface. But some huge wins in a developer context come from the new logging system with it, journald.

Systemd has it’s own internal journaling system, which can reflect out to syslog and friends. However, it’s inherently much richer. Journal messages can include not only text, but arbitrary metadata. You can then query the journal with this arbitrary metadata.

A concrete example of this is the request-id in OpenStack. On any inbound REST API call a request-id is generated, then passed around between workers in that service. This lets you, theoretically, trace through multiple systems to see what is going on. In practice, you end up having to build some other system to collect and search these logs. But with some changes to OpenStack’s logging subsystem to emit journal native messages, you can do the following:

journalctl REQUEST_ID=req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb

And get the following:

-- Logs begin at Wed 2017-03-29 08:23:23 EDT, end at Wed 2017-03-29 16:19:46 EDT. --
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.api.openstack.wsgi [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Action: 'create', calling method: <bound method ServersController.create of <nova.api.openstack.compute.servers.ServersController object at 0x7fa7c93584d0>>, body: {"server": {"min_count": 1, "flavorRef": "d2", "name": "test1", "imageRef": "f69a1669-34b6-4a2a-9f98-6c4ae0a9d21a", "max_count": 1}} from (pid=14042) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:621
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.api.openstack.compute.servers [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Running _create_extension_point for <Extension: name=MultipleCreate, alias=os-multiple-create, version=1> from (pid=14042) _create_extension_point /opt/stack/nova/nova/api/openstack/compute/servers.py:740
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.api.openstack.compute.servers [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Running _create_extension_point for <Extension: name=BlockDeviceMapping, alias=os-block-device-mapping, version=1> from (pid=14042) _create_extension_point /opt/stack/nova/nova/api/openstack/compute/servers.py:740
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.api.openstack.compute.servers [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Running _create_extension_point for <Extension: name=BlockDeviceMappingV1, alias=os-block-device-mapping-v1, version=1> from (pid=14042) _create_extension_point /opt/stack/nova/nova/api/openstack/compute/servers.py:740
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.api.openstack.compute.servers [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Running _create_extension_point for <Extension: name=AvailabilityZone, alias=os-availability-zone, version=1> from (pid=14042) _create_extension_point /opt/stack/nova/nova/api/openstack/compute/servers.py:740
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.api.openstack.compute.servers [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Running _create_extension_point for <Extension: name=UserData, alias=os-user-data, version=1> from (pid=14042) _create_extension_point /opt/stack/nova/nova/api/openstack/compute/servers.py:740
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.api.openstack.compute.servers [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Running _create_extension_point for <Extension: name=Keypairs, alias=os-keypairs, version=1> from (pid=14042) _create_extension_point /opt/stack/nova/nova/api/openstack/compute/servers.py:740
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.api.openstack.compute.servers [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Running _create_extension_point for <Extension: name=SchedulerHints, alias=os-scheduler-hints, version=1> from (pid=14042) _create_extension_point /opt/stack/nova/nova/api/openstack/compute/servers.py:740
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.api.openstack.compute.servers [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Running _create_extension_point for <Extension: name=SecurityGroups, alias=os-security-groups, version=1> from (pid=14042) _create_extension_point /opt/stack/nova/nova/api/openstack/compute/servers.py:740
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.api.openstack.compute.servers [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Running _create_extension_point for <Extension: name=ConfigDrive, alias=os-config-drive, version=1> from (pid=14042) _create_extension_point /opt/stack/nova/nova/api/openstack/compute/servers.py:740
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.network.neutronv2.api [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] validate_networks() for None from (pid=14042) validate_networks /opt/stack/nova/nova/network/neutronv2/api.py:1622
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG neutronclient.v2_0.client [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] GET call to neutron for http://10.42.0.53:9696/v2.0/networks.json?tenant_id=70162ab521a5455faff0680e923dd091&shared=False used request id req-19605b00-631d-41fe-9d2e-78583e4b0999 from (pid=14042) _append_request_id /usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG neutronclient.v2_0.client [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] GET call to neutron for http://10.42.0.53:9696/v2.0/networks.json?shared=True used request id req-f53ce1bb-d261-4a15-a75f-4320b7342023 from (pid=14042) _append_request_id /usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG neutronclient.v2_0.client [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] GET call to neutron for http://10.42.0.53:9696/v2.0/quotas/70162ab521a5455faff0680e923dd091.json used request id req-77f7c098-8cc0-4396-b6bb-ff53db580a5b from (pid=14042) _append_request_id /usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG neutronclient.v2_0.client [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] GET call to neutron for http://10.42.0.53:9696/v2.0/ports.json?fields=id&tenant_id=70162ab521a5455faff0680e923dd091 used request id req-1183c82b-cd80-4a19-ae07-888f5cab0aec from (pid=14042) _append_request_id /usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.virt.hardware [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] emulator threads policy constraint: None from (pid=14042) get_emulator_threads_constraint /opt/stack/nova/nova/virt/hardware.py:1286
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.quota [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Getting quotas for project 70162ab521a5455faff0680e923dd091. Resources: ['metadata_items'] from (pid=14042) _get_quotas /opt/stack/nova/nova/quota.py:369
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.quota [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Getting quotas for user 444f517480154b5588b354e64c50c075 and project 70162ab521a5455faff0680e923dd091. Resources: ['metadata_items'] from (pid=14042) _get_quotas /opt/stack/nova/nova/quota.py:361
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.quota [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Getting quotas for project 70162ab521a5455faff0680e923dd091. Resources: ['injected_files'] from (pid=14042) _get_quotas /opt/stack/nova/nova/quota.py:369
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.quota [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Getting quotas for user 444f517480154b5588b354e64c50c075 and project 70162ab521a5455faff0680e923dd091. Resources: ['injected_files'] from (pid=14042) _get_quotas /opt/stack/nova/nova/quota.py:361
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.quota [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Getting quotas for project 70162ab521a5455faff0680e923dd091. Resources: ['injected_file_content_bytes', 'injected_file_path_bytes'] from (pid=14042) _get_quotas /opt/stack/nova/nova/quota.py:369
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.quota [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Getting quotas for user 444f517480154b5588b354e64c50c075 and project 70162ab521a5455faff0680e923dd091. Resources: ['injected_file_content_bytes', 'injected_file_path_bytes'] from (pid=14042) _get_quotas /opt/stack/nova/nova/quota.py:361
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.quota [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Reserving resources using context.project_id: 70162ab521a5455faff0680e923dd091 from (pid=14042) reserve /opt/stack/nova/nova/quota.py:500
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.quota [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Reserving resources using context.user_id: 444f517480154b5588b354e64c50c075 from (pid=14042) reserve /opt/stack/nova/nova/quota.py:505
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.quota [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Attempting to reserve resources for project 70162ab521a5455faff0680e923dd091 and user 444f517480154b5588b354e64c50c075. Deltas: {'instances': 1, 'ram': 1024, 'cores': 1} from (pid=14042) reserve /opt/stack/nova/nova/quota.py:510
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.quota [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Quota limits for project 70162ab521a5455faff0680e923dd091: {'project_id': u'70162ab521a5455faff0680e923dd091'} from (pid=14042) reserve /opt/stack/nova/nova/quota.py:519
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.quota [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Getting quotas for project 70162ab521a5455faff0680e923dd091. Resources: ['instances', 'ram', 'cores'] from (pid=14042) _get_quotas /opt/stack/nova/nova/quota.py:369
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.quota [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Quotas for project 70162ab521a5455faff0680e923dd091 after resource sync: {'instances': 10, 'ram': 51200, 'cores': 20} from (pid=14042) reserve /opt/stack/nova/nova/quota.py:525
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.quota [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Getting quotas for user 444f517480154b5588b354e64c50c075 and project 70162ab521a5455faff0680e923dd091. Resources: ['instances', 'ram', 'cores'] from (pid=14042) _get_quotas /opt/stack/nova/nova/quota.py:361
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.quota [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Quotas for project 70162ab521a5455faff0680e923dd091 and user 444f517480154b5588b354e64c50c075 after resource sync: {'instances': 10, 'ram': 51200, 'cores': 20} from (pid=14042) reserve /opt/stack/nova/nova/quota.py:533
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.db.sqlalchemy.api [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] QuotaUsage has not changed, refresh is unnecessary for: {'user_id': u'444f517480154b5588b354e64c50c075', 'deleted_at': None, 'reserved': 0, 'in_use': 0, 'deleted': 0, 'created_at': datetime.datetime(2017, 3, 29, 20, 16, 5, 803775), 'updated_at': datetime.datetime(2017, 3, 29, 20, 16, 5, 802794), 'until_refresh': None, 'resource': 'instances', 'project_id': u'70162ab521a5455faff0680e923dd091', 'id': 1} from (pid=14042) _refresh_quota_usages /opt/stack/nova/nova/db/sqlalchemy/api.py:3694
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.db.sqlalchemy.api [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] QuotaUsage has not changed, refresh is unnecessary for: {'user_id': u'444f517480154b5588b354e64c50c075', 'deleted_at': None, 'reserved': 0, 'in_use': 0, 'deleted': 0, 'created_at': datetime.datetime(2017, 3, 29, 20, 16, 5, 808250), 'updated_at': datetime.datetime(2017, 3, 29, 20, 16, 5, 807797), 'until_refresh': None, 'resource': 'ram', 'project_id': u'70162ab521a5455faff0680e923dd091', 'id': 2} from (pid=14042) _refresh_quota_usages /opt/stack/nova/nova/db/sqlalchemy/api.py:3694
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.db.sqlalchemy.api [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] QuotaUsage has not changed, refresh is unnecessary for: {'user_id': u'444f517480154b5588b354e64c50c075', 'deleted_at': None, 'reserved': 0, 'in_use': 0, 'deleted': 0, 'created_at': datetime.datetime(2017, 3, 29, 20, 16, 5, 810384), 'updated_at': datetime.datetime(2017, 3, 29, 20, 16, 5, 809969), 'until_refresh': None, 'resource': 'cores', 'project_id': u'70162ab521a5455faff0680e923dd091', 'id': 3} from (pid=14042) _refresh_quota_usages /opt/stack/nova/nova/db/sqlalchemy/api.py:3694
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.db.sqlalchemy.api [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Copying QuotaUsage for resource "instances" from user_usages into project_usages: {'user_id': u'444f517480154b5588b354e64c50c075', 'deleted_at': None, 'reserved': 0, 'in_use': 0, 'deleted': 0, 'created_at': datetime.datetime(2017, 3, 29, 20, 16, 5, 803775), 'updated_at': datetime.datetime(2017, 3, 29, 20, 16, 5, 802794), 'until_refresh': None, 'resource': 'instances', 'project_id': u'70162ab521a5455faff0680e923dd091', 'id': 1} from (pid=14042) quota_reserve /opt/stack/nova/nova/db/sqlalchemy/api.py:3842
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.db.sqlalchemy.api [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Copying QuotaUsage for resource "ram" from user_usages into project_usages: {'user_id': u'444f517480154b5588b354e64c50c075', 'deleted_at': None, 'reserved': 0, 'in_use': 0, 'deleted': 0, 'created_at': datetime.datetime(2017, 3, 29, 20, 16, 5, 808250), 'updated_at': datetime.datetime(2017, 3, 29, 20, 16, 5, 807797), 'until_refresh': None, 'resource': 'ram', 'project_id': u'70162ab521a5455faff0680e923dd091', 'id': 2} from (pid=14042) quota_reserve /opt/stack/nova/nova/db/sqlalchemy/api.py:3842
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.db.sqlalchemy.api [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Copying QuotaUsage for resource "cores" from user_usages into project_usages: {'user_id': u'444f517480154b5588b354e64c50c075', 'deleted_at': None, 'reserved': 0, 'in_use': 0, 'deleted': 0, 'created_at': datetime.datetime(2017, 3, 29, 20, 16, 5, 810384), 'updated_at': datetime.datetime(2017, 3, 29, 20, 16, 5, 809969), 'until_refresh': None, 'resource': 'cores', 'project_id': u'70162ab521a5455faff0680e923dd091', 'id': 3} from (pid=14042) quota_reserve /opt/stack/nova/nova/db/sqlalchemy/api.py:3842
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.quota [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Created reservations ['b8e99024-107c-4992-b7ea-c96284033336', '15691130-ae33-4dc6-b9cb-cbdc6dc7b407', 'e0fe21ab-eb0e-43a2-898d-631871b5142e'] from (pid=14042) reserve /opt/stack/nova/nova/quota.py:1383
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.compute.api [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Going to run 1 instances... from (pid=14042) _provision_instances /opt/stack/nova/nova/compute/api.py:1002
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.compute.api [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] 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='f69a1669-34b6-4a2a-9f98-6c4ae0a9d21a',instance=<?>,instance_uuid=<?>,no_device=False,snapshot_id=None,source_type='image',tag=None,updated_at=<?>,volume_id=None,volume_size=None)] from (pid=14042) _bdm_validate_set_size_and_instance /opt/stack/nova/nova/compute/api.py:1339
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG nova.quota [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Committed reservations [u'b8e99024-107c-4992-b7ea-c96284033336', u'15691130-ae33-4dc6-b9cb-cbdc6dc7b407', u'e0fe21ab-eb0e-43a2-898d-631871b5142e'] from (pid=14042) commit /opt/stack/nova/nova/quota.py:1409
Mar 29 16:16:05 os4 nova-api[14042]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CAST unique_id: ce8a6568de9f4cc98ff3f06e0ca4004a exchange 'nova' topic 'conductor' from (pid=14042) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:489
Mar 29 16:16:05 os4 nova-api[14042]: INFO nova.osapi_compute.wsgi.server [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] 10.42.0.53 "POST /v2.1/servers HTTP/1.1" status: 202 len: 795 time: 0.8296130
Mar 29 16:16:05 os4 nova-conductor[14326]: WARNING oslo_config.cfg [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Option "scheduler_default_filters" from group "DEFAULT" is deprecated. Use option "enabled_filters" from group "filter_scheduler".
Mar 29 16:16:05 os4 nova-conductor[14326]: DEBUG oslo_db.sqlalchemy.engines [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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 from (pid=14326) _check_effective_sql_mode /usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:261
Mar 29 16:16:05 os4 nova-conductor[14326]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CALL msg_id: 917d9b546f5f4809a5dc38d3399bc714 exchange 'nova' topic 'scheduler' from (pid=14326) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:489
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CAST unique_id: ac54c940a3064721907949fbf6f3af48 NOTIFY exchange 'nova' topic 'notifications.info' from (pid=14269) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:473
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.scheduler.host_manager [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Found 2 cells: 00000000-0000-0000-0000-000000000000, 31d98bab-f734-4463-8f3f-87b604d0bd2b from (pid=14269) _get_computes_all_cells /opt/stack/nova/nova/scheduler/host_manager.py:586
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.scheduler.host_manager [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Getting compute nodes and services for cell 00000000-0000-0000-0000-000000000000(cell0) from (pid=14269) _get_computes_all_cells /opt/stack/nova/nova/scheduler/host_manager.py:591
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG oslo_db.sqlalchemy.engines [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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 from (pid=14269) _check_effective_sql_mode /usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:261
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.scheduler.host_manager [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Getting compute nodes and services for cell 31d98bab-f734-4463-8f3f-87b604d0bd2b(cell1) from (pid=14269) _get_computes_all_cells /opt/stack/nova/nova/scheduler/host_manager.py:591
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG oslo_db.sqlalchemy.engines [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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 from (pid=14269) _check_effective_sql_mode /usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:261
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG oslo_concurrency.lockutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Lock "(u'os4', u'os4')" acquired by "nova.scheduler.host_manager._locked_update" :: waited 0.000s from (pid=14269) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.scheduler.host_manager [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Update host state from compute node: ComputeNode(cpu_allocation_ratio=16.0,cpu_info='{"vendor": "Intel", "model": "Broadwell", "arch": "x86_64", "features": ["smap", "avx", "clflush", "sep", "rtm", "vme", "dtes64", "invpcid", "tsc", "fsgsbase", "xsave", "pge", "vmx", "erms", "xtpr", "cmov", "hle", "smep", "ssse3", "est", "pat", "monitor", "smx", "pbe", "lm", "msr", "adx", "3dnowprefetch", "nx", "fxsr", "syscall", "tm", "sse4.1", "pae", "sse4.2", "pclmuldq", "acpi", "fma", "tsc-deadline", "mmx", "osxsave", "cx8", "mce", "de", "tm2", "ht", "pse", "lahf_lm", "abm", "rdseed", "popcnt", "mca", "pdpe1gb", "apic", "sse", "f16c", "ds", "invtsc", "pni", "rdtscp", "avx2", "aes", "sse2", "ss", "ds_cpl", "bmi1", "bmi2", "pcid", "fpu", "cx16", "pse36", "mtrr", "movbe", "pdcm", "rdrand", "x2apic"], "topology": {"cores": 2, "cells": 1, "threads": 2, "sockets": 1}}',created_at=2017-03-29T10:37:36Z,current_workload=0,deleted=False,deleted_at=None,disk_allocation_ratio=1.0,disk_available_least=195,free_disk_gb=218,free_ram_mb=15435,host='os4',host_ip=10.42.0.53,hypervisor_hostname='os4',hypervisor_type='QEMU',hypervisor_version=2005000,id=1,local_gb=218,local_gb_used=0,memory_mb=15947,memory_mb_used=512,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", "mempages", "pinned_cpus", "memory", "siblings", "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": ["total", "used", "reserved", "size_kb"], "nova_object.name": "NUMAPagesTopology", "nova_object.data": {"used": 0, "total": 4082564, "reserved": 0, "size_kb": 4}, "nova_object.namespace": "nova"}, {"nova_object.version": "1.1", "nova_object.changes": ["total", "used", "reserved", "size_kb"], "nova_object.name": "NUMAPagesTopology", "nova_object.data": {"used": 0, "total": 0, "reserved": 0, "size_kb": 2048}, "nova_object.namespace": "nova"}, {"nova_object.version": "1.1", "nova_object.changes": ["total", "used", "reserved", "size_kb"], "nova_object.name": "NUMAPagesTopology", "nova_object.data": {"used": 0, "total": 0, "reserved": 0, "size_kb": 1048576}, "nova_object.namespace": "nova"}], "id": 0}, "nova_object.namespace": "nova"}]}, "nova_object.namespace": "nova"}',pci_device_pools=PciDevicePoolList,ram_allocation_ratio=1.5,running_vms=0,service_id=None,stats={},supported_hv_specs=[HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec],updated_at=2017-03-29T20:16:00Z,uuid=aa91aff1-89f9-47f7-a66c-8a60d87aa76d,vcpus=4,vcpus_used=0) from (pid=14269) _locked_update /opt/stack/nova/nova/scheduler/host_manager.py:168
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.scheduler.host_manager [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Update host state with aggregates: [] from (pid=14269) _locked_update /opt/stack/nova/nova/scheduler/host_manager.py:171
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.scheduler.host_manager [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Update host state with service dict: {'binary': u'nova-compute', 'deleted': False, 'created_at': datetime.datetime(2017, 3, 29, 10, 37, 36, tzinfo=<iso8601.Utc>), 'updated_at': datetime.datetime(2017, 3, 29, 20, 16, 5, tzinfo=<iso8601.Utc>), 'report_count': 3471, 'topic': u'compute', 'host': u'os4', 'version': 17, 'disabled': False, 'forced_down': False, 'last_seen_up': datetime.datetime(2017, 3, 29, 20, 16, 5, tzinfo=<iso8601.Utc>), 'deleted_at': None, 'disabled_reason': None, 'id': 6} from (pid=14269) _locked_update /opt/stack/nova/nova/scheduler/host_manager.py:174
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.scheduler.host_manager [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Update host state with instances: {} from (pid=14269) _locked_update /opt/stack/nova/nova/scheduler/host_manager.py:177
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG oslo_concurrency.lockutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Lock "(u'os4', u'os4')" released by "nova.scheduler.host_manager._locked_update" :: held 0.005s from (pid=14269) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.filters [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Starting with 1 host(s) from (pid=14269) get_filtered_objects /opt/stack/nova/nova/filters.py:70
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.scheduler.filters.retry_filter [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Re-scheduling is disabled from (pid=14269) host_passes /opt/stack/nova/nova/scheduler/filters/retry_filter.py:34
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.filters [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Filter RetryFilter returned 1 host(s) from (pid=14269) get_filtered_objects /opt/stack/nova/nova/filters.py:104
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.filters [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Filter AvailabilityZoneFilter returned 1 host(s) from (pid=14269) get_filtered_objects /opt/stack/nova/nova/filters.py:104
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.filters [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Filter RamFilter returned 1 host(s) from (pid=14269) get_filtered_objects /opt/stack/nova/nova/filters.py:104
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.filters [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Filter DiskFilter returned 1 host(s) from (pid=14269) get_filtered_objects /opt/stack/nova/nova/filters.py:104
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.filters [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Filter ComputeFilter returned 1 host(s) from (pid=14269) get_filtered_objects /opt/stack/nova/nova/filters.py:104
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.filters [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Filter ComputeCapabilitiesFilter returned 1 host(s) from (pid=14269) get_filtered_objects /opt/stack/nova/nova/filters.py:104
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.filters [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Filter ImagePropertiesFilter returned 1 host(s) from (pid=14269) get_filtered_objects /opt/stack/nova/nova/filters.py:104
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.filters [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Filter ServerGroupAntiAffinityFilter returned 1 host(s) from (pid=14269) get_filtered_objects /opt/stack/nova/nova/filters.py:104
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.filters [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Filter ServerGroupAffinityFilter returned 1 host(s) from (pid=14269) get_filtered_objects /opt/stack/nova/nova/filters.py:104
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.filters [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Filter SameHostFilter returned 1 host(s) from (pid=14269) get_filtered_objects /opt/stack/nova/nova/filters.py:104
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.filters [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Filter DifferentHostFilter returned 1 host(s) from (pid=14269) get_filtered_objects /opt/stack/nova/nova/filters.py:104
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.scheduler.filter_scheduler [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Filtered [(os4, os4) ram: 15435MB disk: 199680MB io_ops: 0 instances: 0] from (pid=14269) _schedule /opt/stack/nova/nova/scheduler/filter_scheduler.py:114
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.scheduler.filter_scheduler [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Weighed [WeighedHost [host: (os4, os4) ram: 15435MB disk: 199680MB io_ops: 0 instances: 0, weight: 0.0]] from (pid=14269) _schedule /opt/stack/nova/nova/scheduler/filter_scheduler.py:119
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.scheduler.filter_scheduler [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Selected host: WeighedHost [host: (os4, os4) ram: 15435MB disk: 199680MB io_ops: 0 instances: 0, weight: 0.0] from (pid=14269) _schedule /opt/stack/nova/nova/scheduler/filter_scheduler.py:126
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG oslo_concurrency.lockutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Lock "(u'os4', u'os4')" acquired by "nova.scheduler.host_manager._locked" :: waited 0.000s from (pid=14269) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG nova.virt.hardware [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Require both a host and instance NUMA topology to fit instance on host. from (pid=14269) numa_fit_instance_to_host /opt/stack/nova/nova/virt/hardware.py:1466
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG oslo_concurrency.lockutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Lock "(u'os4', u'os4')" released by "nova.scheduler.host_manager._locked" :: held 0.003s from (pid=14269) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CAST unique_id: fcea183f04574d61901f435df9d4fba0 NOTIFY exchange 'nova' topic 'notifications.info' from (pid=14269) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:473
Mar 29 16:16:06 os4 nova-scheduler[14269]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] sending reply msg_id: 917d9b546f5f4809a5dc38d3399bc714 reply queue: reply_8feb4f5bbc7d493c8821bc41ffee5e1a time elapsed: 0.215702679008s from (pid=14269) _send_reply /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:90
Mar 29 16:16:06 os4 nova-conductor[14326]: DEBUG oslo_db.sqlalchemy.engines [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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 from (pid=14326) _check_effective_sql_mode /usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:261
Mar 29 16:16:06 os4 nova-conductor[14326]: DEBUG oslo_db.sqlalchemy.engines [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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 from (pid=14326) _check_effective_sql_mode /usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:261
Mar 29 16:16:06 os4 nova-conductor[14326]: DEBUG nova.conductor.manager [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] 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='f69a1669-34b6-4a2a-9f98-6c4ae0a9d21a',instance=<?>,instance_uuid=<?>,no_device=False,snapshot_id=None,source_type='image',tag=None,updated_at=<?>,volume_id=None,volume_size=None)] from (pid=14326) _create_block_device_mapping /opt/stack/nova/nova/conductor/manager.py:841
Mar 29 16:16:06 os4 nova-conductor[14326]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CAST unique_id: cb281d7a070a47e29aa664ff22879597 exchange 'nova' topic 'compute.os4' from (pid=14326) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:489
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG oslo_concurrency.lockutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Lock "a70f2d77-f140-4edf-bf38-8b07076be37a" acquired by "nova.compute.manager._locked_do_build_and_run_instance" :: waited 0.000s from (pid=14334) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CALL msg_id: 38331690f1924074ba2146e3e22ec717 exchange 'nova' topic 'conductor' from (pid=14334) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:489
Mar 29 16:16:06 os4 nova-conductor[14327]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] sending reply msg_id: 38331690f1924074ba2146e3e22ec717 reply queue: reply_2d509f4c3c904a8d83ad6a659f755bf2 time elapsed: 0.0114914269943s from (pid=14327) _send_reply /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:90
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG nova.compute.manager [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] Starting instance... from (pid=14334) _do_build_and_run_instance /opt/stack/nova/nova/compute/manager.py:1747
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CALL msg_id: 5a0709355daf4e4f8dd4589455fdffd8 exchange 'nova' topic 'conductor' from (pid=14334) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:489
Mar 29 16:16:06 os4 nova-conductor[14326]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] sending reply msg_id: 5a0709355daf4e4f8dd4589455fdffd8 reply queue: reply_2d509f4c3c904a8d83ad6a659f755bf2 time elapsed: 0.0587505440053s from (pid=14326) _send_reply /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:90
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CAST unique_id: b400e8e03fed4cc19a7af04d81a25417 NOTIFY exchange 'nova' topic 'notifications.info' from (pid=14334) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:473
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG nova.notifications.objects.base [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Defaulting the value of the field 'projects' to None in FlavorPayload due to 'Cannot call _load_projects on orphaned Flavor object' from (pid=14334) populate_schema /opt/stack/nova/nova/notifications/objects/base.py:118
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CAST unique_id: dff4adf357e940ae91140eb047dbed8a NOTIFY exchange 'nova' topic 'versioned_notifications.info' from (pid=14334) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:473
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG oslo_concurrency.lockutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Lock "compute_resources" acquired by "nova.compute.resource_tracker.instance_claim" :: waited 0.000s from (pid=14334) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG nova.compute.resource_tracker [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Memory overhead for 1024 MB instance; 0 MB from (pid=14334) instance_claim /opt/stack/nova/nova/compute/resource_tracker.py:147
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG nova.compute.resource_tracker [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Disk overhead for 10 GB instance; 0 GB from (pid=14334) instance_claim /opt/stack/nova/nova/compute/resource_tracker.py:150
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CALL msg_id: 57afd33c5efd4638badeb6efd1242afa exchange 'nova' topic 'conductor' from (pid=14334) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:489
Mar 29 16:16:06 os4 nova-conductor[14327]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] sending reply msg_id: 57afd33c5efd4638badeb6efd1242afa reply queue: reply_2d509f4c3c904a8d83ad6a659f755bf2 time elapsed: 0.00463710498298s from (pid=14327) _send_reply /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:90
Mar 29 16:16:06 os4 nova-compute[14334]: INFO nova.compute.claims [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] Attempting claim on node os4: memory 1024 MB, disk 10 GB, vcpus 1 CPU
Mar 29 16:16:06 os4 nova-compute[14334]: INFO nova.compute.claims [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] Total memory: 15947 MB, used: 512.00 MB
Mar 29 16:16:06 os4 nova-compute[14334]: INFO nova.compute.claims [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] memory limit: 23920.50 MB, free: 23408.50 MB
Mar 29 16:16:06 os4 nova-compute[14334]: INFO nova.compute.claims [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] Total disk: 218 GB, used: 0.00 GB
Mar 29 16:16:06 os4 nova-compute[14334]: INFO nova.compute.claims [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] disk limit: 218.00 GB, free: 218.00 GB
Mar 29 16:16:06 os4 nova-compute[14334]: INFO nova.compute.claims [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] Total vcpu: 4 VCPU, used: 0.00 VCPU
Mar 29 16:16:06 os4 nova-compute[14334]: INFO nova.compute.claims [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] vcpu limit not specified, defaulting to unlimited
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG nova.virt.hardware [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Require both a host and instance NUMA topology to fit instance on host. from (pid=14334) numa_fit_instance_to_host /opt/stack/nova/nova/virt/hardware.py:1466
Mar 29 16:16:06 os4 nova-compute[14334]: INFO nova.compute.claims [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] Claim successful on node os4
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CALL msg_id: 572a6e0e3cd642bab51844504c947944 exchange 'nova' topic 'conductor' from (pid=14334) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:489
Mar 29 16:16:06 os4 nova-conductor[14326]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] sending reply msg_id: 572a6e0e3cd642bab51844504c947944 reply queue: reply_2d509f4c3c904a8d83ad6a659f755bf2 time elapsed: 0.0616553190048s from (pid=14326) _send_reply /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:90
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CALL msg_id: 7f329ad9e6ce406cae034a83ad6dcb92 exchange 'nova' topic 'conductor' from (pid=14334) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:489
Mar 29 16:16:06 os4 nova-conductor[14327]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] sending reply msg_id: 7f329ad9e6ce406cae034a83ad6dcb92 reply queue: reply_2d509f4c3c904a8d83ad6a659f755bf2 time elapsed: 0.00696902099298s from (pid=14327) _send_reply /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:90
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG nova.scheduler.client.report [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] Sending allocation for instance {'MEMORY_MB': 1024, 'VCPU': 1, 'DISK_GB': 10} from (pid=14334) _allocate_for_instance /opt/stack/nova/nova/scheduler/client/report.py:807
Mar 29 16:16:06 os4 nova-compute[14334]: INFO nova.scheduler.client.report [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] Submitted allocation for instance
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CALL msg_id: 36a079cbc7304ed6bc5d2e0ca0b3404b exchange 'nova' topic 'conductor' from (pid=14334) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:489
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG nova.scheduler.client.report [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Refreshing aggregate associations for resource provider aa91aff1-89f9-47f7-a66c-8a60d87aa76d from (pid=14334) _ensure_resource_provider /opt/stack/nova/nova/scheduler/client/report.py:437
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG nova.scheduler.client.report [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Updating our resource provider generation from 1 to 2 from (pid=14334) _get_inventory_and_update_provider_generation /opt/stack/nova/nova/scheduler/client/report.py:480
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG oslo_concurrency.lockutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Lock "compute_resources" released by "nova.compute.resource_tracker.instance_claim" :: held 0.291s from (pid=14334) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG nova.compute.manager [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] Start building networks asynchronously for instance. from (pid=14334) _build_resources /opt/stack/nova/nova/compute/manager.py:2062
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CALL msg_id: f70037f919264d8db2021cef722e9f97 exchange 'nova' topic 'conductor' from (pid=14334) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:489
Mar 29 16:16:06 os4 nova-conductor[14327]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] sending reply msg_id: f70037f919264d8db2021cef722e9f97 reply queue: reply_2d509f4c3c904a8d83ad6a659f755bf2 time elapsed: 0.0664471710043s from (pid=14327) _send_reply /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:90
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG oslo_concurrency.lockutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Lock "compute_resources" acquired by "nova.compute.resource_tracker.update_usage" :: waited 0.000s from (pid=14334) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CALL msg_id: 76a1008be9ea4a0f882eaed972093de8 exchange 'nova' topic 'conductor' from (pid=14334) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:489
Mar 29 16:16:06 os4 nova-compute[14334]: DEBUG nova.scheduler.client.report [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Refreshing aggregate associations for resource provider aa91aff1-89f9-47f7-a66c-8a60d87aa76d from (pid=14334) _ensure_resource_provider /opt/stack/nova/nova/scheduler/client/report.py:437
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_concurrency.lockutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Lock "compute_resources" released by "nova.compute.resource_tracker.update_usage" :: held 0.096s from (pid=14334) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
Mar 29 16:16:07 os4 nova-compute[14334]: INFO nova.virt.osinfo [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Cannot load Libosinfo: (No module named gi.repository.Libosinfo)
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CALL msg_id: f545ef909ec64b169fa53a601952279d exchange 'nova' topic 'conductor' from (pid=14334) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:489
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG nova.compute.manager [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] Allocating IP information in the background. from (pid=14334) _allocate_network_async /opt/stack/nova/nova/compute/manager.py:1384
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG nova.network.neutronv2.api [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] allocate_for_instance() from (pid=14334) allocate_for_instance /opt/stack/nova/nova/network/neutronv2/api.py:829
Mar 29 16:16:07 os4 nova-conductor[14327]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] sending reply msg_id: f545ef909ec64b169fa53a601952279d reply queue: reply_2d509f4c3c904a8d83ad6a659f755bf2 time elapsed: 0.0140517560067s from (pid=14327) _send_reply /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:90
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG nova.block_device [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] block_device_list [] from (pid=14334) volume_in_mapping /opt/stack/nova/nova/block_device.py:585
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG nova.compute.manager [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] Start building block device mappings for instance. from (pid=14334) _build_resources /opt/stack/nova/nova/compute/manager.py:2088
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CALL msg_id: e28395f19cde4e4ca2698e93de02a63b exchange 'nova' topic 'conductor' from (pid=14334) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:489
Mar 29 16:16:07 os4 nova-conductor[14326]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] sending reply msg_id: e28395f19cde4e4ca2698e93de02a63b reply queue: reply_2d509f4c3c904a8d83ad6a659f755bf2 time elapsed: 0.0703596939857s from (pid=14326) _send_reply /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:90
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CALL msg_id: 013ddb3c758b4cbfaade984871fb2671 exchange 'nova' topic 'conductor' from (pid=14334) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:489
Mar 29 16:16:07 os4 nova-conductor[14327]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] sending reply msg_id: 013ddb3c758b4cbfaade984871fb2671 reply queue: reply_2d509f4c3c904a8d83ad6a659f755bf2 time elapsed: 0.0648256909917s from (pid=14327) _send_reply /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:90
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG nova.compute.manager [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] Start spawning the instance on the hypervisor. from (pid=14334) _build_and_run_instance /opt/stack/nova/nova/compute/manager.py:1921
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG nova.block_device [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] block_device_list [] from (pid=14334) volume_in_mapping /opt/stack/nova/nova/block_device.py:585
Mar 29 16:16:07 os4 nova-compute[14334]: INFO nova.virt.libvirt.driver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] Creating image
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_concurrency.lockutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Lock "/opt/stack/data/nova/instances/a70f2d77-f140-4edf-bf38-8b07076be37a/disk.info" acquired by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: waited 0.000s from (pid=14334) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_concurrency.lockutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Lock "/opt/stack/data/nova/instances/a70f2d77-f140-4edf-bf38-8b07076be37a/disk.info" released by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: held 0.001s from (pid=14334) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_concurrency.lockutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Lock "ff5dedb42be7cda8422f529dde9a3096688be2c5" acquired by "nova.virt.libvirt.imagebackend.fetch_func_sync" :: waited 0.000s from (pid=14334) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG neutronclient.v2_0.client [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] GET call to neutron for http://10.42.0.53:9696/v2.0/networks.json?tenant_id=70162ab521a5455faff0680e923dd091&shared=False used request id req-3e9bf7cf-1951-49b1-9754-69aba6b56634 from (pid=14334) _append_request_id /usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG neutronclient.v2_0.client [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] GET call to neutron for http://10.42.0.53:9696/v2.0/networks.json?shared=True used request id req-92909c76-6784-4de4-9522-2b12c2e55215 from (pid=14334) _append_request_id /usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG nova.policy [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Policy check for network:attach_external_network failed with credentials {'service_roles': [], 'user_id': u'444f517480154b5588b354e64c50c075', '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'70162ab521a5455faff0680e923dd091', 'project_domain_id': None} from (pid=14334) authorize /opt/stack/nova/nova/policy.py:168
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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/ff5dedb42be7cda8422f529dde9a3096688be2c5.part from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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/ff5dedb42be7cda8422f529dde9a3096688be2c5.part" returned: 0 in 0.055s from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG nova.virt.images [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] f69a1669-34b6-4a2a-9f98-6c4ae0a9d21a was qcow2, converting to raw from (pid=14334) fetch_to_raw /opt/stack/nova/nova/virt/images.py:146
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Running cmd (subprocess): qemu-img convert -O raw -f qcow2 /opt/stack/data/nova/instances/_base/ff5dedb42be7cda8422f529dde9a3096688be2c5.part /opt/stack/data/nova/instances/_base/ff5dedb42be7cda8422f529dde9a3096688be2c5.converted from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CMD "qemu-img convert -O raw -f qcow2 /opt/stack/data/nova/instances/_base/ff5dedb42be7cda8422f529dde9a3096688be2c5.part /opt/stack/data/nova/instances/_base/ff5dedb42be7cda8422f529dde9a3096688be2c5.converted" returned: 0 in 0.118s from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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/ff5dedb42be7cda8422f529dde9a3096688be2c5.converted from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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/ff5dedb42be7cda8422f529dde9a3096688be2c5.converted" returned: 0 in 0.067s from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_concurrency.lockutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Lock "ff5dedb42be7cda8422f529dde9a3096688be2c5" released by "nova.virt.libvirt.imagebackend.fetch_func_sync" :: held 0.573s from (pid=14334) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf touch -c /opt/stack/data/nova/instances/_base/ff5dedb42be7cda8422f529dde9a3096688be2c5 from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf touch -c /opt/stack/data/nova/instances/_base/ff5dedb42be7cda8422f529dde9a3096688be2c5" returned: 0 in 0.145s from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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/ff5dedb42be7cda8422f529dde9a3096688be2c5 from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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/ff5dedb42be7cda8422f529dde9a3096688be2c5" returned: 0 in 0.057s from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_concurrency.lockutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Lock "ff5dedb42be7cda8422f529dde9a3096688be2c5" acquired by "nova.virt.libvirt.imagebackend.copy_qcow2_image" :: waited 0.000s from (pid=14334) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
Mar 29 16:16:07 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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/ff5dedb42be7cda8422f529dde9a3096688be2c5 from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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/ff5dedb42be7cda8422f529dde9a3096688be2c5" returned: 0 in 0.050s from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Running cmd (subprocess): qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/ff5dedb42be7cda8422f529dde9a3096688be2c5 /opt/stack/data/nova/instances/a70f2d77-f140-4edf-bf38-8b07076be37a/disk from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CMD "qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/ff5dedb42be7cda8422f529dde9a3096688be2c5 /opt/stack/data/nova/instances/a70f2d77-f140-4edf-bf38-8b07076be37a/disk" returned: 0 in 0.031s from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG nova.virt.disk.api [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Checking if we can resize image /opt/stack/data/nova/instances/a70f2d77-f140-4edf-bf38-8b07076be37a/disk. size=10737418240 from (pid=14334) can_resize_image /opt/stack/nova/nova/virt/disk/api.py:214
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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/a70f2d77-f140-4edf-bf38-8b07076be37a/disk from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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/a70f2d77-f140-4edf-bf38-8b07076be37a/disk" returned: 0 in 0.049s from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Running cmd (subprocess): qemu-img resize /opt/stack/data/nova/instances/a70f2d77-f140-4edf-bf38-8b07076be37a/disk 10737418240 from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CMD "qemu-img resize /opt/stack/data/nova/instances/a70f2d77-f140-4edf-bf38-8b07076be37a/disk 10737418240" returned: 0 in 0.027s from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG oslo_concurrency.lockutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Lock "ff5dedb42be7cda8422f529dde9a3096688be2c5" released by "nova.virt.libvirt.imagebackend.copy_qcow2_image" :: held 0.164s from (pid=14334) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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/ff5dedb42be7cda8422f529dde9a3096688be2c5 from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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/ff5dedb42be7cda8422f529dde9a3096688be2c5" returned: 0 in 0.049s from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG nova.virt.disk.api [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Checking if we can resize image /opt/stack/data/nova/instances/a70f2d77-f140-4edf-bf38-8b07076be37a/disk. size=10737418240 from (pid=14334) can_resize_image /opt/stack/nova/nova/virt/disk/api.py:214
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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/a70f2d77-f140-4edf-bf38-8b07076be37a/disk from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG oslo_concurrency.processutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb 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/a70f2d77-f140-4edf-bf38-8b07076be37a/disk" returned: 0 in 0.052s from (pid=14334) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG nova.virt.disk.api [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Cannot resize image /opt/stack/data/nova/instances/a70f2d77-f140-4edf-bf38-8b07076be37a/disk to a smaller size. from (pid=14334) can_resize_image /opt/stack/nova/nova/virt/disk/api.py:220
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG nova.virt.libvirt.driver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] Ensure instance console log exists: /opt/stack/data/nova/instances/a70f2d77-f140-4edf-bf38-8b07076be37a/console.log from (pid=14334) _ensure_console_log_for_instance /opt/stack/nova/nova/virt/libvirt/driver.py:2936
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG neutronclient.v2_0.client [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] POST call to neutron for http://10.42.0.53:9696/v2.0/ports.json used request id req-3e2a6228-9e64-4a3b-b25c-e0f441738a4f from (pid=14334) _append_request_id /usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG nova.network.neutronv2.api [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] Successfully created port: 0c051449-cc3a-4745-b0c7-ff65c445b798 from (pid=14334) _create_port_minimal /opt/stack/nova/nova/network/neutronv2/api.py:396
Mar 29 16:16:08 os4 nova-compute[14334]: DEBUG neutronclient.v2_0.client [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] GET call to neutron for http://10.42.0.53:9696/v2.0/extensions.json used request id req-9bc517c3-5106-471e-a388-7379bf33a82a from (pid=14334) _append_request_id /usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128
Mar 29 16:16:09 os4 nova-compute[14334]: DEBUG neutronclient.v2_0.client [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] PUT call to neutron for http://10.42.0.53:9696/v2.0/ports/0c051449-cc3a-4745-b0c7-ff65c445b798.json used request id req-06dff966-90bd-45dd-83f4-42f63b4d370a from (pid=14334) _append_request_id /usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128
Mar 29 16:16:09 os4 nova-compute[14334]: DEBUG nova.network.neutronv2.api [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] Successfully updated port: 0c051449-cc3a-4745-b0c7-ff65c445b798 from (pid=14334) _update_port /opt/stack/nova/nova/network/neutronv2/api.py:433
Mar 29 16:16:09 os4 nova-compute[14334]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CALL msg_id: 2adf28dab4814f31826e2ecbd43cf462 exchange 'nova' topic 'conductor' from (pid=14334) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:489
Mar 29 16:16:09 os4 nova-conductor[14326]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] sending reply msg_id: 2adf28dab4814f31826e2ecbd43cf462 reply queue: reply_2d509f4c3c904a8d83ad6a659f755bf2 time elapsed: 0.00981185701676s from (pid=14326) _send_reply /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:90
Mar 29 16:16:09 os4 nova-compute[14334]: DEBUG oslo_concurrency.lockutils [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] Acquired semaphore "refresh_cache-a70f2d77-f140-4edf-bf38-8b07076be37a" from (pid=14334) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212
Mar 29 16:16:09 os4 nova-compute[14334]: DEBUG nova.network.neutronv2.api [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] [instance: a70f2d77-f140-4edf-bf38-8b07076be37a] _get_instance_nw_info() from (pid=14334) _get_instance_nw_info /opt/stack/nova/nova/network/neutronv2/api.py:1280
Mar 29 16:16:09 os4 nova-compute[14334]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] CALL msg_id: eea079f2759b4c7e8e37f5920b1be459 exchange 'nova' topic 'conductor' from (pid=14334) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:489
Mar 29 16:16:09 os4 nova-conductor[14327]: DEBUG oslo_messaging._drivers.amqpdriver [req-3e4fa169-80ec-4635-8a7e-b60c16eddbcb demo demo] sending reply msg_id: eea079f2759b4c7e8e37f5920b1be459 reply queue: reply_2d509f4c3c904a8d83ad6a659f755bf2

That, is the flow of creating a server in all the Nova processes.

That’s the kind of analysis that most people were added Elastic Search into their environments to get. And while this clearly doesn’t actually replicate all the very cool things you can do with Elastic Search, it does really give you a bunch of new tools as a developer.

Note: the enablement for everything above is still very much work in progress. The DevStack patches have landed, but are off by default. The oslo.log patch is in the proof of concept phase for review.

This idea of programs being able to send not just log messages, but other metadata around them, is really powerful. It means, for instance, you can always send the code function / line number where a message was emitted. It’s not clogging up the log message itself, but if you want it later you can go ask for it. Or even if it is in the log message, by extracting in advance what the critical metadata is, you can give your consumers structured fields instead of relying on things like grok to parse the logs. Which simplifies ingest by things like Elastic Search.

There is a lot to explore here to provide a better developer and operator experience, which is only possible because we have systemd. I for one look forward to exploring the space.