n-api and n-cpu receive timeouts from q-svc because of "Lock Wait timeout"

[Jeremy Stanley]

This request failed:

http://logs.openstack.org/12/123112/1/check/check-tempest-dsvm-neutron-full/cdb7110/logs/screen-n-api.txt.gz#_2014-09-22_14_16_01_028

2014-09-22 14:16:01.028 DEBUG nova.api.openstack.wsgi [req-bb64d882-d91e-4bff-9407-19277208e277 TestSecurityGroupsBasicOps-454747816 TestSecurityGroupsBasicOps-1777134551] Calling method '<bound method Controller.show of <nova.api.openstack.compute.servers.Controller object at 0x7f05ee9db610>>' _process_stack /opt/stack/new/nova/nova/api/openstack/wsgi.py:935
2014-09-22 14:16:01.063 DEBUG neutronclient.client [req-bb64d882-d91e-4bff-9407-19277208e277 TestSecurityGroupsBasicOps-454747816 TestSecurityGroupsBasicOps-1777134551]
REQ: curl -i http://127.0.0.1:9696/v2.0/ports.json?device_id=40737ad4-4513-4027-b031-cf7cf519d5b5 -X GET -H "X-Auth-Token: 916a5769e0ba42339f45c3f6bb00f147" -H "User-Agent: python-neutronclient"
 http_log_req /opt/stack/new/python-neutronclient/neutronclient/common/utils.py:140
2014-09-22 14:16:31.065 DEBUG neutronclient.client [req-bb64d882-d91e-4bff-9407-19277208e277 TestSecurityGroupsBasicOps-454747816 TestSecurityGroupsBasicOps-1777134551] throwing ConnectionFailed : HTTPConnectionPool(host='127.0.0.1', port=9696): Read timed out. (read timeout=30) _cs_request /opt/stack/new/python-neutronclient/neutronclient/client.py:132
2014-09-22 14:16:48.360 ERROR nova.api.openstack [req-bb64d882-d91e-4bff-9407-19277208e277 TestSecurityGroupsBasicOps-454747816 TestSecurityGroupsBasicOps-1777134551] Caught error: Connection to neutron failed: HTTPConnectionPool(host='127.0.0.1', port=9696): Read timed out. (read timeout=30)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack Traceback (most recent call last):
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/__init__.py", line 124, in __call__
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack return req.get_response(self.application)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1320, in send
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack application, catch_exc_info=False)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1284, in call_application
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack app_iter = application(self.environ, start_response)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack return resp(environ, start_response)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 646, in __call__
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack return self._call_app(env, start_response)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 624, in _call_app
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack return self._app(env, _fake_start_response)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack return resp(environ, start_response)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack return resp(environ, start_response)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/routes/middleware.py", line 131, in __call__
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack response = self.app(environ, start_response)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack return resp(environ, start_response)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack resp = self.call_func(req, *args, **self.kwargs)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack return self.func(req, *args, **kwargs)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 908, in __call__
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack content_type, body, accept)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 999, in _process_stack
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack request, action_args)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 878, in post_process_extensions
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack **action_args)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/compute/contrib/security_groups.py", line 597, in show
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack return self._show(req, resp_obj)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/compute/contrib/security_groups.py", line 593, in _show
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack self._extend_servers(req, [resp_obj.obj['server']])
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/compute/contrib/security_groups.py", line 557, in _extend_servers
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack servers))
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/network/security_group/neutron_driver.py", line 346, in get_instances_security_groups_bindings
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack ports = self._get_ports_from_server_list(servers, neutron)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/network/security_group/neutron_driver.py", line 305, in _get_ports_from_server_list
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack ports.extend(neutron.list_ports(**search_opts).get('ports'))
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/python-neutronclient/neutronclient/v2_0/client.py", line 98, in with_params
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack ret = self.function(instance, *args, **kwargs)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/python-neutronclient/neutronclient/v2_0/client.py", line 312, in list_ports
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack **_params)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/python-neutronclient/neutronclient/v2_0/client.py", line 1334, in list
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack for r in self._pagination(collection, path, **params):
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/python-neutronclient/neutronclient/v2_0/client.py", line 1347, in _pagination
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack res = self.get(path, params=params)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/python-neutronclient/neutronclient/v2_0/client.py", line 1320, in get
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack headers=headers, params=params)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/python-neutronclient/neutronclient/v2_0/client.py", line 1297, in retry_request
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack headers=headers, params=params)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/python-neutronclient/neutronclient/v2_0/client.py", line 1240, in do_request
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack content_type=self.content_type())
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/python-neutronclient/neutronclient/client.py", line 180, in do_request
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack **kwargs)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack File "/opt/stack/new/python-neutronclient/neutronclient/client.py", line 133, in _cs_request
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack raise exceptions.ConnectionFailed(reason=e)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack ConnectionFailed: Connection to neutron failed: HTTPConnectionPool(host='127.0.0.1', port=9696): Read timed out. (read timeout=30)
2014-09-22 14:16:48.360 30109 TRACE nova.api.openstack
2014-09-22 14:16:48.385 INFO nova.api.openstack [req-bb64d882-d91e-4bff-9407-19277208e277 TestSecurityGroupsBasicOps-454747816 TestSecurityGroupsBasicOps-1777134551] http://127.0.0.1:8774/v2/50c4cb69aa66452ea00f6823976bef6d/servers/40737ad4-4513-4027-b031-cf7cf519d5b5 returned with HTTP 500
2014-09-22 14:16:48.386 DEBUG nova.api.openstack.wsgi [req-bb64d882-d91e-4bff-9407-19277208e277 TestSecurityGroupsBasicOps-454747816 TestSecurityGroupsBasicOps-1777134551] Returning 500 to user: The server has either erred or is incapable of performing the requested operation. __call__ /opt/stack/new/nova/nova/api/openstack/wsgi.py:1199
2014-09-22 14:16:48.389 INFO nova.osapi_compute.wsgi.server [req-bb64d882-d91e-4bff-9407-19277208e277 TestSecurityGroupsBasicOps-454747816 TestSecurityGroupsBasicOps-1777134551] 127.0.0.1 "GET /v2/50c4cb69aa66452ea00f6823976bef6d/servers/40737ad4-4513-4027-b031-cf7cf519d5b5 HTTP/1.1" status: 500 len: 354 time: 47.3637452

Comparing to the q-svc debug log from the same time, bafflingly no requests were logged failed or otherwise between 14:16:00.341 and 14:16:48.397.

[Jeremy Stanley (fungi)]

Added Nova, Neutron and the Neutron Client (used by Nova's Neutron driver) as the interaction is subtle and more eyes might help point out what I'm missing.

[Jeremy Stanley (fungi)]

310 matches in the past week for message:"Connection to neutron failed: HTTPConnectionPool(host='127.0.0.1', port=9696): Read timed out" AND filename:"logs/screen-n-api.txt" (100% FAILURE build_status).

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiQ29ubmVjdGlvbiB0byBuZXV0cm9uIGZhaWxlZDogSFRUUENvbm5lY3Rpb25Qb29sKGhvc3Q9JzEyNy4wLjAuMScsIHBvcnQ9OTY5Nik6IFJlYWQgdGltZWQgb3V0XCIgQU5EIGZpbGVuYW1lOlwibG9ncy9zY3JlZW4tbi1hcGkudHh0XCIiLCJmaWVsZHMiOlsiYnVpbGRfc3RhdHVzIiwiZmlsZW5hbWUiXSwib2Zmc2V0IjowLCJ0aW1lZnJhbWUiOiI2MDQ4MDAiLCJncmFwaG1vZGUiOiJjb3VudCIsInRpbWUiOnsidXNlcl9pbnRlcnZhbCI6MH0sInN0YW1wIjoxNDExNDI1MjE4ODg2fQ==

[Sean Dague (sdague)]

Yeh, it looks like neutron is timing out the connection (possibly some other locking?), the request is eventually handled later, but it's too late.

http://logs.openstack.org/12/123112/1/check/check-tempest-dsvm-neutron-full/cdb7110/logs/screen-q-svc.txt.gz#_2014-09-22_14_16_48_510

[Eugene Nikanorov (enikanorov)]

Indeed there is a gap of 48 seconds after the last "Got semaphore "db-access" lock"

[Itsuro Oda (oda-g)]

> Indeed there is a gap of 48 seconds after the last "Got semaphore "db-access" lock"

It is sure that execution of update_device_down takes 48 sec by looking q-agt log in addition to q-svc log.
It seems there is no concurrent operation executed in neutron-server.
So I guess that there is an external factor to block neutron-server process.
And I found the following:
http://logs.openstack.org/12/123112/1/check/check-tempest-dsvm-neutron-full/cdb7110/logs/syslog.txt.gz#_Sep_22_14_16_00

Iscsi device was failed just same period (16:00-16:48).
I think this is cause of this problem.
(eg. writing to DB was blocked at that period)

[Sean Dague (sdague)]

@dql why did you change this to a New state? What makes you think the incomplete nature of the nova bug was resolved?

[Sean Dague (sdague)]

I believe this is a neutron timeout issue, marking as Invalid

[Kyle Mestery (mestery)]

Moving to Liberty-1 now in the hopes of raising the visibility of this.

[Salvatore Orlando (salvatore-orlando)]

Changed bug title to reflect what it is in reality.
Between n-api and n-cpu there are now only 32 hits in a week, 80% failure rate.

It is nowhere near the 310 hits per week noticed back in september so I'm decreasing the priority to medium

[Armando Migliaccio (armando-migliaccio)]

query ran today:

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiQ29ubmVjdGlvbiB0byBuZXV0cm9uIGZhaWxlZDogSFRUUENvbm5lY3Rpb25Qb29sKGhvc3Q9JzEyNy4wLjAuMScsIHBvcnQ9OTY5Nik6IFJlYWQgdGltZWQgb3V0XCIgQU5EIGZpbGVuYW1lOlwibG9ncy9zY3JlZW4tbi1hcGkudHh0XCIiLCJmaWVsZHMiOlsiYnVpbGRfc3RhdHVzIiwiZmlsZW5hbWUiXSwib2Zmc2V0IjowLCJ0aW1lZnJhbWUiOiI2MDQ4MDAiLCJncmFwaG1vZGUiOiJjb3VudCIsInRpbWUiOnsidXNlcl9pbnRlcnZhbCI6MH0sInN0YW1wIjoxNDExNDI1MjE4ODg2fQ==

Yielded no results.

This one:

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiSFRUUENvbm5lY3Rpb25Qb29sKGhvc3Q9JzEyNy4wLjAuMScsIHBvcnQ9OTY5Nik6IFJlYWQgdGltZWQgb3V0LiAocmVhZCB0aW1lb3V0PTMwKVwiIiwiZmllbGRzIjpbImJ1aWxkX3N0YXR1cyIsImZpbGVuYW1lIl0sIm9mZnNldCI6MCwidGltZWZyYW1lIjoiNjA0ODAwIiwiZ3JhcGhtb2RlIjoiY291bnQiLCJ0aW1lIjp7InVzZXJfaW50ZXJ2YWwiOjB9LCJzdGFtcCI6MTQ0MTA0NDgwODY0OH0=

(message:"HTTPConnectionPool(host='127.0.0.1', port=9696): Read timed out. (read timeout=30)")

Yields a handful of errors but they are because of Juno builds, and we ain't gonna fix that.

[Armando Migliaccio (armando-migliaccio)]

No longer valid, Juno is about to go EOL and this doesn't show up in master.

[David Comay (comay)]

Although Juno is going to EOL, are there plans for addressing this within Kilo? Or are plugins expected to work-around it?