Connection to neutron from Nova fails: timeout

[Yuri Shovkoplias]

1. Make a request from nova-api to Neutron, Neutron does not respond and returns timeout.

nova-api.log
screen-n-api.log:2015-02-18 14:09:26.869 ERROR nova.api.openstack [req-a2f8ceed-127f-46eb-8c3b-36b773feeac1 admin admin] Caught error: Connection to neutron failed: HTTPC
onnectionPool(host='42.99.133.174', port=9696): Read timed out. (read timeout=30)
screen-n-api.log:2015-02-18 14:09:26.869 TRACE nova.api.openstack ConnectionFailed: Connection to neutron failed: HTTPConnectionPool(host='42.99.133.174', port=9696): Read timed out. (read timeo
ut=30)

2. Neutron service logs show, that the request above can not be found in the logs.
Original request was initiated on 14:09:26, Neutron was stuck from 14:08:56 and started to write to log again on 14:11:32.

This issue was repeating during the day (3/4 times).

3. Issue is also present in the older logs.

neutron service.log

2015-02-18 14:08:56.862 ESC[00;32mDEBUG keystoneclient.middleware.auth_token [ESC[00;36m-ESC[00;32m] ESC[01;35mESC[00;32mReturning cached tokenESC[00m ESC[00;33mfrom (pid=26620) _cache_get /opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py:1521ESC[00m
2015-02-18 14:08:56.863 ESC[00;32mDEBUG keystoneclient.middleware.auth_token [ESC[00;36m-ESC[00;32m] ESC[01;35mESC[00;32mStoring token in cacheESC[00m ESC[00;33mfrom (pid=26620) store /opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py:1436ESC[00m
2015-02-18 14:08:56.863 ESC[00;32mDEBUG keystoneclient.middleware.auth_token [ESC[00;36m-ESC[00;32m] ESC[01;35mESC[00;32mReceived request from user: 8c0059c52cf043c78c1195bc7e9f0e7d with project_id : 8d310bc75c2a48f78f543699cc79939d and roles: _member_,admin ESC[00m ESC[00;33mfrom (pid=26620) _build_user_headers /opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py:972ESC[00m
2015-02-18 14:08:56.865 ESC[00;32mDEBUG routes.middleware [ESC[00;36m-ESC[00;32m] ESC[01;35mESC[00;32mNo route matched for GET /ports.jsonESC[00m ESC[00;33mfrom (pid=26620) __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:97ESC[00m
2015-02-18 14:08:56.865 ESC[00;32mDEBUG routes.middleware [ESC[00;36m-ESC[00;32m] ESC[01;35mESC[00;32mMatched GET /ports.jsonESC[00m ESC[00;33mfrom (pid=26620) __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:100ESC[00m
2015-02-18 14:11:32.663 ESC[00;32mDEBUG routes.middleware [ESC[00;36m-ESC[00;32m] ESC[01;35mESC[00;32mRoute path: '/ports{.format}', defaults: {'action': u'index', 'controller': <wsgify at 129764304 wrapping <function resource at 0x75c30c8>>}ESC[00m ESC[00;33mfrom (pid=26620) __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:102ESC[00m
2015-02-18 14:11:32.663 ESC[00;32mDEBUG routes.middleware [ESC[00;36m-ESC[00;32m] ESC[01;35mESC[00;32mMatch dict: {'action': u'index', 'controller': <wsgify at 129764304 wrapping <function resource at 0x75c30c8>>, 'format': u'json'}ESC[00m ESC[00;33mfrom (pid=26620) __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:103ESC[00m
2015-02-18 14:11:32.683 ESC[00;36mINFO neutron.wsgi [ESC[01;36mreq-1962d88f-ef32-42e1-ae1f-6dae51b3fa27 ESC[00;36madmin 8d310bc75c2a48f78f543699cc79939dESC[00;36m] ESC[01;35mESC[00;36m(26620) accepted ('42.99.133.174', 34915)
ESC[00m
2015-02-18 14:11:32.683 ESC[00;36mINFO neutron.wsgi [ESC[01;36mreq-1962d88f-ef32-42e1-ae1f-6dae51b3fa27 ESC[00;36madmin 8d310bc75c2a48f78f543699cc79939dESC[00;36m] ESC[01;35mESC[00;36m(26620) accepted ('42.99.133.174', 34916)
ESC[00m
2015-02-18 14:11:32.684 ESC[00;36mINFO neutron.wsgi [ESC[01;36mreq-1962d88f-ef32-42e1-ae1f-6dae51b3fa27 ESC[00;36madmin 8d310bc75c2a48f78f543699cc79939dESC[00;36m] ESC[01;35mESC[00;36m(26620) accepted ('42.99.133.174', 34920)
ESC[00m
2015-02-18 14:11:32.684 ESC[00;36mINFO neutron.wsgi [ESC[01;36mreq-1962d88f-ef32-42e1-ae1f-6dae51b3fa27 ESC[00;36madmin 8d310bc75c2a48f78f543699cc79939dESC[00;36m] ESC[01;35mESC[00;36m(26620) accepted ('42.99.133.174', 34926)
ESC[00m
2015-02-18 14:11:32.684 ESC[00;36mINFO neutron.wsgi [ESC[01;36mreq-1962d88f-ef32-42e1-ae1f-6dae51b3fa27 ESC[00;36madmin 8d310bc75c2a48f78f543699cc79939dESC[00;36m] ESC[01;35mESC[00;36m(26620) accepted ('42.99.133.174', 34927)
ESC[00m2015-02-18 14:11:32.685 ESC[00;36mINFO neutron.wsgi [ESC[01;36mreq-1962d88f-ef32-42e1-ae1f-6dae51b3fa27 ESC[00;36madmin 8d310bc75c2a48f78f543699cc79939dESC[00;36m] ESC[01;35mESC[00;36m(26620) accepted ('42.99.133.174', 34930)

[Yuri Shovkoplias (yuri-shovkoplias)]

More information on the exact OS version and other config details to be available in several hours

[Alexander Ignatov (aignatov)]

Yuri, diagnostic snapshot would be helpful as well to get more from debug logs.

[Dmitry Mescheryakov (dmitrymex)]

Yuri, the bug clearly lacks at least fuel version used. Also, as Alexander pointed out, it would be nice to have a snapshot.

[Dmitry Mescheryakov (dmitrymex)]

The bug is hanging in incomplete state for more than a month, hence moving it to invalid state.