search

sonata-nfv / son-gkeeper

SONATA's Service Platform Gatekeeper
http://www.sonata-nfv.eu
Apache License 2.0
2 stars 18 forks source link

empty response on get /vim/:uuid request #836

Open santiagordguez opened 7 years ago

santiagordguez commented 7 years ago

Hi @jbonnet

Once recovered the list of vim requests (GET /vims) that responses with {"status":201,"count":1,"items":{"request_uuid":"b86771d2-2176-48d8-a484-a390e902cc29"},"message":"OK"} the GET https://sp.int3.sonata-nfv.eu/api/v2/vims/b86771d2-2176-48d8-a484-a390e902cc29 responses with a "[]" but in the logs we can see:

#son-gtkvim log:

I, [2017-08-25 12:38:25#8]  INFO -- : GtkVim: GET /vim/compute-resources with params={}
D, [2017-08-25T12:38:25.087451 #8] DEBUG -- :    (0.2ms)  BEGIN
D, [2017-08-25T12:38:25.088425 #8] DEBUG -- :   SQL (0.3ms)  INSERT INTO "vims_requests" ("created_at", "updated_at") VALUES ($1, $2) RETURNING "id"  [["created_at", "2017-08-25 12:38:25.087573"], ["updated_at", "2017-08-25 12:38:25.087573"]]
D, [2017-08-25T12:38:25.091718 #8] DEBUG -- :    (3.0ms)  COMMIT
D, [2017-08-25T12:38:25.092262 #8] DEBUG -- :    (0.4ms)  BEGIN
D, [2017-08-25T12:38:25.093233 #8] DEBUG -- :   SQL (0.3ms)  UPDATE "vims_requests" SET "status" = $1, "updated_at" = $2 WHERE "vims_requests"."id" = $3  [["status", "new"], ["updated_at", "2017-08-25 12:38:25.092365"], ["id", "e52a1e2b-be59-48e1-be07-11cec275c783"]]
D, [2017-08-25T12:38:25.093972 #8] DEBUG -- :    (0.5ms)  COMMIT
D, [2017-08-25T12:38:25.094080 #8] DEBUG -- : MQServer.publish {} with correlation e52a1e2b-be59-48e1-be07-11cec275c783 to infrastructure.management.compute.list
I, [2017-08-25 12:38:25#8]  INFO -- : GtkVim: returning GET /vim/compute-resources with request={"request_uuid":"e52a1e2b-be59-48e1-be07-11cec275c783"}
172.20.0.1 - - [25/Aug/2017:12:38:25 +0000] "GET /vim/compute-resources HTTP/1.1" 201 55 0.0116
D, [2017-08-25 12:38:25#8] DEBUG -- : GtkVim: entered GET /vim_requests/compute-resources/e52a1e2b-be59-48e1-be07-11cec275c783
D, [2017-08-25T12:38:25.347650 #8] DEBUG -- :   VimsRequest Load (0.3ms)  SELECT  "vims_requests".* FROM "vims_requests" WHERE "vims_requests"."id" = $1 LIMIT 1  [["id", "e52a1e2b-be59-48e1-be07-11cec275c783"]]
D, [2017-08-25 12:38:25#8] DEBUG -- : GtkVim: found request for e52a1e2b-be59-48e1-be07-11cec275c783, but it's not complete yet
172.20.0.1 - - [25/Aug/2017:12:38:25 +0000] "GET /vim_requests/compute-resources/e52a1e2b-be59-48e1-be07-11cec275c783 HTTP/1.1" 202 38 0.0021
D, [2017-08-25T12:38:25.953450 #8] DEBUG -- : MQServer.consume: delivery_info: {:consumer_tag=>"bunny-1503664352000-926673108136", :delivery_tag=>#<Bunny::VersionedDeliveryTag:0x00563cca058220 @tag=8, @version=0>, :redelivered=>false, :exchange=>"son-kernel", :routing_key=>"infrastructure.management.compute.list", :consumer=>#<Bunny::Consumer:47409541470840 @channel_id=1 @queue=infrastructure.management.compute.list> @consumer_tag=bunny-1503664352000-926673108136 @exclusive=false @no_ack=true>, :channel=>#<Bunny::Channel:47409541519460 @id=1 @connection=#<Bunny::Session:0x563cc9c421e0 guest@sp.int3.sonata-nfv.eu:5672, vhost=/, addresses=[sp.int3.sonata-nfv.eu:5672]>>}
D, [2017-08-25T12:38:25.953554 #8] DEBUG -- : MQServer.consume: properties: {:content_type=>"application/x-yaml", :delivery_mode=>2, :correlation_id=>"e52a1e2b-be59-48e1-be07-11cec275c783", :app_id=>"sonata.kernel.InfrAdaptor"}
D, [2017-08-25T12:38:25.953581 #8] DEBUG -- : MQServer.consume: payload: ---
- core_total: 20
  core_used: 7
  memory_total: 51200
  memory_used: 18432
  vim_city: "Athens"
  vim_endpoint: "10.100.32.200"
  vim_name: "Athens-200"
  vim_uuid: "1111-22222222-33333333-4444"

D, [2017-08-25T12:38:25.962609 #8] DEBUG -- :   VimsRequest Load (8.4ms)  SELECT  "vims_requests".* FROM "vims_requests" WHERE "vims_requests"."id" = $1 LIMIT 1  [["id", "e52a1e2b-be59-48e1-be07-11cec275c783"]]
D, [2017-08-25T12:38:25.968038 #8] DEBUG -- :    (4.7ms)  BEGIN
D, [2017-08-25T12:38:25.971028 #8] DEBUG -- :   SQL (1.7ms)  UPDATE "vims_requests" SET "status" = $1, "query_response" = $2, "updated_at" = $3 WHERE "vims_requests"."id" = $4  [["status", "complete"], ["query_response", "[{\"core_total\":20,\"core_used\":7,\"memory_total\":51200,\"memory_used\":18432,\"vim_city\":\"Athens\",\"vim_endpoint\":\"10.100.32.200\",\"vim_name\":\"Athens-200\",\"vim_uuid\":\"1111-22222222-33333333-4444\"}]"], ["updated_at", "2017-08-25 12:38:25.968418"], ["id", "e52a1e2b-be59-48e1-be07-11cec275c783"]]
D, [2017-08-25T12:38:26.008436 #8] DEBUG -- :    (36.9ms)  COMMIT
D, [2017-08-25T12:38:26.008550 #8] DEBUG -- : MQServer.consume: vimsquery saved

son-gtkapi log:

E, [2017-08-25T12:43:52.760094 #6] ERROR -- GtkApi::KpiManagerService#update_metric: response={:status=>201, :count=>1, :items=>[], :message=>"OK"}
172.20.0.34 - - [25/Aug/2017:12:43:52 +0000] "GET /api/v2/services?status=active&limit=10&offset=0 HTTP/1.0" 200 3670 0.2865
D, [2017-08-25T12:43:52.800058 #6] DEBUG -- GtkApi: query_string=
/app/routes/vim.rb:86: warning: already initialized constant GtkApi::MESSAGE
/app/routes/request.rb:82: warning: previous definition of MESSAGE was here
I, [2017-08-25 12:43:52#6]  INFO -- GtkApi GET /api/v2/vims?: entered
D, [2017-08-25T12:43:52.800263 #6] DEBUG -- GtkApi.check_rate_limit: entered
D, [2017-08-25T12:43:52.800318 #6] DEBUG -- GtkApi.check_rate_limit: settings.services['rate_limiter']={"model"=>"RateLimiter", "env_var_url"=>"RATE_LIMITER_URL", "limits"=>{"anonymous_operations"=>{"description"=>"Limit imposed to the user creation process (ten times per minute)", "period"=>60, "limit"=>10}, "other_operations"=>{"description"=>"Limit imposed to the remaining operations (once per second)", "period"=>1, "limit"=>1}}}
D, [2017-08-25T12:43:52.800415 #6] DEBUG -- GtkApi::RateLimiter#check: entered with {:limit_id=>"anonymous_operations", :client_id=>"f495c4d6-4c07-4b5d-b73f-6fb2b0eb42e8"}
D, [2017-08-25T12:43:52.800455 #6] DEBUG -- GtkApi::ManagerService#postCurb: entered with url=http://son-gtkrlt:5150/check, body={:limit_id=>"anonymous_operations", :client_id=>"f495c4d6-4c07-4b5d-b73f-6fb2b0eb42e8"}
D, [2017-08-25T12:43:52.803371 #6] DEBUG -- GtkApi::ManagerService#postCurb: response body={"allowed":true,"remaining":9}
D, [2017-08-25T12:43:52.803455 #6] DEBUG -- GtkApi::ManagerService#postCurb: status 200, parsed_response={:allowed=>true, :remaining=>9}
D, [2017-08-25T12:43:52.803497 #6] DEBUG -- GtkApi::RateLimiter#check: resp={:status=>200, :count=>1, :items=>{:allowed=>true, :remaining=>9}, :message=>"OK"}
D, [2017-08-25T12:43:52.803530 #6] DEBUG -- GtkApi.check_rate_limit: resp is {:allowed=>true, :remaining=>9}
D, [2017-08-25T12:43:52.803572 #6] DEBUG -- GtkApi::VimManagerService#find_vims_comp_rs({"offset"=>"0", "limit"=>"10"}): entered
D, [2017-08-25T12:43:52.803653 #6] DEBUG -- GtkApi::ManagerService#getCurb: entered with url=http://sp.int3.sonata-nfv.eu:5700/vim/compute-resources, params={}, headers={"Accept"=>"application/json", "Content-Type"=>"application/json"}
D, [2017-08-25T12:43:52.803701 #6] DEBUG -- GtkApi::ManagerService#getCurb: complete_url=http://sp.int3.sonata-nfv.eu:5700/vim/compute-resources
D, [2017-08-25T12:43:52.803774 #6] DEBUG -- GtkApi::ManagerService#getCurb: header[Accept]: application/json
D, [2017-08-25T12:43:52.803819 #6] DEBUG -- GtkApi::ManagerService#getCurb: header[Content-Type]: application/json
D, [2017-08-25T12:43:52.845323 #6] DEBUG -- GtkApi::ManagerService#getCurb: header_str=HTTP/1.1 201 Created
Content-Type: text/html;charset=utf-8
X-XSS-Protection: 1; mode=block
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
Content-Length: 55

D, [2017-08-25T12:43:52.845379 #6] DEBUG -- GtkApi::ManagerService#getCurb: response body={"request_uuid":"b86771d2-2176-48d8-a484-a390e902cc29"}
D, [2017-08-25T12:43:52.845522 #6] DEBUG -- GtkApi::ManagerService#getCurb: parsed_response={:request_uuid=>"b86771d2-2176-48d8-a484-a390e902cc29"}
D, [2017-08-25T12:43:52.845579 #6] DEBUG -- GtkApi::VimManagerService#find_vims_comp_rs({"offset"=>"0", "limit"=>"10"}): response={:status=>201, :count=>1, :items=>{:request_uuid=>"b86771d2-2176-48d8-a484-a390e902cc29"}, :message=>"OK"}
D, [2017-08-25 12:43:52#6] DEBUG -- GtkApi GET /api/v2/vims?: vims= {:status=>201, :count=>1, :items=>{:request_uuid=>"b86771d2-2176-48d8-a484-a390e902cc29"}, :message=>"OK"}
D, [2017-08-25T12:43:52.845754 #6] DEBUG -- GtkApi: Schema=http, host=sp.int3.sonata-nfv.eu, path=/api/v2/vims
D, [2017-08-25 12:43:52#6] DEBUG -- GtkApiHelper.build_pagination_headers: url: http://sp.int3.sonata-nfv.eu/api/v2/vims, limit: 10, offset: 0, total: 4
172.20.0.34 - - [25/Aug/2017:12:43:52 +0000] "GET /api/v2/vims HTTP/1.0" 200 103 0.0468
172.20.0.34 - - [25/Aug/2017:12:43:52 +0000] "OPTIONS /api/v2/vims/b86771d2-2176-48d8-a484-a390e902cc29 HTTP/1.0" 200 - 0.0006
D, [2017-08-25T12:43:53.033419 #6] DEBUG -- GtkApi.check_rate_limit: entered
D, [2017-08-25T12:43:53.033499 #6] DEBUG -- GtkApi.check_rate_limit: settings.services['rate_limiter']={"model"=>"RateLimiter", "env_var_url"=>"RATE_LIMITER_URL", "limits"=>{"anonymous_operations"=>{"description"=>"Limit imposed to the user creation process (ten times per minute)", "period"=>60, "limit"=>10}, "other_operations"=>{"description"=>"Limit imposed to the remaining operations (once per second)", "period"=>1, "limit"=>1}}}
D, [2017-08-25T12:43:53.033549 #6] DEBUG -- GtkApi::RateLimiter#check: entered with {:limit_id=>"anonymous_operations", :client_id=>"f495c4d6-4c07-4b5d-b73f-6fb2b0eb42e8"}
D, [2017-08-25T12:43:53.033588 #6] DEBUG -- GtkApi::ManagerService#postCurb: entered with url=http://son-gtkrlt:5150/check, body={:limit_id=>"anonymous_operations", :client_id=>"f495c4d6-4c07-4b5d-b73f-6fb2b0eb42e8"}
D, [2017-08-25T12:43:53.036338 #6] DEBUG -- GtkApi::ManagerService#postCurb: response body={"allowed":true,"remaining":8}
D, [2017-08-25T12:43:53.036408 #6] DEBUG -- GtkApi::ManagerService#postCurb: status 200, parsed_response={:allowed=>true, :remaining=>8}
D, [2017-08-25T12:43:53.036455 #6] DEBUG -- GtkApi::RateLimiter#check: resp={:status=>200, :count=>1, :items=>{:allowed=>true, :remaining=>8}, :message=>"OK"}
D, [2017-08-25T12:43:53.036488 #6] DEBUG -- GtkApi.check_rate_limit: resp is {:allowed=>true, :remaining=>8}
D, [2017-08-25 12:43:53#6] DEBUG -- : GtkApi: GET /api/v2/vims/b86771d2-2176-48d8-a484-a390e902cc29
D, [2017-08-25T12:43:53.036637 #6] DEBUG -- GtkApi::VimManagerService#find_vim_comp_rs_request_by_uuid(b86771d2-2176-48d8-a484-a390e902cc29): entered
D, [2017-08-25T12:43:53.036681 #6] DEBUG -- GtkApi::ManagerService#getCurb: entered with url=http://sp.int3.sonata-nfv.eu:5700/vim_requests/compute-resources/b86771d2-2176-48d8-a484-a390e902cc29, params={}, headers={"Accept"=>"application/json", "Content-Type"=>"application/json"}
D, [2017-08-25T12:43:53.036708 #6] DEBUG -- GtkApi::ManagerService#getCurb: complete_url=http://sp.int3.sonata-nfv.eu:5700/vim_requests/compute-resources/b86771d2-2176-48d8-a484-a390e902cc29
D, [2017-08-25T12:43:53.036757 #6] DEBUG -- GtkApi::ManagerService#getCurb: header[Accept]: application/json
D, [2017-08-25T12:43:53.036788 #6] DEBUG -- GtkApi::ManagerService#getCurb: header[Content-Type]: application/json
D, [2017-08-25T12:43:53.089161 #6] DEBUG -- GtkApi::ManagerService#getCurb: header_str=HTTP/1.1 202 Accepted
Content-Type: text/html;charset=utf-8
X-XSS-Protection: 1; mode=block
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
Content-Length: 38

D, [2017-08-25T12:43:53.089213 #6] DEBUG -- GtkApi::ManagerService#getCurb: response body={"query_response":null,"status":"new"}
D, [2017-08-25T12:43:53.089300 #6] DEBUG -- GtkApi::ManagerService#getCurb: parsed_response={:query_response=>nil, :status=>"new"}
D, [2017-08-25T12:43:53.089351 #6] DEBUG -- GtkApi::VimManagerService#find_vim_comp_rs_request_by_uuid(b86771d2-2176-48d8-a484-a390e902cc29): Got response: {:status=>202, :count=>1, :items=>{:query_response=>nil, :status=>"new"}, :message=>"OK"}
D, [2017-08-25 12:43:53#6] DEBUG -- : GtkApi: leaving GET /vim_request/b86771d2-2176-48d8-a484-a390e902cc29" with request []
172.20.0.34 - - [25/Aug/2017:12:43:53 +0000] "GET /api/v2/vims/b86771d2-2176-48d8-a484-a390e902cc29 HTTP/1.0" 200 2 0.0568

Is this related with the rate limiter?

felipevicens commented 7 years ago

I'm getting this @srodriguezOPT https://sp.int3.sonata-nfv.eu/api/v2/vims/b86771d2-2176-48d8-a484-a390e902cc29 [{"core_total":20,"core_used":7,"memory_total":51200,"memory_used":18432,"vim_city":"Athens","vim_endpoint":"10.100.32.200","vim_name":"Athens-200","vim_uuid":"1111-22222222-33333333-4444"}]

jbonnet commented 7 years ago

@felipevicens with the rate limiter you get a 429 HTTP code (Too many requests). Do I understand correctly by @srodriguezOPT comment, that the problem is not there anymore?

santiagordguez commented 7 years ago

Hi @felipevicens , @jbonnet

In the BSS,

image

responses with {"status":201,"count":1,"items":{"request_uuid":"bd613b65-c2a7-45b9-999b-c8bddfcf911d"},"message":"OK"}

but

image

responses with

image

And as you mention, if the request is made directly in a browser, works fine

image

jbonnet commented 7 years ago

@srodriguezOPT , @felipevicens Let me check...

felipevicens commented 7 years ago

@srodriguezOPT The call is asyncronous. We need to wait until the answer is ready. The IA takes some time creating the reply to son-gtksrv. That's why the answer is empty

jbonnet commented 7 years ago

Exactly, just like the service instantiation requests...

santiagordguez commented 7 years ago

A retrying policy with 1 second between requests was implemented in the BSS for the getVims. It seems solved but we must put an eye on this to confirm it.

jbonnet commented 7 years ago

@srodriguezOPT A better solution is the BSS to have an endpoint the GK could call when things are ready (a callback). That endpoint should be passed in the initial request. Same for the services instantiation, update and termination.

santiagordguez commented 7 years ago

@jbonnet Yes, I agree. After this release, we need to develop a better solution for asynchronous requests. This solution (really ugly) is temporal for this release.