1858949 – Placement API only logging requestlog to /var/log/placement/placement.log when no allocation candidates are found

Bug 1858949 - Placement API only logging requestlog to /var/log/placement/placement.log when no allocation candidates are found

Summary: Placement API only logging requestlog to /var/log/placement/placement.log whe...

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat OpenStack
Classification:	Red Hat
Component:	openstack-placement
Sub Component:
Version:	16.0 (Train)
Hardware:	Unspecified
OS:	Unspecified
Priority:	medium
Severity:	medium
Target Milestone:	Upstream M3
Target Release:	17.0
Assignee:	melanie witt
QA Contact:	OSP DFG:Compute
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:	1872495
TreeView+	depends on / blocked

Reported:	2020-07-20 20:25 UTC by David Vallee Delisle
Modified:	2023-10-06 21:11 UTC (History)
CC List:	2 users (show)
Fixed In Version:	openstack-placement-3.1.0-0.20200819011901.f7a11d0.el8ost
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Clones:	1872495 (view as bug list)
Environment:
Last Closed:	2022-09-21 12:10:55 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Priority	Status	Summary	Last Updated
OpenStack gerrit	744569	None	MERGED	Add DEBUG logs to help troubleshoot no allocation candidates	2020-09-04 20:41:17 UTC
Red Hat Issue Tracker	OSP-14672	None	None	None	2022-04-13 19:55:23 UTC
Red Hat Product Errata	RHEA-2022:6543	None	None	None	2022-09-21 12:11:55 UTC

Description David Vallee Delisle 2020-07-20 20:25:41 UTC

Description of problem:
When trying to debug a failed allocation, we have nothing in the logs except for the requestlog [1], even with debug log level enabled.

Just grepping for LOG in the code yields a lot more than that [2]

Version-Release number of selected component (if applicable):
puppet-placement-2.4.1-0.20200310125657.afddd56.el8ost.noarch
python3-placement-2.0.0-0.20200225223305.36beddb.el8ost.noarch
openstack-placement-api-2.0.0-0.20200225223305.36beddb.el8ost.noarch
openstack-placement-common-2.0.0-0.20200225223305.36beddb.el8ost.noarch

How reproducible:
All the time

Steps to Reproduce:
1. Deploy standard configuration
2. Request a placement allocation like this:
~~~
DISK_GB=47; MEMORY_MB=6144; VCPU=3; curl  -H "accept: application/json" -H "User-Agent: nova-scheduler keystoneauth1/3.4.0 python-requests/2.14.2 CPython/2.7.5" -H "OpenStack-API-Version: placement 1.17" -H "X-Auth-Token: $OC_TOKEN" "$PLACEMENT_ENDPOINT/allocation_candidates?limit=1000&resources=DISK_GB%3A${DISK_GB}%2CMEMORY_MB%3A${MEMORY_MB}%2CVCPU%3A${VCPU}"
~~~

Actual results:
See [1]

Expected results:
See [2]

Additional info:
[1]
~~~
2020-07-20 16:19:19.912 23 DEBUG placement.wsgi [-] logging_debug_format_suffix    = %(funcName)s %(pathname)s:%(lineno)d log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.912 23 DEBUG placement.wsgi [-] logging_default_format_string  = %(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s [-] %(instance)s%(message)s log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.912 23 DEBUG placement.wsgi [-] logging_exception_prefix       = %(asctime)s.%(msecs)03d %(process)d ERROR %(name)s %(instance)s log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.912 23 DEBUG placement.wsgi [-] logging_user_identity_format   = %(user)s %(tenant)s %(domain)s %(user_domain)s %(project_domain)s log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.912 23 DEBUG placement.wsgi [-] max_logfile_count              = 30 log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.912 23 DEBUG placement.wsgi [-] max_logfile_size_mb            = 200 log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.913 23 DEBUG placement.wsgi [-] publish_errors                 = False log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.913 23 DEBUG placement.wsgi [-] pybasedir                      = /usr/lib/python3.6/site-packages log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.913 23 DEBUG placement.wsgi [-] rate_limit_burst               = 0 log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.913 23 DEBUG placement.wsgi [-] rate_limit_except_level        = CRITICAL log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.913 23 DEBUG placement.wsgi [-] rate_limit_interval            = 0 log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.913 23 DEBUG placement.wsgi [-] state_path                     = /usr/lib/python3.6/site-packages log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.914 23 DEBUG placement.wsgi [-] syslog_log_facility            = LOG_USER log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.914 23 DEBUG placement.wsgi [-] tempdir                        = None log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.914 23 DEBUG placement.wsgi [-] use_eventlog                   = False log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.914 23 DEBUG placement.wsgi [-] use_journal                    = False log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.914 23 DEBUG placement.wsgi [-] use_json                       = False log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.914 23 DEBUG placement.wsgi [-] use_stderr                     = False log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.914 23 DEBUG placement.wsgi [-] use_syslog                     = False log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.914 23 DEBUG placement.wsgi [-] watch_log_file                 = False log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2581
2020-07-20 16:19:19.914 23 DEBUG placement.wsgi [-] api.auth_strategy              = keystone log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.914 23 DEBUG placement.wsgi [-] placement_database.connection  = **** log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.915 23 DEBUG placement.wsgi [-] placement_database.connection_debug = 0 log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.915 23 DEBUG placement.wsgi [-] placement_database.connection_parameters =  log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.915 23 DEBUG placement.wsgi [-] placement_database.connection_recycle_time = 3600 log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.915 23 DEBUG placement.wsgi [-] placement_database.connection_trace = False log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.915 23 DEBUG placement.wsgi [-] placement_database.max_overflow = None log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.915 23 DEBUG placement.wsgi [-] placement_database.max_pool_size = None log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.915 23 DEBUG placement.wsgi [-] placement_database.max_retries = 10 log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.915 23 DEBUG placement.wsgi [-] placement_database.mysql_sql_mode = TRADITIONAL log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.915 23 DEBUG placement.wsgi [-] placement_database.pool_timeout = None log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.915 23 DEBUG placement.wsgi [-] placement_database.retry_interval = 10 log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.915 23 DEBUG placement.wsgi [-] placement_database.slave_connection = **** log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.916 23 DEBUG placement.wsgi [-] placement_database.sqlite_synchronous = True log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.916 23 DEBUG placement.wsgi [-] placement_database.sync_on_startup = False log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.916 23 DEBUG placement.wsgi [-] placement.incomplete_consumer_project_id = 00000000-0000-0000-0000-000000000000 log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.916 23 DEBUG placement.wsgi [-] placement.incomplete_consumer_user_id = 00000000-0000-0000-0000-000000000000 log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.916 23 DEBUG placement.wsgi [-] placement.policy_file          = policy.yaml log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.916 23 DEBUG placement.wsgi [-] placement.randomize_allocation_candidates = False log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.916 23 DEBUG placement.wsgi [-] oslo_policy.enforce_scope      = False log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.917 23 DEBUG placement.wsgi [-] oslo_policy.policy_default_rule = default log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.917 23 DEBUG placement.wsgi [-] oslo_policy.policy_dirs        = ['policy.d'] log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.917 23 DEBUG placement.wsgi [-] oslo_policy.policy_file        = policy.json log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.917 23 DEBUG placement.wsgi [-] oslo_policy.remote_content_type = application/x-www-form-urlencoded log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.917 23 DEBUG placement.wsgi [-] oslo_policy.remote_ssl_ca_crt_file = None log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.917 23 DEBUG placement.wsgi [-] oslo_policy.remote_ssl_client_crt_file = None log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.917 23 DEBUG placement.wsgi [-] oslo_policy.remote_ssl_client_key_file = None log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.918 23 DEBUG placement.wsgi [-] oslo_policy.remote_ssl_verify_server_crt = False log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.918 23 DEBUG placement.wsgi [-] cors.allow_credentials         = True log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.918 23 DEBUG placement.wsgi [-] cors.allow_headers             = ['X-Auth-Token', 'X-Openstack-Request-Id', 'X-Identity-Status', 'X-Roles', 'X-Service-Catalog', 'X-User-Id', 'X-Tenant-Id', 'OpenStack-API-Version'] log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.918 23 DEBUG placement.wsgi [-] cors.allow_methods             = ['GET', 'PUT', 'POST', 'DELETE', 'PATCH'] log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.918 23 DEBUG placement.wsgi [-] cors.allowed_origin            = None log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.918 23 DEBUG placement.wsgi [-] cors.expose_headers            = ['X-Auth-Token', 'X-Openstack-Request-Id', 'X-Subject-Token', 'X-Service-Token', 'OpenStack-API-Version'] log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.919 23 DEBUG placement.wsgi [-] cors.max_age                   = 3600 log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-20 16:19:19.919 23 DEBUG placement.wsgi [-] ******************************************************************************** log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2591
2020-07-20 16:19:19.926 23 WARNING keystonemiddleware.auth_token [-] AuthToken middleware is set with keystone_authtoken.service_token_roles_required set to False. This is backwards compatible but deprecated behaviour. Please set this to True.
2020-07-20 16:19:19.958 23 DEBUG oslo_concurrency.lockutils [-] Acquired lock "trait_sync" lock /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:265
2020-07-20 16:19:19.983 23 DEBUG oslo_db.sqlalchemy.engines [-] 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 _check_effective_sql_mode /usr/lib/python3.6/site-packages/oslo_db/sqlalchemy/engines.py:307
2020-07-20 16:19:19.992 23 DEBUG oslo_concurrency.lockutils [-] Releasing lock "trait_sync" lock /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:281
2020-07-20 16:19:19.992 23 DEBUG oslo_concurrency.lockutils [-] Acquired lock "resource_classes_sync" lock /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:265
2020-07-20 16:19:19.994 23 DEBUG placement.objects.resource_class [-] Found existing resource classes in db: ['DISK_GB', 'FPGA', 'IPV4_ADDRESS', 'MEMORY_MB', 'MEM_ENCRYPTION_CONTEXT', 'NET_BW_EGR_KILOBIT_PER_SEC', 'NET_BW_IGR_KILOBIT_PER_SEC', 'NUMA_CORE', 'NUMA_MEMORY_MB', 'NUMA_SOCKET', 'NUMA_THREAD', 'PCI_DEVICE', 'PCPU', 'PGPU', 'SRIOV_NET_VF', 'VCPU', 'VGPU', 'VGPU_DISPLAY_HEAD'] _resource_classes_sync /usr/lib/python3.6/site-packages/placement/objects/resource_class.py:229
2020-07-20 16:19:19.995 23 DEBUG oslo_concurrency.lockutils [-] Releasing lock "resource_classes_sync" lock /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:281
2020-07-20 16:19:19.996 23 DEBUG placement.requestlog [req-aeaa64d1-00a5-47f3-b1dd-a713ade0f754 - - - - -] Starting request: 192.168.24.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A47%2CMEMORY_MB%3A6144%2CVCPU%3A3" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:62
2020-07-20 16:19:20.494 23 INFO placement.requestlog [req-aeaa64d1-00a5-47f3-b1dd-a713ade0f754 249c2360880f41cdbf046b8e0b351c5b 8dc07cf3e7474cf498ac025e25007d93 - default default] 192.168.24.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A47%2CMEMORY_MB%3A6144%2CVCPU%3A3" status: 200 len: 53 microversion: 1.17
2020-07-20 16:19:37.266 23 DEBUG placement.requestlog [req-2ed7e0dd-552e-4a9f-81c0-3f948a0f42f8 - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/0dbfef6a-7b77-4615-8d6c-7071a4914c44/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:62
2020-07-20 16:19:37.279 23 INFO placement.requestlog [req-2ed7e0dd-552e-4a9f-81c0-3f948a0f42f8 7b43e5ae61334305860550608d9d8c0d 1bf06c0bfb504468927db53c7d5a392b - default default] 192.168.24.1 "GET /placement/resource_providers/0dbfef6a-7b77-4615-8d6c-7071a4914c44/allocations" status: 200 len: 54 microversion: 1.0
2020-07-20 16:19:37.333 23 DEBUG placement.requestlog [req-0170d01d-8c2e-440f-819b-0ba85dd4697d - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/666bad55-c12c-4a72-b0c8-5b118a5e47dc/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:62
2020-07-20 16:19:37.344 23 INFO placement.requestlog [req-0170d01d-8c2e-440f-819b-0ba85dd4697d 7b43e5ae61334305860550608d9d8c0d 1bf06c0bfb504468927db53c7d5a392b - default default] 192.168.24.1 "GET /placement/resource_providers/666bad55-c12c-4a72-b0c8-5b118a5e47dc/allocations" status: 200 len: 54 microversion: 1.0
2020-07-20 16:19:41.146 23 DEBUG placement.requestlog [req-6cb0017c-5557-4a6a-8ca9-2fb58c07b1d3 - - - - -] Starting request: 192.168.24.1 "GET /placement/" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:62
2020-07-20 16:19:41.147 23 INFO placement.requestlog [req-6cb0017c-5557-4a6a-8ca9-2fb58c07b1d3 - - - - -] 192.168.24.1 "GET /placement/" status: 200 len: 136 microversion: 1.0
2020-07-20 16:20:23.204 23 DEBUG placement.requestlog [req-d911d565-c288-4fdd-a11f-2791e04225e0 - - - - -] Starting request: 192.168.24.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A47%2CMEMORY_MB%3A6144%2CVCPU%3A3" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:62
2020-07-20 16:20:23.224 23 INFO placement.requestlog [req-d911d565-c288-4fdd-a11f-2791e04225e0 249c2360880f41cdbf046b8e0b351c5b 8dc07cf3e7474cf498ac025e25007d93 - default default] 192.168.24.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A47%2CMEMORY_MB%3A6144%2CVCPU%3A3" status: 200 len: 53 microversion: 1.17
~~~

[2]
~~~
handlers/allocation.py:            LOG.debug("Deleted auto-created consumer with consumer UUID "
handlers/allocation.py:            LOG.warning("Got an exception when deleting auto-created "
handlers/allocation.py:            LOG.debug("Successfully wrote allocations %s", alloc_list)
handlers/allocation.py:            LOG.debug("Successfully wrote allocations %s", alloc_list)
handlers/allocation.py:    LOG.debug("Successfully deleted allocations %s", allocations)
handlers/util.py:LOG = logging.getLogger(__name__)
handlers/util.py:            LOG.debug("Supplied project or user ID for consumer %s was "
objects/allocation.py:LOG = logging.getLogger(__name__)
objects/allocation.py:            LOG.warning(
objects/allocation.py:            LOG.warning(
objects/allocation.py:            LOG.debug('Retrying allocations write on resource provider '
objects/allocation.py:        LOG.warning('Exceeded retry limit of %d on allocations write',
objects/allocation_candidate.py:LOG = logging.getLogger(__name__)
objects/allocation_candidate.py:            LOG.debug("%s (suffix '%s') returned %d matches",
objects/allocation_candidate.py:            LOG.debug('Excluding resource provider %s, it has '
objects/allocation_candidate.py:        LOG.debug('Excluding a set of allocation candidate %s : '
objects/allocation_candidate.py:    LOG.debug('Merging candidates yields %d allocation requests and %d '
objects/allocation_candidate.py:    LOG.debug('Excluding the following set of AllocationRequest because '
objects/research_context.py:LOG = logging.getLogger(__name__)
objects/research_context.py:                LOG.debug("No provider found for in_tree%s=%s",
objects/research_context.py:            LOG.debug("Group %s getting allocation candidates in the same "
objects/research_context.py:        LOG.debug(
objects/research_context.py:            LOG.debug('Limiting results yields %d allocation requests and '
objects/research_context.py:                LOG.debug('Excluding the following AllocationRequest because '
objects/research_context.py:                LOG.debug('Excluding the following AllocationRequest because '
objects/research_context.py:        LOG.debug("found %d providers with available %d %s",
objects/research_context.py:                LOG.debug("found %d providers after applying initial "
objects/research_context.py:                    LOG.debug("found %d providers after applying forbidden "
objects/research_context.py:            LOG.debug("found %d providers after filtering by previous result",
objects/research_context.py:        LOG.debug("found %d providers under %d trees with available %d %s",
objects/research_context.py:            LOG.debug(
objects/research_context.py:            LOG.debug(
objects/research_context.py:            LOG.debug("found %d providers under %d trees after applying "
objects/research_context.py:            LOG.debug("found %d providers under %d trees after applying "
objects/research_context.py:        LOG.debug(
objects/research_context.py:    LOG.debug("found %d providers under %d trees after applying "
objects/research_context.py:        LOG.debug("found %d providers after applying required traits filter "
objects/research_context.py:        LOG.debug("found %d providers after applying required aggregates "
objects/research_context.py:            LOG.debug("found %d providers after applying forbidden aggregates "
objects/research_context.py:            LOG.debug("found %d providers after applying forbidden traits "
objects/reshaper.py:LOG = logging.getLogger(__name__)
objects/reshaper.py:        LOG.debug("reshaping: *interim* inventory replacement for provider %s",
objects/reshaper.py:    LOG.debug("reshaping: attempting allocation replacement")
objects/reshaper.py:        LOG.debug("reshaping: *final* inventory replacement for provider %s",
objects/resource_class.py:LOG = logging.getLogger(__name__)
objects/resource_class.py:            LOG.warning("Exceeded retry limit on ID generation while "
objects/resource_class.py:    LOG.debug("Found existing resource classes in db: %s", db_classes)
objects/resource_class.py:            LOG.debug("Synced resource_classes from os_resource_classes: %s",
objects/resource_provider.py:LOG = logging.getLogger(__name__)
objects/resource_provider.py:    LOG.debug("_ensure_aggregate() did not find aggregate %s. "
objects/resource_provider.py:        LOG.debug("_ensure_aggregate() created new aggregate %s (id=%d).",
objects/resource_provider.py:            LOG.debug("_ensure_provider() failed to create new aggregate %s. "
objects/resource_provider.py:            LOG.debug("Setting aggregates for provider %s. Successfully "
objects/resource_provider.py:            LOG.debug("Setting aggregates for provider %s. Another thread "
objects/resource_provider.py:        LOG.debug("Setting aggregates for provider %s. Successfully "
objects/resource_provider.py:            LOG.warning('Resource provider %(uuid)s is now over-'
objects/resource_provider.py:            LOG.warning('Resource provider %(uuid)s is now over-'
objects/trait.py:LOG = logging.getLogger(__name__)
objects/trait.py:            LOG.debug("Synced traits from os_traits into API DB: %s",
policy.py:LOG = logging.getLogger(__name__)
policy.py:                LOG.error('Found [oslo_policy]/policy_file and '
policy.py:                LOG.warning('[placement]/policy_file is deprecated. Use '
policy.py:            LOG.exception('Policy not registered')
policy.py:            LOG.debug('Policy check for %(action)s failed with credentials '
requestlog.py:LOG = logging.getLogger(__name__)
requestlog.py:        # We must instantiate a Request context, otherwise the LOG in the
requestlog.py:        LOG.debug('Starting request: %s "%s %s"',
requestlog.py:        if LOG.isEnabledFor(logging.INFO):
requestlog.py:        """Write the log info out in a formatted form to ``LOG.info``.
requestlog.py:        LOG.info(self.format, log_format)
util.py:LOG = logging.getLogger(__name__)
wsgi_wrapper.py:LOG = logging.getLogger(__name__)
wsgi_wrapper.py:            LOG.debug("Placement API returning an error response: %s", exc)
~~~

Comment 1 melanie witt 2020-07-23 23:12:36 UTC

Hi dvd, lyarwood and I looked through puppet/tripleo-heat-templates and didn't find any real differences between their logging configs.

Then, lyarwood logged into a OSP16.1 environment to look around and found that when he enabled DEBUG, he did pick up other messages in the logs after booting an instance:

[15:59:42]  <lyarwood>	just enabled DEBUG in the 16.1 env jparker gave me and I got this
[15:59:45]  <lyarwood>	# grep DEBUG /var/log/containers/placement/placement.log | awk '{ print $5 }' | sort | uniq
[15:59:48]  <lyarwood>	oslo_concurrency.lockutils
[15:59:49]  <lyarwood>	oslo_db.sqlalchemy.engines
[15:59:52]  <lyarwood>	placement.handlers.allocation
[15:59:53]  <lyarwood>	placement.objects.allocation_candidate
[15:59:55]  <lyarwood>	placement.objects.research_context
[15:59:57]  <lyarwood>	placement.objects.resource_class
[15:59:59]  <lyarwood>	placement.requestlog
[16:00:01]  <lyarwood>	placement.wsgi

Can you do a similar test to boot an instance and check what's being logged to confirm whether something is really missing? Because so far, we're unable to reproduce the problem.

Comment 3 David Vallee Delisle 2020-07-25 15:11:58 UTC

Hello,

So I'm following this article [a] and I want to simulate a a placement on the undercloud's placement API.

[1] Here's the steps I took
[2] And here's the logs generated. 

It appears like nothing was returned, but we don't have much logs unfortunately.

I faced the original issue when I was deploying with predictable IPs and nova-scheduler complained that the placement api returned nothing, and logged nothing. I just deployed without the predictable IPs templates and now it works. I'll try again with the predictable IPs soon.

Thanks,

DVD



[a] https://access.redhat.com/solutions/3537351

[1]
~~~
(undercloud) [root@undercloud-0 placement]# export OC_TOKEN=$(openstack token issue -c id -f value)
(undercloud) [root@undercloud-0 placement]# export PLACEMENT_ENDPOINT="https://$(grep placement /var/lib/config-data/puppet-generated/haproxy/etc/haproxy/haproxy.cfg  -A1 | tail -1| awk '{print $2}')/placement"
(undercloud) [root@undercloud-0 placement]# curl -s -H "accept: application/json" -H "User-Agent: nova-scheduler keystoneauth1/3.4.0 python-requests/2.14.2 CPython/2.7.5" -H "OpenStack-API-Version: placement 1.17" -H "X-Auth-Token: $OC_TOKEN" "$PLACEMENT_ENDPOINT/resource_providers" | jq -r '.resource_providers[] | [.name, .uuid] | @csv'
"d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e","d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e"
"9369d4cc-07f4-482e-a369-054d16d7f083","9369d4cc-07f4-482e-a369-054d16d7f083"
"Neutron segment id fa7cd35d-818f-42fe-a7af-f23524567356","fa7cd35d-818f-42fe-a7af-f23524567356"
"Neutron segment id 5e3a1c04-21f0-42b2-aa73-3a699ec3d777","5e3a1c04-21f0-42b2-aa73-3a699ec3d777"
"Neutron segment id 22e2bdb3-2e2d-478e-adb8-59b8c7d7d7d0","22e2bdb3-2e2d-478e-adb8-59b8c7d7d7d0"
"Neutron segment id 85e42887-071a-42f8-a087-b08742dd9a73","85e42887-071a-42f8-a087-b08742dd9a73"
"Neutron segment id 8a439443-c5ac-4be2-bbcf-aba711d85ed8","8a439443-c5ac-4be2-bbcf-aba711d85ed8"
"Neutron segment id 76ef4b8c-782d-448b-a695-0dd3896ba8c7","76ef4b8c-782d-448b-a695-0dd3896ba8c7"
(undercloud) [root@undercloud-0 placement]# DISK_GB=3000; MEMORY_MB=2048; VCPU=1; curl -s -H "accept: application/json" -H "User-Agent: nova-scheduler keystoneauth1/3.4.0 python-requests/2.14.2 CPython/2.7.5" -H "OpenStack-API-Version: placement 1.17" -H "X-Auth-Token: $OC_TOKEN" "$PLACEMENT_ENDPOINT/allocation_candidates?limit=1000&resources=DISK_GB%3A${DISK_GB}%2CMEMORY_MB%3A${MEMORY_MB}%2CVCPU%3A${VCPU}" | jq '.'
{
  "allocation_requests": [],
  "provider_summaries": {}
}
(undercloud) [root@undercloud-0 placement]# less /var/log/containers/placement/placement.log 
(undercloud) [root@undercloud-0 placement]# DISK_GB=30; MEMORY_MB=2048; VCPU=1; curl -s -H "accept: application/json" -H "User-Agent: nova-scheduler keystoneauth1/3.4.0 python-requests/2.14.2 CPython/2.7.5" -H "OpenStack-API-Version: placement 1.17" -H "X-Auth-Token: $OC_TOKEN" "$PLACEMENT_ENDPOINT/allocation_candidates?limit=1000&resources=DISK_GB%3A${DISK_GB}%2CMEMORY_MB%3A${MEMORY_MB}%2CVCPU%3A${VCPU}" | jq '.'
{
  "allocation_requests": [],
  "provider_summaries": {}
}
~~~

[2]
~~~
2020-07-25 11:01:49.829 23 DEBUG placement.wsgi [-] cors.allow_methods             = ['GET', 'PUT', 'POST', 'DELETE', 'PATCH'] log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-25 11:01:49.829 23 DEBUG placement.wsgi [-] cors.allowed_origin            = None log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-25 11:01:49.829 23 DEBUG placement.wsgi [-] cors.expose_headers            = ['X-Auth-Token', 'X-Openstack-Request-Id', 'X-Subject-Token', 'X-Service-Token', 'OpenStack-API-Version'] log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-25 11:01:49.829 23 DEBUG placement.wsgi [-] cors.max_age                   = 3600 log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2589
2020-07-25 11:01:49.829 23 DEBUG placement.wsgi [-] ******************************************************************************** log_opt_values /usr/lib/python3.6/site-packages/oslo_config/cfg.py:2591
2020-07-25 11:01:49.837 23 WARNING keystonemiddleware.auth_token [-] AuthToken middleware is set with keystone_authtoken.service_token_roles_required set to False. This is backwards compatible but deprecated behaviour. Please set this to True.
2020-07-25 11:01:49.865 23 DEBUG oslo_concurrency.lockutils [-] Acquired lock "trait_sync" lock /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:265
2020-07-25 11:01:49.888 23 DEBUG oslo_db.sqlalchemy.engines [-] 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 _check_effective_sql_mode /usr/lib/python3.6/site-packages/oslo_db/sqlalchemy/engines.py:307
2020-07-25 11:01:49.897 23 DEBUG oslo_concurrency.lockutils [-] Releasing lock "trait_sync" lock /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:281
2020-07-25 11:01:49.897 23 DEBUG oslo_concurrency.lockutils [-] Acquired lock "resource_classes_sync" lock /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:265
2020-07-25 11:01:49.900 23 DEBUG placement.objects.resource_class [-] Found existing resource classes in db: ['DISK_GB', 'FPGA', 'IPV4_ADDRESS', 'MEMORY_MB', 'MEM_ENCRYPTION_CONTEXT', 'NET_BW_EGR_KILOBIT_PER_SEC', 'NET_BW_IGR_KILOBIT_PER_SEC', 'NUMA_CORE', 'NUMA_MEMORY_MB', 'NUMA_SOCKET', 'NUMA_THREAD', 'PCI_DEVICE', 'PCPU', 'PGPU', 'SRIOV_NET_VF', 'VCPU', 'VGPU', 'VGPU_DISPLAY_HEAD'] _resource_classes_sync /usr/lib/python3.6/site-packages/placement/objects/resource_class.py:229
2020-07-25 11:01:49.901 23 DEBUG oslo_concurrency.lockutils [-] Releasing lock "resource_classes_sync" lock /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:281
2020-07-25 11:01:49.901 23 DEBUG placement.requestlog [req-9a18169b-4802-4655-b9e1-9ee247acd29f - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:01:49.928 23 INFO placement.requestlog [req-9a18169b-4802-4655-b9e1-9ee247acd29f 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/allocations" status: 200 len: 130 microversion: 1.0
2020-07-25 11:01:49.998 23 DEBUG placement.requestlog [req-526ea01d-6d85-4817-b741-74a75a89054f - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:01:50.014 23 INFO placement.requestlog [req-526ea01d-6d85-4817-b741-74a75a89054f 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/allocations" status: 200 len: 133 microversion: 1.0
2020-07-25 11:02:50.244 23 DEBUG placement.requestlog [req-ec71f824-c905-42be-843c-a03e80e0c845 - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:02:50.302 23 INFO placement.requestlog [req-ec71f824-c905-42be-843c-a03e80e0c845 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/allocations" status: 200 len: 130 microversion: 1.0
2020-07-25 11:02:50.377 23 DEBUG placement.requestlog [req-e3906da4-e81d-40b1-8b31-b19c076ba86a - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:02:50.392 23 INFO placement.requestlog [req-e3906da4-e81d-40b1-8b31-b19c076ba86a 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/allocations" status: 200 len: 133 microversion: 1.0
2020-07-25 11:02:54.169 23 DEBUG placement.requestlog [req-723c1a4a-3f84-426b-82dd-8371ad963775 - - - - -] Starting request: 192.168.24.1 "GET /placement/" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:02:54.170 23 INFO placement.requestlog [req-723c1a4a-3f84-426b-82dd-8371ad963775 - - - - -] 192.168.24.1 "GET /placement/" status: 200 len: 136 microversion: 1.0
2020-07-25 11:03:52.135 23 DEBUG placement.requestlog [req-c7f30427-f9e2-48d0-b7ed-d6159ac0511d - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:03:52.654 23 INFO placement.requestlog [req-c7f30427-f9e2-48d0-b7ed-d6159ac0511d 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/allocations" status: 200 len: 130 microversion: 1.0
2020-07-25 11:03:52.662 23 DEBUG placement.requestlog [req-09e12c0d-7a7c-4846-b3b4-a32a0cd4e50e - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers?in_tree=d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:03:52.674 23 INFO placement.requestlog [req-09e12c0d-7a7c-4846-b3b4-a32a0cd4e50e 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers?in_tree=d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e" status: 200 len: 885 microversion: 1.14
2020-07-25 11:03:52.680 23 DEBUG placement.requestlog [req-8a0de45f-5250-4588-867c-54613da3833a - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/inventories" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:03:52.694 23 INFO placement.requestlog [req-8a0de45f-5250-4588-867c-54613da3833a 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/inventories" status: 200 len: 170 microversion: 1.0
2020-07-25 11:03:52.699 23 DEBUG placement.requestlog [req-5969091a-37eb-4808-bdcf-f955ccf6bfc9 - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/aggregates" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:03:52.710 23 INFO placement.requestlog [req-5969091a-37eb-4808-bdcf-f955ccf6bfc9 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/aggregates" status: 200 len: 53 microversion: 1.19
2020-07-25 11:03:52.715 23 DEBUG placement.requestlog [req-ffee4ebd-86ce-40f0-8be0-ae9489d03405 - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/traits" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:03:52.733 23 INFO placement.requestlog [req-ffee4ebd-86ce-40f0-8be0-ae9489d03405 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/traits" status: 200 len: 133 microversion: 1.6
2020-07-25 11:03:52.802 23 DEBUG placement.requestlog [req-ea79d49c-1872-4701-bef6-da00f1638b2f - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:03:52.816 23 INFO placement.requestlog [req-ea79d49c-1872-4701-bef6-da00f1638b2f 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/allocations" status: 200 len: 133 microversion: 1.0
2020-07-25 11:03:52.824 23 DEBUG placement.requestlog [req-fc212798-a855-468d-b8ac-535574b5dcf1 - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers?in_tree=9369d4cc-07f4-482e-a369-054d16d7f083" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:03:52.834 23 INFO placement.requestlog [req-fc212798-a855-468d-b8ac-535574b5dcf1 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers?in_tree=9369d4cc-07f4-482e-a369-054d16d7f083" status: 200 len: 885 microversion: 1.14
2020-07-25 11:03:52.839 23 DEBUG placement.requestlog [req-4ca94399-1054-4236-9968-803693d14f69 - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/inventories" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:03:52.851 23 INFO placement.requestlog [req-4ca94399-1054-4236-9968-803693d14f69 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/inventories" status: 200 len: 173 microversion: 1.0
2020-07-25 11:03:52.856 23 DEBUG placement.requestlog [req-9981cff9-3c34-46c2-8bd0-30e473373748 - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/aggregates" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:03:52.865 23 INFO placement.requestlog [req-9981cff9-3c34-46c2-8bd0-30e473373748 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/aggregates" status: 200 len: 53 microversion: 1.19
2020-07-25 11:03:52.870 23 DEBUG placement.requestlog [req-b64aa346-304e-4cbe-8058-1338bd118d25 - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/traits" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:03:52.888 23 INFO placement.requestlog [req-b64aa346-304e-4cbe-8058-1338bd118d25 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/traits" status: 200 len: 133 microversion: 1.6
2020-07-25 11:03:54.566 23 DEBUG placement.requestlog [req-f50f977f-137b-4c9b-897d-00a519bbf6e8 - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:03:54.630 23 INFO placement.requestlog [req-f50f977f-137b-4c9b-897d-00a519bbf6e8 b6fa029392ba414387548b512ca091f4 539d39acc19445f4b6f30238a12f890a - default default] 192.168.24.1 "GET /placement/resource_providers" status: 200 len: 7026 microversion: 1.17
2020-07-25 11:03:56.931 23 DEBUG placement.requestlog [req-ac600e40-b1eb-49d3-ad89-dab8f635ed9a - - - - -] Starting request: 192.168.24.1 "GET /placement/" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:03:56.932 23 INFO placement.requestlog [req-ac600e40-b1eb-49d3-ad89-dab8f635ed9a - - - - -] 192.168.24.1 "GET /placement/" status: 200 len: 136 microversion: 1.0
2020-07-25 11:04:30.297 23 DEBUG placement.requestlog [req-809d4a76-5f6c-4fbb-9e53-3757a3ca2c92 - - - - -] Starting request: 192.168.24.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A3000%2CMEMORY_MB%3A2048%2CVCPU%3A1" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:04:30.322 23 INFO placement.requestlog [req-809d4a76-5f6c-4fbb-9e53-3757a3ca2c92 b6fa029392ba414387548b512ca091f4 539d39acc19445f4b6f30238a12f890a - default default] 192.168.24.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A3000%2CMEMORY_MB%3A2048%2CVCPU%3A1" status: 200 len: 53 microversion: 1.17
2020-07-25 11:04:54.135 23 DEBUG placement.requestlog [req-143c1f67-879b-4a38-9b3a-1e64d3549d31 - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:04:54.151 23 INFO placement.requestlog [req-143c1f67-879b-4a38-9b3a-1e64d3549d31 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/allocations" status: 200 len: 130 microversion: 1.0
2020-07-25 11:04:54.221 23 DEBUG placement.requestlog [req-f5878b3f-09a0-4470-adf1-61a96181408e - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:04:54.236 23 INFO placement.requestlog [req-f5878b3f-09a0-4470-adf1-61a96181408e 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/allocations" status: 200 len: 133 microversion: 1.0
2020-07-25 11:04:58.221 23 DEBUG placement.requestlog [req-f6d56bf5-8594-41ae-81c9-8f9b7f904b68 - - - - -] Starting request: 192.168.24.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A30%2CMEMORY_MB%3A2048%2CVCPU%3A1" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:04:58.241 23 INFO placement.requestlog [req-f6d56bf5-8594-41ae-81c9-8f9b7f904b68 b6fa029392ba414387548b512ca091f4 539d39acc19445f4b6f30238a12f890a - default default] 192.168.24.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A30%2CMEMORY_MB%3A2048%2CVCPU%3A1" status: 200 len: 53 microversion: 1.17
2020-07-25 11:04:58.834 23 DEBUG placement.requestlog [req-2d63bc30-2de2-4ff7-b7b1-0bff168a0fe1 - - - - -] Starting request: 192.168.24.1 "GET /placement/" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:04:58.835 23 INFO placement.requestlog [req-2d63bc30-2de2-4ff7-b7b1-0bff168a0fe1 - - - - -] 192.168.24.1 "GET /placement/" status: 200 len: 136 microversion: 1.0
2020-07-25 11:05:56.121 23 DEBUG placement.requestlog [req-150d9448-dfbf-4bb6-95e2-e5325df2d828 - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:05:56.136 23 INFO placement.requestlog [req-150d9448-dfbf-4bb6-95e2-e5325df2d828 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/allocations" status: 200 len: 130 microversion: 1.0
2020-07-25 11:05:56.204 23 DEBUG placement.requestlog [req-1c73246e-ba08-4438-b800-f241f470a4e1 - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:05:56.219 23 INFO placement.requestlog [req-1c73246e-ba08-4438-b800-f241f470a4e1 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/allocations" status: 200 len: 133 microversion: 1.0
2020-07-25 11:06:44.133 23 DEBUG placement.requestlog [req-f834bd9d-8177-4e41-b3fe-0e6200b395a6 - - - - -] Starting request: 192.168.24.1 "GET /placement/" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:06:44.134 23 INFO placement.requestlog [req-f834bd9d-8177-4e41-b3fe-0e6200b395a6 - - - - -] 192.168.24.1 "GET /placement/" status: 200 len: 136 microversion: 1.0
2020-07-25 11:06:57.144 23 DEBUG placement.requestlog [req-22cfdf3e-34fc-4721-845e-96dbf280a1b1 - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:06:57.159 23 INFO placement.requestlog [req-22cfdf3e-34fc-4721-845e-96dbf280a1b1 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/allocations" status: 200 len: 130 microversion: 1.0
2020-07-25 11:06:57.224 23 DEBUG placement.requestlog [req-8754dc0b-6a4b-44c9-8d47-c0ae338dd647 - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:06:57.239 23 INFO placement.requestlog [req-8754dc0b-6a4b-44c9-8d47-c0ae338dd647 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/allocations" status: 200 len: 133 microversion: 1.0
2020-07-25 11:07:57.196 23 DEBUG placement.requestlog [req-a9924ea6-a300-43d0-8f11-7790a70d6643 - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:07:57.212 23 INFO placement.requestlog [req-a9924ea6-a300-43d0-8f11-7790a70d6643 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/d5e5162d-ab5a-4252-b35a-7c8dcc1bf99e/allocations" status: 200 len: 130 microversion: 1.0
2020-07-25 11:07:57.276 23 DEBUG placement.requestlog [req-0c7506b6-b2c5-4e3b-ae68-d8ccadc5a79c - - - - -] Starting request: 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:07:57.290 23 INFO placement.requestlog [req-0c7506b6-b2c5-4e3b-ae68-d8ccadc5a79c 65dd0170b8c74fbbb4468ecf4270f795 1ab1d51fc6ad44f9aa7517c77860afe3 - default default] 192.168.24.1 "GET /placement/resource_providers/9369d4cc-07f4-482e-a369-054d16d7f083/allocations" status: 200 len: 133 microversion: 1.0
2020-07-25 11:08:04.084 23 DEBUG placement.requestlog [req-793e78d9-2a2c-4a20-a021-bfdce02972e8 - - - - -] Starting request: 192.168.24.1 "GET /placement/" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-25 11:08:04.085 23 INFO placement.requestlog [req-793e78d9-2a2c-4a20-a021-bfdce02972e8 - - - - -] 192.168.24.1 "GET /placement/" status: 200 len: 136 microversion: 1.0
~~~

Comment 4 David Vallee Delisle 2020-07-28 00:02:30 UTC

That previous comment was on the undercloud's placement. I did something similar on the overcloud's:

(overcloud) [stack@undercloud-0 ~]$ curl -s -H "accept: application/json" -H "User-Agent: nova-scheduler keystoneauth1/3.4.0 python-requests/2.14.2 CPython/2.7.5" -H "OpenStack-API-Version: placement 1.17" -H "X-Auth-Token: $OC_TOKEN" "$PLACEMENT_ENDPOINT/resource_providers" | jq -r '.resource_providers[] | [.name, .uuid] | @csv'
"compute-0.ess.int.redhat.com","699f3c5b-a523-4214-ad2e-5a26b7e07c86"
(overcloud) [stack@undercloud-0 ~]$ DISK_GB=3000; MEMORY_MB=2048; VCPU=1; curl -s -H "accept: application/json" -H "User-Agent: nova-scheduler keystoneauth1/3.4.0 python-requests/2.14.2 CPython/2.7.5" -H "OpenStack-API-Version: placement 1.17" -H "X-Auth-Token: $OC_TOKEN" "$PLACEMENT_ENDPOINT/allocation_candidates?limit=1000&resources=DISK_GB%3A${DISK_GB}%2CMEMORY_MB%3A${MEMORY_MB}%2CVCPU%3A${VCPU}" 
{"allocation_requests": [], "provider_summaries": {}}

(overcloud) [stack@undercloud-0 ~]$ DISK_GB=30; MEMORY_MB=2048; VCPU=1; curl -s -H "accept: application/json" -H "User-Agent: nova-scheduler keystoneauth1/3.4.0 python-requests/2.14.2 CPython/2.7.5" -H "OpenStack-API-Version: placement 1.17" -H "X-Auth-Token: $OC_TOKEN" "$PLACEMENT_ENDPOINT/allocation_candidates?limit=1000&resources=DISK_GB%3A${DISK_GB}%2CMEMORY_MB%3A${MEMORY_MB}%2CVCPU%3A${VCPU}" 
{"allocation_requests": [], "provider_summaries": {}}

(overcloud) [stack@undercloud-0 ~]$ DISK_GB=10; MEMORY_MB=2048; VCPU=1; curl -s -H "accept: application/json" -H "User-Agent: nova-scheduler keystoneauth1/3.4.0 python-requests/2.14.2 CPython/2.7.5" -H "OpenStack-API-Version: placement 1.17" -H "X-Auth-Token: $OC_TOKEN" "$PLACEMENT_ENDPOINT/allocation_candidates?limit=1000&resources=DISK_GB%3A${DISK_GB}%2CMEMORY_MB%3A${MEMORY_MB}%2CVCPU%3A${VCPU}"                          
{"allocation_requests": [], "provider_summaries": {}}

I can provide access to this lab if you want to poke at it, just send me your pubkey.

Thanks,

DVD

[1]
~~~
2020-07-27 23:39:00.910 24 DEBUG oslo_concurrency.lockutils [-] Acquired lock "trait_sync" lock /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:265
2020-07-27 23:39:00.932 24 DEBUG oslo_db.sqlalchemy.engines [-] 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 _check_effective_sql_mode /usr/lib/python3.6/site-packages/oslo_db/sqlalchemy/engines.py:307
2020-07-27 23:39:00.939 24 DEBUG oslo_concurrency.lockutils [-] Releasing lock "trait_sync" lock /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:281
2020-07-27 23:39:00.939 24 DEBUG oslo_concurrency.lockutils [-] Acquired lock "resource_classes_sync" lock /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:265
2020-07-27 23:39:00.941 24 DEBUG placement.objects.resource_class [-] Found existing resource classes in db: ['DISK_GB', 'FPGA', 'IPV4_ADDRESS', 'MEMORY_MB', 'MEM_ENCRYPTION_CONTEXT', 'NET_BW_EGR_KILOBIT_PER_SEC', 'NET_BW_IGR_KILOBIT_PER_SEC', 'NUMA_CORE', 'NUMA_MEMORY_MB', 'NUMA_SOCKET', 'NUMA_THREAD', 'PCI_DEVICE', 'PCPU', 'PGPU', 'SRIOV_NET_VF', 'VCPU', 'VGPU', 'VGPU_DISPLAY_HEAD'] _resource_classes_sync /usr/lib/python3.6/site-packages/placement/objects/resource_class.py:229
2020-07-27 23:39:00.942 24 DEBUG oslo_concurrency.lockutils [-] Releasing lock "resource_classes_sync" lock /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:281
2020-07-27 23:39:00.942 24 DEBUG placement.requestlog [req-632decfe-e7a8-423f-9321-8affc72223f0 - - - - -] Starting request: 172.17.1.87 "GET /placement/resource_providers/699f3c5b-a523-4214-ad2e-5a26b7e07c86/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-27 23:39:00.966 24 INFO placement.requestlog [req-632decfe-e7a8-423f-9321-8affc72223f0 ceb5e5b8377049a2af386f6750bc824c 50e4b9d858644fb2809bbd5629262abc - default default] 172.17.1.87 "GET /placement/resource_providers/699f3c5b-a523-4214-ad2e-5a26b7e07c86/allocations" status: 200 len: 54 microversion: 1.0
2020-07-27 23:39:40.294 24 DEBUG placement.requestlog [req-b64786e2-c76c-4c9c-9126-36292e7ceba8 - - - - -] Starting request: 172.17.1.87 "GET /placement/" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-27 23:39:40.295 24 INFO placement.requestlog [req-b64786e2-c76c-4c9c-9126-36292e7ceba8 - - - - -] 172.17.1.87 "GET /placement/" status: 200 len: 136 microversion: 1.0
2020-07-27 23:39:49.468 24 DEBUG placement.requestlog [req-08824d6d-8673-4270-86cf-7fc77f264dbc - - - - -] Starting request: 172.17.1.87 "GET /placement/resource_providers" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-27 23:39:50.202 24 INFO placement.requestlog [req-08824d6d-8673-4270-86cf-7fc77f264dbc aa00df9fa2764cd6a8f5eba0abab9409 cdcefa6faed14c56ac40efb7a928b775 - default default] 172.17.1.87 "GET /placement/resource_providers" status: 200 len: 877 microversion: 1.17
2020-07-27 23:40:00.847 24 DEBUG placement.requestlog [req-09580149-f245-451a-9165-e295c8ea93e9 - - - - -] Starting request: 172.17.1.87 "GET /placement/resource_providers/699f3c5b-a523-4214-ad2e-5a26b7e07c86/allocations" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-27 23:40:00.860 24 INFO placement.requestlog [req-09580149-f245-451a-9165-e295c8ea93e9 ceb5e5b8377049a2af386f6750bc824c 50e4b9d858644fb2809bbd5629262abc - default default] 172.17.1.87 "GET /placement/resource_providers/699f3c5b-a523-4214-ad2e-5a26b7e07c86/allocations" status: 200 len: 54 microversion: 1.0
2020-07-27 23:40:03.623 24 DEBUG placement.requestlog [req-cb13dca8-43e3-416b-b07b-7b11fcd6be14 - - - - -] Starting request: 172.17.1.87 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A3000%2CMEMORY_MB%3A2048%2CVCPU%3A1" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-27 23:40:03.646 24 INFO placement.requestlog [req-cb13dca8-43e3-416b-b07b-7b11fcd6be14 aa00df9fa2764cd6a8f5eba0abab9409 cdcefa6faed14c56ac40efb7a928b775 - default default] 172.17.1.87 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A3000%2CMEMORY_MB%3A2048%2CVCPU%3A1" status: 200 len: 53 microversion: 1.17
2020-07-27 23:40:14.065 24 DEBUG placement.requestlog [req-5f2afa19-971d-4b46-8fb9-4eb243a380fd - - - - -] Starting request: 172.17.1.87 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A30%2CMEMORY_MB%3A2048%2CVCPU%3A1" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-27 23:40:14.089 24 INFO placement.requestlog [req-5f2afa19-971d-4b46-8fb9-4eb243a380fd aa00df9fa2764cd6a8f5eba0abab9409 cdcefa6faed14c56ac40efb7a928b775 - default default] 172.17.1.87 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A30%2CMEMORY_MB%3A2048%2CVCPU%3A1" status: 200 len: 53 microversion: 1.17
2020-07-27 23:40:26.490 24 DEBUG placement.requestlog [req-c6fd38f7-c8a4-4bf4-8f6f-ec0ecc38399a - - - - -] Starting request: 172.17.1.87 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A10%2CMEMORY_MB%3A2048%2CVCPU%3A1" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-27 23:40:26.513 24 INFO placement.requestlog [req-c6fd38f7-c8a4-4bf4-8f6f-ec0ecc38399a aa00df9fa2764cd6a8f5eba0abab9409 cdcefa6faed14c56ac40efb7a928b775 - default default] 172.17.1.87 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A10%2CMEMORY_MB%3A2048%2CVCPU%3A1" status: 200 len: 53 microversion: 1.17
~~~

Comment 5 Lee Yarwood 2020-07-30 20:20:02 UTC

Can you try adding -i to curl to get the response headers and using the request-id to trace this more accurately?

For example against an upstream devstack env I can do the following:

$ export TOKEN=$(openstack token issue -c id -f value)
$ export ENDPOINT=$(openstack endpoint list -c URL -f value | grep placement)
$ DISK_GB=1; MEMORY_MB=64; VCPU=1;
$ curl -i -s -H "accept: application/json" \
  -H "User-Agent: nova-scheduler keystoneauth1/3.4.0 python-requests/2.14.2 CPython/2.7.5" 
  -H "OpenStack-API-Version: placement 1.17" \
  -H "X-Auth-Token: $TOKEN" \
  "$ENDPOINT/allocation_candidates?limit=1000&resources=DISK_GB%3A${DISK_GB}%2CMEMORY_MB%3A${MEMORY_MB}%2CVCPU%3A${VCPU}"
HTTP/1.1 200 OK
Date: Thu, 30 Jul 2020 03:56:28 GMT
Server: Apache/2.4.43 (Fedora) OpenSSL/1.1.1g mod_wsgi/4.6.6 Python/3.7
Content-Length: 1421
Content-Type: application/json
Cache-Control: no-cache
Last-Modified: Thu, 30 Jul 2020 03:56:28 GMT
openstack-api-version: placement 1.17
vary: openstack-api-version
x-openstack-request-id: req-60a3d040-01be-47f2-b7aa-99ea4c9ab817
Connection: close

{"allocation_requests": [{"allocations": {"7d3786ba-4a63-44ec-a40e-914f4c2554d8": {"resources": {"DISK_GB": 1, "MEMORY_MB": 64, "VCPU": 1}}}}], "provider_summaries": {"7d3786ba-4a63-44ec-a40e-914f4c2554d8": {"resources": {"VCPU": {"capacity": 64, "used": 1}, "MEMORY_MB": {"capacity": 23241, "used": 512}, "DISK_GB": {"capacity": 20, "used": 0}}, "traits": ["COMPUTE_VOLUME_EXTEND", "COMPUTE_RESCUE_BFV", "HW_CPU_X86_MMX", "COMPUTE_GRAPHICS_MODEL_VMVGA", "COMPUTE_IMAGE_TYPE_AMI", "COMPUTE_STORAGE_BUS_FDC", "HW_CPU_X86_SVM", "COMPUTE_GRAPHICS_MODEL_CIRRUS", "COMPUTE_NET_VIF_MODEL_E1000E", "COMPUTE_GRAPHICS_MODEL_QXL", "COMPUTE_ACCELERATORS", "COMPUTE_TRUSTED_CERTS", "COMPUTE_STORAGE_BUS_SCSI", "COMPUTE_NET_VIF_MODEL_PCNET", "COMPUTE_DEVICE_TAGGING", "COMPUTE_VOLUME_ATTACH_WITH_TAG", "COMPUTE_IMAGE_TYPE_AKI", "HW_CPU_X86_SSE", "COMPUTE_STORAGE_BUS_IDE", "COMPUTE_IMAGE_TYPE_ARI", "COMPUTE_STORAGE_BUS_USB", "COMPUTE_STORAGE_BUS_VIRTIO", "COMPUTE_NET_ATTACH_INTERFACE_WITH_TAG", "COMPUTE_NET_VIF_MODEL_SPAPR_VLAN", "COMPUTE_IMAGE_TYPE_QCOW2", "COMPUTE_NODE", "COMPUTE_NET_VIF_MODEL_E1000", "COMPUTE_IMAGE_TYPE_RAW", "COMPUTE_NET_VIF_MODEL_NE2K_PCI", "COMPUTE_NET_VIF_MODEL_RTL8139", "COMPUTE_STORAGE_BUS_SATA", "COMPUTE_IMAGE_TYPE_ISO", "COMPUTE_NET_VIF_MODEL_VIRTIO", "COMPUTE_VOLUME_MULTI_ATTACH", "COMPUTE_GRAPHICS_MODEL_VGA", "HW_CPU_X86_SSE2", "COMPUTE_NET_ATTACH_INTERFACE", "COMPUTE_GRAPHICS_MODEL_VIRTIO"]}}}

$ journalctl -q -u devstack@placement-api | grep req-60a3d040-01be-47f2-b7aa-99ea4c9ab817
Jul 29 23:56:28 localhost.localdomain devstack[918705]: DEBUG placement.requestlog [None req-60a3d040-01be-47f2-b7aa-99ea4c9ab817 None None] Starting request: 192.168.122.131 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A64%2CVCPU%3A1" {{(pid=918707) __call__ /opt/stack/placement/placement/requestlog.py:61}}
Jul 29 23:56:28 localhost.localdomain devstack[918705]: DEBUG placement.objects.research_context [None req-60a3d040-01be-47f2-b7aa-99ea4c9ab817 admin admin] found 1 providers with available 1 DISK_GB {{(pid=918707) get_provider_ids_matching /opt/stack/placement/placement/objects/research_context.py:543}}
Jul 29 23:56:28 localhost.localdomain devstack[918705]: DEBUG placement.objects.research_context [None req-60a3d040-01be-47f2-b7aa-99ea4c9ab817 admin admin] found 1 providers with available 64 MEMORY_MB {{(pid=918707) get_provider_ids_matching /opt/stack/placement/placement/objects/research_context.py:543}}
Jul 29 23:56:28 localhost.localdomain devstack[918705]: DEBUG placement.objects.research_context [None req-60a3d040-01be-47f2-b7aa-99ea4c9ab817 admin admin] found 1 providers after filtering by previous result {{(pid=918707) get_provider_ids_matching /opt/stack/placement/placement/objects/research_context.py:574}}
Jul 29 23:56:28 localhost.localdomain devstack[918705]: DEBUG placement.objects.research_context [None req-60a3d040-01be-47f2-b7aa-99ea4c9ab817 admin admin] found 1 providers with available 1 VCPU {{(pid=918707) get_provider_ids_matching /opt/stack/placement/placement/objects/research_context.py:543}}
Jul 29 23:56:28 localhost.localdomain devstack[918705]: DEBUG placement.objects.research_context [None req-60a3d040-01be-47f2-b7aa-99ea4c9ab817 admin admin] found 1 providers after filtering by previous result {{(pid=918707) get_provider_ids_matching /opt/stack/placement/placement/objects/research_context.py:574}}
Jul 29 23:56:28 localhost.localdomain devstack[918705]: DEBUG placement.objects.allocation_candidate [None req-60a3d040-01be-47f2-b7aa-99ea4c9ab817 admin admin] RequestGroup(use_same_provider=False, resources={DISK_GB:1, MEMORY_MB:64, VCPU:1}, traits=[], aggregates=[]) (suffix '') returned 1 matches {{(pid=918707) _get_by_requests /opt/stack/placement/placement/objects/allocation_candidate.py:148}}
Jul 29 23:56:28 localhost.localdomain devstack[918705]: DEBUG placement.objects.allocation_candidate [None req-60a3d040-01be-47f2-b7aa-99ea4c9ab817 admin admin] Merging candidates yields 1 allocation requests and 1 provider summaries {{(pid=918707) _merge_candidates /opt/stack/placement/placement/objects/allocation_candidate.py:788}}
Jul 29 23:56:28 localhost.localdomain devstack[918705]: INFO placement.requestlog [None req-60a3d040-01be-47f2-b7aa-99ea4c9ab817 admin admin] 192.168.122.131 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A64%2CVCPU%3A1" status: 200 len: 1421 microversion: 1.17

Comment 6 David Vallee Delisle 2020-07-31 17:28:37 UTC

Hello Lee,

Here's more information. It looks like we don't log anything on failed request

[1] overcloud successful request
[2] undercloud failed request

[3] overcloud successful logs
[4] undercloud failed logs

[5] overcloud failed request
[6] overcloud failed logs

Mel has access to the lab. Let me know if you need anything else.

Thank you very much,

DVD


[1]
~~~
(overcloud) [stack@undercloud-0 ~]$ curl -i -H "accept: application/json"   -H "User-Agent: nova-scheduler keystoneauth1/3.4.0 python-requests/2.14.2 CPython/2.7.5"   -H "OpenStack-API-Version: placement 1.17"   -H "X-Auth-Token: $TOKEN"   "$ENDPOINT/allocation_candidates?limit=1000&resources=DISK_GB%3A${DISK_GB}%2CMEMORY_MB%3A${MEMORY_MB}%2CVCPU%3A${VCPU}"
HTTP/1.1 200 OK
Date: Fri, 31 Jul 2020 16:25:41 GMT
Server: Apache
Content-Length: 1164
Last-Modified: Fri, 31 Jul 2020 16:25:41 GMT
Cache-Control: no-cache
openstack-api-version: placement 1.17
vary: openstack-api-version,Accept-Encoding
x-openstack-request-id: req-cb72d88d-deae-4fff-a701-09c9919ecda8
Content-Type: application/json

{"allocation_requests": [{"allocations": {"699f3c5b-a523-4214-ad2e-5a26b7e07c86": {"resources": {"DISK_GB": 1, "MEMORY_MB": 64, "VCPU": 1}}}}], "provider_summaries": {"699f3c5b-a523-4214-ad2e-5a26b7e07c86": {"resources": {"VCPU": {"capacity": 64, "used": 0}, "MEMORY_MB": {"capacity": 1700, "used": 0}, "DISK_GB": {"capacity": 49, "used": 0}}, "traits": ["COMPUTE_VOLUME_MULTI_ATTACH", "HW_CPU_X86_VMX", "HW_CPU_X86_AVX2", "HW_CPU_X86_SSE42", "COMPUTE_IMAGE_TYPE_AMI", "COMPUTE_IMAGE_TYPE_ARI", "COMPUTE_IMAGE_TYPE_AKI", "HW_CPU_X86_AVX512DQ", "COMPUTE_IMAGE_TYPE_QCOW2", "HW_CPU_X86_AVX512BW", "HW_CPU_X86_AESNI", "HW_CPU_X86_BMI", "HW_CPU_X86_BMI2", "COMPUTE_DEVICE_TAGGING", "HW_CPU_X86_MMX", "COMPUTE_IMAGE_TYPE_RAW", "HW_CPU_X86_SSE", "HW_CPU_X86_ABM", "HW_CPU_X86_AVX512CD", "HW_CPU_X86_F16C", "HW_CPU_X86_AVX512VL", "HW_CPU_X86_AVX", "HW_CPU_X86_SSE2", "HW_CPU_X86_SSSE3", "HW_CPU_X86_AVX512F", "COMPUTE_NET_ATTACH_INTERFACE_WITH_TAG", "COMPUTE_TRUSTED_CERTS", "COMPUTE_VOLUME_EXTEND", "HW_CPU_X86_MPX", "COMPUTE_NET_ATTACH_INTERFACE", "COMPUTE_IMAGE_TYPE_ISO", "HW_CPU_X86_SSE41", "COMPUTE_VOLUME_ATTACH_WITH_TAG", "HW_CPU_X86_CLMUL", "HW_CPU_X86_FMA3"]}}}

[2]
~~~
(overcloud) [stack@undercloud-0 ~]$ source stackrc
(undercloud) [stack@undercloud-0 ~]$ export TOKEN=$(openstack token issue -c id -f value)
(undercloud) [stack@undercloud-0 ~]$ export ENDPOINT=$(openstack endpoint list -c URL -f value | grep placement | tail -1)
(undercloud) [stack@undercloud-0 ~]$ curl -i -H "accept: application/json"   -H "User-Agent: nova-scheduler keystoneauth1/3.4.0 python-requests/2.14.2 CPython/2.7.5"   -H "OpenStack-API-Version: placement 1.17"   -H "X-Auth-Token: $TOKEN"   "$ENDPOINT/allocation_candidates?limit=1000&resources=DISK_GB%3A${DISK_GB}%2CMEMORY_MB%3A${MEMORY_MB}%2CVCPU%3A${VCPU}"
HTTP/1.1 200 OK
Date: Fri, 31 Jul 2020 16:26:22 GMT
Server: Apache
Content-Length: 53
Last-Modified: Fri, 31 Jul 2020 16:26:22 GMT
Cache-Control: no-cache
openstack-api-version: placement 1.17
vary: openstack-api-version,Accept-Encoding
x-openstack-request-id: req-6ca4a83c-a7a2-452d-bccb-5df70864420f
Content-Type: application/json

{"allocation_requests": [], "provider_summaries": {}}
~~~

[3]
~~~
2020-07-31 16:25:41.659 24 DEBUG placement.requestlog [req-cb72d88d-deae-4fff-a701-09c9919ecda8 - - - - -] Starting request: 172.17.1.87 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A64%2CVCPU%3A1" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-31 16:25:41.949 24 DEBUG placement.objects.research_context [req-cb72d88d-deae-4fff-a701-09c9919ecda8 aa00df9fa2764cd6a8f5eba0abab9409 cdcefa6faed14c56ac40efb7a928b775 - default default] found 1 providers with available 1 DISK_GB get_provider_ids_matching /usr/lib/python3.6/site-packages/placement/objects/research_context.py:543
2020-07-31 16:25:41.949 24 DEBUG placement.objects.research_context [req-cb72d88d-deae-4fff-a701-09c9919ecda8 aa00df9fa2764cd6a8f5eba0abab9409 cdcefa6faed14c56ac40efb7a928b775 - default default] found 1 providers with available 64 MEMORY_MB get_provider_ids_matching /usr/lib/python3.6/site-packages/placement/objects/research_context.py:543
2020-07-31 16:25:41.949 24 DEBUG placement.objects.research_context [req-cb72d88d-deae-4fff-a701-09c9919ecda8 aa00df9fa2764cd6a8f5eba0abab9409 cdcefa6faed14c56ac40efb7a928b775 - default default] found 1 providers after filtering by previous result get_provider_ids_matching /usr/lib/python3.6/site-packages/placement/objects/research_context.py:574
2020-07-31 16:25:41.950 24 DEBUG placement.objects.research_context [req-cb72d88d-deae-4fff-a701-09c9919ecda8 aa00df9fa2764cd6a8f5eba0abab9409 cdcefa6faed14c56ac40efb7a928b775 - default default] found 1 providers with available 1 VCPU get_provider_ids_matching /usr/lib/python3.6/site-packages/placement/objects/research_context.py:543
2020-07-31 16:25:41.950 24 DEBUG placement.objects.research_context [req-cb72d88d-deae-4fff-a701-09c9919ecda8 aa00df9fa2764cd6a8f5eba0abab9409 cdcefa6faed14c56ac40efb7a928b775 - default default] found 1 providers after filtering by previous result get_provider_ids_matching /usr/lib/python3.6/site-packages/placement/objects/research_context.py:574
2020-07-31 16:25:41.958 24 DEBUG placement.objects.allocation_candidate [req-cb72d88d-deae-4fff-a701-09c9919ecda8 aa00df9fa2764cd6a8f5eba0abab9409 cdcefa6faed14c56ac40efb7a928b775 - default default] RequestGroup(use_same_provider=False, resources={DISK_GB:1, MEMORY_MB:64, VCPU:1}, traits=[], aggregates=[]) (suffix '') returned 1 matches _get_by_requests /usr/lib/python3.6/site-packages/placement/objects/allocation_candidate.py:148
2020-07-31 16:25:41.958 24 DEBUG placement.objects.allocation_candidate [req-cb72d88d-deae-4fff-a701-09c9919ecda8 aa00df9fa2764cd6a8f5eba0abab9409 cdcefa6faed14c56ac40efb7a928b775 - default default] Merging candidates yields 1 allocation requests and 1 provider summaries _merge_candidates /usr/lib/python3.6/site-packages/placement/objects/allocation_candidate.py:788
2020-07-31 16:25:41.959 24 INFO placement.requestlog [req-cb72d88d-deae-4fff-a701-09c9919ecda8 aa00df9fa2764cd6a8f5eba0abab9409 cdcefa6faed14c56ac40efb7a928b775 - default default] 172.17.1.87 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A64%2CVCPU%3A1" status: 200 len: 1164 microversion: 1.17
~~~

[4]
~~~
2020-07-31 12:26:22.139 23 DEBUG placement.requestlog [req-6ca4a83c-a7a2-452d-bccb-5df70864420f - - - - -] Starting request: 192.168.24.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A64%2CVCPU%3A1" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-31 12:26:22.216 23 INFO placement.requestlog [req-6ca4a83c-a7a2-452d-bccb-5df70864420f b6fa029392ba414387548b512ca091f4 539d39acc19445f4b6f30238a12f890a - default default] 192.168.24.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A64%2CVCPU%3A1" status: 200 len: 53 microversion: 1.17
~~~

[5]
~~~
(overcloud) [stack@undercloud-0 ~]$ curl -i -H "accept: application/json"   -H "User-Agent: nova-scheduler keystoneauth1/3.4.0 python-requests/2.14.2 CPython/2.7.5"   -H "OpenStack-API-Version: placement 1.17"   -H "X-Auth-Token: $TOKEN"   "$ENDPOINT/allocation_candidates?limit=1000&resources=DISK_GB%3A${DISK_GB}%2CMEMORY_MB%3A${MEMORY_MB}%2CVCPU%3A${VCPU}"
HTTP/1.1 200 OK
Date: Fri, 31 Jul 2020 17:25:18 GMT
Server: Apache
Content-Length: 53
Last-Modified: Fri, 31 Jul 2020 17:25:18 GMT
Cache-Control: no-cache
openstack-api-version: placement 1.17
vary: openstack-api-version,Accept-Encoding
x-openstack-request-id: req-6dbb4e4c-30f9-4e77-b9ba-fd915711d6a3
Content-Type: application/json

{"allocation_requests": [], "provider_summaries": {}}
~~~

[6]
~~~
[root@controller-0 placement]# grep req-6dbb4e4c-30f9-4e77-b9ba-fd915711d6a3 placement.log
2020-07-31 17:25:18.121 24 DEBUG placement.requestlog [req-6dbb4e4c-30f9-4e77-b9ba-fd915711d6a3 - - - - -] Starting request: 172.17.1.87 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A64%2CVCPU%3A3000" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-07-31 17:25:18.409 24 INFO placement.requestlog [req-6dbb4e4c-30f9-4e77-b9ba-fd915711d6a3 aa00df9fa2764cd6a8f5eba0abab9409 cdcefa6faed14c56ac40efb7a928b775 - default default] 172.17.1.87 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A64%2CVCPU%3A3000" status: 200 len: 53 microversion: 1.17
~~~

Comment 7 melanie witt 2020-08-03 21:39:36 UTC

Currently, placement will not log anything other than a successful GET request in the event that it returned no allocation candidates.

Rather, you will see something like this in the nova-scheduler log "Got no allocation candidates from the Placement API":

Jul 24 01:21:38.661960 ubuntu-bionic-ovh-bhs1-0018744637 nova-scheduler[55436]: DEBUG nova.scheduler.manager [None req-820ed8aa-491f-4982-a5e9-eb102433b488 tempest-ServerStableDeviceRescueTest-1911086583 tempest-ServerStableDeviceRescueTest-1911086583] Starting to schedule for instances: ['2ab2b5f7-3e91-47d6-8fe9-41c1c439b6d2'] {{(pid=56617) select_destinations /opt/stack/nova/nova/scheduler/manager.py:134}}
Jul 24 01:21:38.662416 ubuntu-bionic-ovh-bhs1-0018744637 nova-scheduler[55436]: DEBUG nova.scheduler.request_filter [None req-820ed8aa-491f-4982-a5e9-eb102433b488 tempest-ServerStableDeviceRescueTest-1911086583 tempest-ServerStableDeviceRescueTest-1911086583] compute_status_filter request filter added forbidden trait COMPUTE_STATUS_DISABLED {{(pid=56617) compute_status_filter /opt/stack/nova/nova/scheduler/request_filter.py:250}}
Jul 24 01:21:38.662615 ubuntu-bionic-ovh-bhs1-0018744637 nova-scheduler[55436]: DEBUG nova.scheduler.request_filter [None req-820ed8aa-491f-4982-a5e9-eb102433b488 tempest-ServerStableDeviceRescueTest-1911086583 tempest-ServerStableDeviceRescueTest-1911086583] Request filter 'compute_status_filter' took 0.0 seconds {{(pid=56617) wrapper /opt/stack/nova/nova/scheduler/request_filter.py:44}}
Jul 24 01:21:38.662985 ubuntu-bionic-ovh-bhs1-0018744637 nova-scheduler[55436]: DEBUG nova.scheduler.request_filter [None req-820ed8aa-491f-4982-a5e9-eb102433b488 tempest-ServerStableDeviceRescueTest-1911086583 tempest-ServerStableDeviceRescueTest-1911086583] Request filter 'accelerators_filter' took 0.0 seconds {{(pid=56617) wrapper /opt/stack/nova/nova/scheduler/request_filter.py:44}}
Jul 24 01:21:38.755176 ubuntu-bionic-ovh-bhs1-0018744637 nova-scheduler[55436]: INFO nova.scheduler.manager [None req-820ed8aa-491f-4982-a5e9-eb102433b488 tempest-ServerStableDeviceRescueTest-1911086583 tempest-ServerStableDeviceRescueTest-1911086583] Got no allocation candidates from the Placement API. This could be due to insufficient resources or a temporary occurrence as compute nodes start up.

In the placement-api log it shows for the same request ID:

Jul 24 01:21:38.695339 ubuntu-bionic-ovh-bhs1-0018744637 devstack[50755]: DEBUG placement.requestlog [req-820ed8aa-491f-4982-a5e9-eb102433b488 req-4f65608e-e77d-4b05-84b5-5b7045b61c9d None None] Starting request: 158.69.73.228 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A128%2CVCPU%3A1&root_required=%21COMPUTE_STATUS_DISABLED" {{(pid=50756) __call__ /opt/stack/placement/placement/requestlog.py:61}}
Jul 24 01:21:38.741210 ubuntu-bionic-ovh-bhs1-0018744637 devstack[50755]: INFO placement.requestlog [req-820ed8aa-491f-4982-a5e9-eb102433b488 req-4f65608e-e77d-4b05-84b5-5b7045b61c9d service placement] 158.69.73.228 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A128%2CVCPU%3A1&root_required=%21COMPUTE_STATUS_DISABLED" status: 200 len: 53 microversion: 1.35

Historically, placement did not log much related to allocation candidates requests because the requests did single, large, mysql queries that could not emit which part of the WHERE clause failed to find records. However, changes were made in Stein (OSP15) [1][2] to add granular DEBUG logging.

As we have observed, the DEBUG logging is only done during successful requests where at least one allocation candidate is found.

This is where we get the "found 1 providers with available 1 DISK_GB" message during a request that finds a candidate:

https://github.com/openstack/placement/blob/df56e21c906ecc5b145df015f740dad885511538/placement/objects/research_context.py#L542

But during a request that does not find a candidate, we don't get that far and fail here:

https://github.com/openstack/placement/blob/df56e21c906ecc5b145df015f740dad885511538/placement/objects/allocation_candidate.py#L136

with ResourceProviderNotFound being raised here:

https://github.com/openstack/placement/blob/df56e21c906ecc5b145df015f740dad885511538/placement/objects/research_context.py#L117-L126

because placement has already determined it can't find any candidates and bails out early.

It looks like we could add some DEBUG log messages to this spot ^ to aid in debugging situations where placement is returning no allocation candidates.

[1] https://review.opendev.org/590041
[2] https://review.opendev.org/639889

Comment 9 David Vallee Delisle 2020-08-18 16:44:17 UTC

Thanks Mel, I had to test this patch today because I ran into an issue and it works pretty well in this scenario at least:

2020-08-18 16:25:42.662 23 DEBUG placement.requestlog [req-e480c443-0463-48ce-9335-aba5a94cd4d3 - - - - -] Starting request: 172.17.1.87 "GET /placement/allocation_candidates?limit=1000&required=COMPUTE_IMAGE_TYPE_QCOW2%2C%21COMPUTE_STATUS_DISABLED&resources=DISK_GB%3A10%2CMEMORY_MB%3A4096%2CVCPU%3A2" __call__ /usr/lib/python3.6/site-packages/placement/requestlog.py:61
2020-08-18 16:25:42.946 23 DEBUG placement.objects.research_context [req-e480c443-0463-48ce-9335-aba5a94cd4d3 ceb5e5b8377049a2af386f6750bc824c 50e4b9d858644fb2809bbd5629262abc - default default] getting providers with 10 DISK_GB __init__ /usr/lib/python3.6/site-packages/placement/objects/research_context.py:125
2020-08-18 16:25:42.951 23 DEBUG placement.objects.research_context [req-e480c443-0463-48ce-9335-aba5a94cd4d3 ceb5e5b8377049a2af386f6750bc824c 50e4b9d858644fb2809bbd5629262abc - default default] getting providers with 4096 MEMORY_MB __init__ /usr/lib/python3.6/site-packages/placement/objects/research_context.py:125
2020-08-18 16:25:42.955 23 DEBUG placement.objects.research_context [req-e480c443-0463-48ce-9335-aba5a94cd4d3 ceb5e5b8377049a2af386f6750bc824c 50e4b9d858644fb2809bbd5629262abc - default default] found no providers with 4096 MEMORY_MB __init__ /usr/lib/python3.6/site-packages/placement/objects/research_context.py:129

Comment 10 melanie witt 2020-08-25 21:53:20 UTC

https://review.opendev.org/744569 has merged upstream.

Comment 16 errata-xmlrpc 2022-09-21 12:10:55 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Release of components for Red Hat OpenStack Platform 17.0 (Wallaby)), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHEA-2022:6543

Note You need to log in before you can comment on or make changes to this bug.