1575817 – Instance failed to spawn due to "ConnectTimeout: Request to http://XXX/v2.0/ports timed out"

Bug 1575817 - Instance failed to spawn due to "ConnectTimeout: Request to http://XXX/v2.0/ports timed out"

Summary: Instance failed to spawn due to "ConnectTimeout: Request to http://XXX/v2.0/p...

Keywords:
Status:	CLOSED NOTABUG
Alias:	None
Product:	Red Hat OpenStack
Classification:	Red Hat
Component:	openstack-neutron
Sub Component:
Version:	12.0 (Pike)
Hardware:	Unspecified
OS:	Unspecified
Priority:	high
Severity:	high
Target Milestone:	---
Target Release:	---
Assignee:	Assaf Muller
QA Contact:	Roee Agiman
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2018-05-08 02:43 UTC by Chen
Modified:	2023-09-15 00:08 UTC (History)
CC List:	16 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2018-10-09 13:25:27 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Issue Tracker	OSP-11384	0	None	None	None	2021-12-10 16:09:57 UTC

Description Chen 2018-05-08 02:43:09 UTC

Description of problem:

Instance failed to spawn due to "ConnectTimeout: Request to http://XXX/v2.0/ports timed out"

2018-05-07 13:38:14.512 1 ERROR nova.compute.manager [req-b5bcb178-a400-4634-9c88-0238497c3bad f8adc12e823442a1ac290df984e25d33 b1ae66164d244ad394c304b64da24595 - default default] Instance failed network setup after 1 attempt(s): ConnectTimeout: Request to http://172.17.0.15:9696/v2.0/ports timed out
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager Traceback (most recent call last):
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1415, in _allocate_network_async
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     bind_host_id=bind_host_id)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 873, in allocate_for_instance
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     security_group_ids)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 810, in _create_ports_for_instance
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     neutron, instance, created_port_ids)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     self.force_reraise()
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     six.reraise(self.type_, self.value, self.tb)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 799, in _create_ports_for_instance
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     request.address, security_group_ids)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 399, in _create_port_minimal
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     port_response = port_client.create_port(port_req_body)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 112, in wrapper
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     ret = obj(*args, **kwargs)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 781, in create_port
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     return self.post(self.ports_path, body=body)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 112, in wrapper
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     ret = obj(*args, **kwargs)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 357, in post
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     headers=headers, params=params)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 112, in wrapper
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     ret = obj(*args, **kwargs)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 280, in do_request
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     resp, replybody = self.httpclient.do_request(action, method, body=body)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/neutronclient/client.py", line 342, in do_request
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     return self.request(url, method, **kwargs)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/neutronclient/client.py", line 330, in request
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     resp = super(SessionClient, self).request(*args, **kwargs)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/keystoneauth1/adapter.py", line 192, in request
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     return self.session.request(url, method, **kwargs)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/positional/__init__.py", line 101, in inner
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     return wrapped(*args, **kwargs)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/keystoneauth1/session.py", line 703, in request
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     resp = send(**kwargs)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/keystoneauth1/session.py", line 768, in _send_request
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager     raise exceptions.ConnectTimeout(msg)
2018-05-07 13:38:14.512 1 ERROR nova.compute.manager ConnectTimeout: Request to http://172.17.0.15:9696/v2.0/ports timed out


Version-Release number of selected component (if applicable):

OSP12
12.0-20180319.1 

How reproducible:

100% in customer's site

Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

Comment 3 Chen 2018-05-24 08:01:08 UTC

Hi,

In nova-compute.log we got timeout error

2018-05-17 10:00:05.953 1 ERROR nova.compute.manager [instance: 93941bb3-f6b4-46a6-8ad7-63e75378b37b] ConnectTimeout: Request to http://172.17.0.11:9696/v2.0/ports timed out

In neutron server.log, we have

2018-05-17 10:00:37.425 57220 INFO neutron.wsgi [req-d1e7309b-da4a-4cc9-9418-5c151dbc751b 577b8e030640426490c49dad0c03a238 9a6a7fdf37e5455b9c53a8d782d938a9 - default default] 172.17.0.21 "POST /v2.0/ports HTTP/1.1" status: 201  len: 1027 time: 61.4733062

which means, the POST took 61 seconds to finish. And here I pasted the log where it took long time to finish:

1. Quota related work seemed fine. But after that the next job waited 30 seconds: 09:59:36 -> 10:00:06

2018-05-17 09:59:36.011 57220 DEBUG neutron.pecan_wsgi.hooks.quota_enforcement [req-d1e7309b-da4a-4cc9-9418-5c151dbc751b 577b8e030640426490c49dad0c03a238 9a6a7fdf37e5455b9c53a8d782d938a9 - default default] Made reservation on behalf of 9a6a7fdf37e5455b9c53a8d782d938a9 for: {'port': 1} before /usr/lib/python2.7/site-packages/neutron/pecan_wsgi/hooks/quota_enforcement.py:55
2018-05-17 10:00:06.048 57220 DEBUG neutron_lib.callbacks.manager [req-d1e7309b-da4a-4cc9-9418-5c151dbc751b 577b8e030640426490c49dad0c03a238 9a6a7fdf37e5455b9c53a8d782d938a9 - default default] Notify callbacks ['neutron.plugins.ml2.plugin.Ml2Plugin._ensure_default_security_group_handler--9223372036853858547'] for port, before_create _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:167

2. event-dispatch wasn't released until 30 seconds:10:00:07 -> 10:00:37

2018-05-17 10:00:07.370 57220 DEBUG neutron.scheduler.dhcp_agent_scheduler [req-d1e7309b-da4a-4cc9-9418-5c151dbc751b 577b8e030640426490c49dad0c03a238 9a6a7fdf37e5455b9c53a8d782d938a9 - default default] Network f5c68d5c-e52d-4fda-b21d-0f0c7f38057d is already hosted by enough agents. _get_dhcp_agents_hosting_network /usr/lib/python2.7/site-packages/neutron/scheduler/dhcp_agent_scheduler.py:243
2018-05-17 10:00:37.347 57220 DEBUG oslo_concurrency.lockutils [req-d1e7309b-da4a-4cc9-9418-5c151dbc751b 577b8e030640426490c49dad0c03a238 9a6a7fdf37e5455b9c53a8d782d938a9 - - -] Lock "event-dispatch" released by "neutron.plugins.ml2.ovo_rpc.dispatch_events" :: held 30.196s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:282

I asked the customer to increase "timeout" option to 90 and the instance can be created successfully. But what was costing so much time ?

Best Regards,
Chen

Comment 4 Chen 2018-05-31 07:23:20 UTC

Hi,

The customer redeployed the environment with 3 controllers and the customer found it is necessary to enlarge the timeout in compute node or the instance creation would fail all the time.

Best Regards,
Chen

Comment 24 Red Hat Bugzilla 2023-09-15 00:08:00 UTC

The needinfo request[s] on this closed bug have been removed as they have been unresolved for 500 days

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