Details
-
Type:
extRequest
-
Status: Closed
-
Priority:
Major
-
Resolution: Done
-
Fix Version/s: 2021
-
Component/s: FIWARE-LAB-HELP
-
Sender Email:
-
HD-Node:Spain
Description
Hi,
here to ask help about issues regarding FIWARE-Lab Genoa node sanity check fails, MAYBE related to an authorization with Keystone (please see here attached trace/logs already sent to Fernando Lopez)
btw, see also:
https://jira.fiware.org/browse/LAB-860
https://jira.fiware.org/browse/LAB-860
Thanks for your help
regards
giorgio
------------------------------------------------------
After fiware-lab SSL reworks (maybe),
genoa node sanity check fails:
-------------------------------------------
test_allocate_ip: unittest.case.SkipTest
Details
Errors: 2016-10-21 02:37:52,147 UTC - TestCase - ERROR - init_world(),
failure in Nova: failed to get security group list: The server has
either erred or is incapable of performing the requested operation.
(HTTP 500) (Request-ID: req-4e17b43c-8d71-4320-a430-fe203124f3f0)
2016-10-21 02:37:52,147 UTC - TestCase - ERROR - Fail with:
cls.reset_world_sec_groups(world, suite)
2016-10-21 02:38:52,632 UTC - TestCase - ERROR - init_world(), failure
in Neutron: failed to get router list: <html><body><h1>504 Gateway
Time-out</h1>
The server didn't respond in time.
</body></html>
2016-10-21 02:38:52,633 UTC - TestCase - ERROR - Fail with:
cls.reset_world_routers(world, suite)
2016-10-21 02:39:22,754 UTC - TestCase - ERROR - init_world(), failure
in Nova: failed to get allocated IP list: The server has either erred
or is incapable of performing the requested operation. (HTTP 500)
(Request-ID: req-17c7ed71-fd7c-4555-b828-7ce278798f20)
2016-10-21 02:39:22,754 UTC - TestCase - ERROR - Fail with:
cls.reset_world_allocated_ips(world, suite)
2016-10-21 02:39:22,755 UTC - TestCase - ERROR - Fail in some reset_world
Error in initialization phase: Error in initialization phase:
resources from previous executions not released
Traceback
-------------------------------------------
Now,
If I run any openstack command,
first time all run correctly (command completes immediately),
afterward, if I run the command few second after, command hang going
in timeout.
As specified in previous mail
(PLEASE READ log traces in previous mail, here below forwarded),
I suspect authorization issue with internal Keystone APIs dialog (but
maybe I'm wrong!).
Any idea/suggestions about how to troubleshoouting ?
btw, see also:
https://jira.fiware.org/browse/LAB-860
https://jira.fiware.org/browse/LAB-860
btw, I know to be annoying asking you, but I do not know how to
proceed elsewere.
Please forward me if you can't help on this.
Thanks for your patience!
respect
giorgio
-------------------------------------------------------
Giorgio Robino <giorgio.robino@cnit.it> ha scritto:
[Nascondi Testo quotato]
Hi Fernando!
Central Keystone side, there is any known issue ?
It seems to me that something wrong in keystone API calls (maybe after
SSL certificate config?)
e.g. if i run a "nova list" command, hi have keystone authorization issues,
see log extracts here below.
BTW, we didn't change outr configuration since two weeks ago.
Any idea?
thanks
giorgio
----------------------------
root@controller01:~# nova --debug list
DEBUG (session:196) REQ: curl -g -i -X GET
http://130.206.84.8:4730/v2.0/ -H "Accept: application/json" -H
"User-Agent:
python-keystoneclient"
INFO (connectionpool:187) Starting new HTTP connection (1): 130.206.84.8
DEBUG (connectionpool:353) "GET /v2.0/ HTTP/1.1" 200 422
DEBUG (session:226) RESP: [200] date: Wed, 19 Oct 2016 08:01:49 GMT
vary: X-Auth-Token content-length: 422 content-type
: application/json
RESP BODY: {"version": {"status": "stable", "updated":
"2014-04-17T00:00:00Z", "media-types": [
,
{"base": "application/xml", "type": "application/vnd.open stack.identity-v2.0+xml"}], "id": "v2.0", "links": [
{"href": "http://130.206.84.8:4730/v2.0/", "rel": "self"},
{"href": "http://docs.openstack.org/", "type": "text/html", "rel": "describedby"}]}}
DEBUG (v2:76) Making authentication request to
http://130.206.84.8:4730/v2.0/tokens
DEBUG (connectionpool:353) "POST /v2.0/tokens HTTP/1.1" 200 58933
DEBUG (iso8601:184) Parsed 2016-10-20T08:01:50Z into
with default timezone
<iso8601.iso8601.Utc object at 0x7
f5fc3b5e590>
DEBUG (iso8601:140) Got u'2016' for 'year' with default None
DEBUG (iso8601:140) Got u'10' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 10 for 'month' with default 10
DEBUG (iso8601:140) Got u'20' for 'daydash' with default 1
DEBUG (iso8601:140) Got 20 for 'day' with default 20
DEBUG (iso8601:140) Got u'08' for 'hour' with default None
DEBUG (iso8601:140) Got u'01' for 'minute' with default None
DEBUG (iso8601:140) Got u'50' for 'second' with default None
DEBUG (session:196) REQ: curl -g -i -X GET
http://130.251.135.65:8774/v2/00000000000003228460960090160000/servers/detai
l -H "User-Agent: python-novaclient" -H "Accept: application/json" -H
"X-Auth-Token:
1cc4514a1689"
INFO (connectionpool:187) Starting new HTTP connection (1): 130.251.135.65
DEBUG (connectionpool:353) "GET
/v2/00000000000003228460960090160000/servers/detail HTTP/1.1" 401 23
DEBUG (session:226) RESP:
DEBUG (v2:76) Making authentication request to
http://130.206.84.8:4730/v2.0/tokens
INFO (connectionpool:222) Resetting dropped connection: 130.206.84.8
DEBUG (connectionpool:353) "POST /v2.0/tokens HTTP/1.1" 200 58933
INFO (connectionpool:222) Resetting dropped connection: 130.251.135.65
DEBUG (connectionpool:353) "GET
/v2/00000000000003228460960090160000/servers/detail HTTP/1.1" 500 128
DEBUG (session:226) RESP:
DEBUG (shell:911) The server has either erred or is incapable of
performing the requested operation. (HTTP 500) (Request-ID:
req-90791e10-7506-424b-821e
-364ab557e8b5)
Traceback (most recent call last):
File "/usr/lib/python2.7/dist-packages/novaclient/shell.py", line
908, in main
OpenStackComputeShell().main(argv)
File "/usr/lib/python2.7/dist-packages/novaclient/shell.py", line
835, in main
args.func(self.cs, args)
File "/usr/lib/python2.7/dist-packages/novaclient/v2/shell.py",
line 1377, in do_list
sort_dirs=sort_dirs)
File "/usr/lib/python2.7/dist-packages/novaclient/v2/servers.py",
line 594, in list
return self._list("/servers%s%s" % (detail, query_string), "servers")
File "/usr/lib/python2.7/dist-packages/novaclient/base.py", line
64, in _list
_resp, body = self.api.client.get(url)
File "/usr/lib/python2.7/dist-packages/keystoneclient/adapter.py",
line 170, in get
return self.request(url, 'GET', **kwargs)
File "/usr/lib/python2.7/dist-packages/novaclient/client.py", line
92, in request
raise exceptions.from_response(resp, body, url, method)
ClientException: The server has either erred or is incapable of
performing the requested operation. (HTTP 500) (Request-ID:
req-90791e10-7506-424b-821e-
364ab557e8b5)
ERROR (ClientException): The server has either erred or is incapable
of performing the requested operation. (HTTP 500) (Request-ID:
req-90791e10-7506-42
4b-821e-364ab557e8b5)
----------------------------
/var/log/nova/nova-api.log
2016-10-19 08:04:29.100 8439 DEBUG keystoneclient.session [-] REQ:
curl -g -i -X GET http://130.206.84.8:4731/v3/auth/tokens -H
"X-Subject-Token: {SHA1}
da1cb5c57ad020ce3c457707e22b963b1cd872e0" -H
"User-Agent: python-keystoneclient" -H "Accept: application/json" -H
"X-Auth-Token:
c26ecbdfc94d27f7be18c363453490bb9fb2f240"
_http_log_request
/usr/lib/python2.7/dist-packages/keystoneclient/session.py:196
2016-10-19 08:04:29.141 8433 ERROR nova.api.openstack
[req-90791e10-7506-424b-821e-364ab557e8b5 admin-genoa
00000000000003228460960090160000 - - -] Caught error: Request to
http://172.18.0.2:9696/v2.0/ports.json?device_id=ba151850-22c8-4689-911b-d7c4aa82b4dc&device_id=ca9689da-37d2-4e65-b782-d7a899318a1a timed out
(HTTP
408)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack Traceback (most
recent call last):
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/nova/api/openstack/_init_.py",
line 125, in _call_
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack return
req.get_response(self.application)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/webob/request.py", line 1320, in send
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack application,
catch_exc_info=False)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/webob/request.py", line 1284, in
call_application
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack app_iter =
application(self.environ, start_response)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in _call_
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack return
resp(environ, start_response)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token/_init_.py",
line 634, in _call_
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack return
self._call_app(env, start_response)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token/_init_.py",
line 554, in _call_app
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack return
self._app(env, _fake_start_response)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in _call_
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack return
resp(environ, start_response)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in _call_
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack return
resp(environ, start_response)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/local/lib/python2.7/dist-packages/routes/middleware.py", line
141, in _call_
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack response =
self.app(environ, start_response)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in _call_
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack return
resp(environ, start_response)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in _call_
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack resp =
self.call_func(req, *args, **self.kwargs)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack return
self.func(req, *args, **kwargs)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py", line
756, in _call_
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack
content_type, body, accept)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py", line
847, in _process_stack
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack request,
action_args)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py", line
710, in post_process_extensions
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack **action_args)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/nova/api/openstack/compute/contrib/security_groups.py", line 471,
in
detail
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack
self._extend_servers(req, list(resp_obj.obj['servers']))
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/nova/api/openstack/compute/contrib/security_groups.py", line 422,
in
_extend_servers
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack servers))
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/nova/network/security_group/neutron_driver.py", line 366,
in
get_instances_security_groups_bindings
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack ports =
self._get_ports_from_server_list(servers, neutron)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/nova/network/security_group/neutron_driver.py", line 325,
in
_get_ports_from_server_list
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack
ports.extend(neutron.list_ports(**search_opts).get('ports'))
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line
102, in with_params
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack ret =
self.function(instance, *args, **kwargs)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line
534, in list_ports
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack **_params)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line
307, in list
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack for r in
self._pagination(collection, path, **params):
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line
320, in _pagination
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack res =
self.get(path, params=params)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line
293, in get
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack
headers=headers, params=params)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line
270, in retry_request
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack
headers=headers, params=params)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line
200, in do_request
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack
content_type=self.content_type())
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/neutronclient/client.py", line 306,
in do_request
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack return
self.request(url, method, **kwargs)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/neutronclient/client.py", line 294,
in request
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack resp =
super(SessionClient, self).request(*args, **kwargs)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/keystoneclient/adapter.py", line 95,
in request
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack return
self.session.request(url, method, **kwargs)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/keystoneclient/utils.py", line 318,
in inner
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack return
func(*args, **kwargs)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/keystoneclient/session.py", line
384, in request
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack resp =
send(**kwargs)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack File
"/usr/lib/python2.7/dist-packages/keystoneclient/session.py", line
425, in _send_request
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack raise
exceptions.RequestTimeout(msg)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack RequestTimeout:
Request to
http://172.18.0.2:9696/v2.0/ports.json?device_id=ba151850-22c8-4689-911b-d7c4aa82b4dc&device_id=ca9689da-37d2-4e65-b782-d7a899318a1a timed out
(HTTP
408)
2016-10-19 08:04:29.141 8433 TRACE nova.api.openstack
2016-10-19 08:04:29.146 8433 INFO nova.api.openstack
[req-90791e10-7506-424b-821e-364ab557e8b5 admin-genoa
00000000000003228460960090160000 - - -]
http://130.251.135.65:8774/v2/00000000000003228460960090160000/servers/detail
returned with HTTP 500
2016-10-19 08:04:29.148 8433 DEBUG nova.api.openstack.wsgi
[req-90791e10-7506-424b-821e-364ab557e8b5 admin-genoa
00000000000003228460960090160000 - - -] Returning 500 to user: The
server has either erred or is incapable of performing the requested
operation. _call_
/usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py:1166
2016-10-19 08:04:29.149 8433 INFO nova.osapi_compute.wsgi.server
[req-90791e10-7506-424b-821e-364ab557e8b5 admin-genoa
00000000000003228460960090160000 - - -] 172.18.0.11 "GET
/v2/00000000000003228460960090160000/servers/detail HTTP/1.1" status:
500 len: 354 time: 30.3907800
2016-10-19 08:04:29.230 8439 DEBUG keystoneclient.session [-] RESP:
_http_log_response
/usr/lib/python2.7/dist-packages/keystoneclient/session.py:226
2016-10-19 08:04:29.230 8439 DEBUG keystoneclient.session [-] Request
returned failure status: 404 request
/usr/lib/python2.7/dist-packages/keystoneclient/session.py:398
2016-10-19 08:04:29.231 8439 WARNING keystonemiddleware.auth_token [-]
Authorization failed for token
2016-10-19 08:04:29.231 8439 WARNING keystonemiddleware.auth_token [-]
Identity response: {"error": {"message": "Could not find token:
8660895fc7034c8aaa93ae868ae2d0c9", "code": 404, "title": "Not Found"}}
2016-10-19 08:04:29.232 8439 WARNING keystonemiddleware.auth_token [-]
Authorization failed for token
2016-10-19 08:04:29.235 8439 INFO nova.osapi_compute.wsgi.server [-]
172.18.0.11 "GET /v2/0595b850bd2d44fa8911d488f7c27c96/images/detail
HTTP/1.1" status: 401 len: 278 time: 0.1447031
2016-10-19 08:04:29.236 8428 DEBUG nova.api.openstack.wsgi [-] Calling
method '<bound method Versions.index of
<nova.api.openstack.compute.versions.Versions object at
0x7f5330d36490>>' _process_stack
/usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py:783
----------------------------
Issue Links
- relates to
-
HELP-7566
FIWARE.Request.Lab.FIWARE.telefonica.network.IP.filtered.
-
- Closed
-
Activity
Hi,
These are the stats from the last 24 hours (aprox) of keystone statistics about http requests from 130.251.xx.xx IPs:
[ -1000 ] 16849 0.995627
........[ -1000 .401 ] 4 0.000237403
........[ -1000 .404 ] 944 0.0560271
........[ -1000 .200 ] 15843 0.940293
........[ -1000 .201 ] 25 0.00148377
[ 1000-5000 ] 72 0.00425456
........[ 1000-5000 .404 ] 3 0.0416667
........[ 1000-5000 .200 ] 69 0.958333
[ 5000-10000 ] 1 5.90912e-05
........[ 5000-10000.200 ] 1 1
[ 10000-20000 ] 1 5.90912e-05
........[ 10000-20000.200 ] 1 1
[ 20000-30000 ] 0
[ 30000-50000 ] 0
[ 50000- ] 0
[ CODE ] Count %Code kbytes
[ 300 ] 33 0.195001 30
[ 401 ] 4 0.023636 1
[ 200 ] 15914 94.037700 179866
[ 201 ] 25 0.147728 2943
[ 404 ] 947 5.595935 255
[Total ] 16923
The stats is divided in 2 parts — The 1st one gives in miliseconds how long did it take to get a response (example: ........[ -1000 .200 ] 15843 0.940293 — This means that 15843 requests took less than 1ms to get a response "200 OK" — This is almost 94.03% of the requests).
You can see that only 1 response took longer than 10seconds and none above 20 seconds.
The 2nd part shows that you only had 5 different error codes: 200, 201, 300, 401 and 404 —
-----------------------
All queries come from 130.251.xxx.6[467] (no query comes from 130.251.xxx.6[0123579] (... so controller02 doesn't get tokens, but someone else does – Who is 130.251.135.64?)
Maybe we could do some debug session together?
These are keystone stats.
Hi José
130.251.135.64 is the vrouter address, as shown in the /etc/controller.yaml snippet here below:
------------------------------
vips:
vrouter_pub:
network_role: public/vip
node_roles:
- controller
- primary-controller
namespace: vrouter
ipaddr: 130.251.135.64
------------------------------
Ok for debug session togheter. When it's possible your side?
proposal: tomorrow Thursday 26, at 10:00 Rome time
my Skype account: giorgio.robino
thanks
giorgio
10:15 (Rome time)
Hi Jose, ok our side. Please call me at Skype account: giorgio.robino
Thanks Josè for your time and help! 
I agree with ticket closing.
We verified that the probelm was related tp some IP filtering relating to server outside Genoa node Fiware-lab domain
(in a telefonica/third party firewall/router network misconfiguration)
All this caused as 2side effect" the Genoa node sanity-check failure last weeks 
Having solved that issue, the Genoa node sanity checks are back "green".
I'll please correct to correct last weeks karma calculation on genoa node.
Thanks again to all people involved in trobleshooting.
giorgio - genoa node fiware-lab team
Hi,
it seems the authentication is ok:
POST /v2.0/tokens HTTP/1.1" 200 58933
You have a 500 error in nova:
DEBUG (shell:911) The server has either erred or is incapable of
performing the requested operation. (HTTP 500) (Request-ID:
req-90791e10-7506-424b-821e
-364ab557e8b5)