Requesting authentication token sometimes fails

[tsoenen]

Hi guys (@jbonnet @dang03 @felipevicens ),

I noticed that sometimes, the SLM fails to receive a token when requesting one. This is from the GK logs when such an event arises. Its hard to reproduce, it just happens sometimes (during the same SP instantation it is sometimes successful, fails, and is successful again):

D, [2018-02-09T11:25:26.950561 #1] DEBUG -- GtkApi::MicroService#find_by_credentials: entered with credentials c29uLXNsbToxMjM0
D, [2018-02-09T11:25:26.950670 #1] DEBUG -- GtkApi::ManagerService#postCurb: entered with url=http://son-gtkusr:5600/api/v1/login/service, body={}
D, [2018-02-09T11:25:26.950789 #1] DEBUG -- GtkApi::ManagerService#postCurb: header[authorization]: basic c29uLXNsbToxMjM0
D, [2018-02-09T11:25:27.310756 #1] DEBUG -- GtkApi::ManagerService#postCurb: response body={"error":"unauthorized_client","error_description":"INVALID_CREDENTIALS: Invalid client credentials"}
E, [2018-02-09T11:25:27.310878 #1] ERROR -- GtkApi::ManagerService#postCurb: Status 400
D, [2018-02-09T11:25:27.310926 #1] DEBUG -- GtkApi::MicroService#find_by_credentials: Status 400 when looking for micro_service with credentials c29uLXNsbToxMjM0
E, [2018-02-09T11:25:27.310983 #1] ERROR -- GtkApi::MicroService#find_by_credentials: Error during processing: c29uLXNsbToxMjM0
E, [2018-02-09T11:25:27.311107 #1] ERROR -- GtkApi::MicroService#find_by_credentials: Backtrace:
	/app/models/micro_service.rb:112:in `find_by_credentials'
	/app/routes/micro_services_controller.rb:80:in `block (2 levels) in <class:GtkApi>'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1632:in `call'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1632:in `block in compile!'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:991:in `block (3 levels) in route!'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1010:in `route_eval'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:991:in `block (2 levels) in route!'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1037:in `block in process_route'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1035:in `catch'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1035:in `process_route'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:989:in `block in route!'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:988:in `each'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:988:in `route!'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1094:in `block in dispatch!'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1073:in `block in invoke'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1073:in `catch'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1073:in `invoke'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1091:in `dispatch!'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:923:in `block in call!'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1073:in `block in invoke'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1073:in `catch'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1073:in `invoke'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:923:in `call!'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:913:in `call'
	/usr/local/bundle/gems/rack-2.0.3/lib/rack/session/abstract/id.rb:232:in `context'
	/usr/local/bundle/gems/rack-2.0.3/lib/rack/session/abstract/id.rb:226:in `call'
	/usr/local/bundle/gems/rack-protection-2.0.0/lib/rack/protection/xss_header.rb:18:in `call'
	/usr/local/bundle/gems/rack-protection-2.0.0/lib/rack/protection/path_traversal.rb:16:in `call'
	/usr/local/bundle/gems/rack-protection-2.0.0/lib/rack/protection/json_csrf.rb:26:in `call'
	/usr/local/bundle/gems/rack-protection-2.0.0/lib/rack/protection/base.rb:50:in `call'
	/usr/local/bundle/gems/rack-protection-2.0.0/lib/rack/protection/base.rb:50:in `call'
	/usr/local/bundle/gems/rack-protection-2.0.0/lib/rack/protection/frame_options.rb:31:in `call'
	/usr/local/bundle/gems/rack-2.0.3/lib/rack/logger.rb:15:in `call'
	/usr/local/bundle/gems/rack-2.0.3/lib/rack/common_logger.rb:33:in `call'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:231:in `call'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:224:in `call'
	/usr/local/bundle/gems/rack-2.0.3/lib/rack/head.rb:12:in `call'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:194:in `call'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1955:in `call'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1499:in `block in call'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1726:in `synchronize'
	/usr/local/bundle/gems/sinatra-2.0.0/lib/sinatra/base.rb:1499:in `call'
	/usr/local/bundle/gems/puma-3.11.0/lib/puma/configuration.rb:225:in `call'
	/usr/local/bundle/gems/puma-3.11.0/lib/puma/server.rb:624:in `handle_request'
	/usr/local/bundle/gems/puma-3.11.0/lib/puma/server.rb:438:in `process_client'
	/usr/local/bundle/gems/puma-3.11.0/lib/puma/server.rb:302:in `block in run'
	/usr/local/bundle/gems/puma-3.11.0/lib/puma/thread_pool.rb:120:in `block in spawn_thread'
E, [2018-02-09T11:25:27.311239 #1] ERROR -- GtkApi:: GET /api/v2/micro-services: leaving with {"error":{"code":400,"message":"No micro-service with basic authentication c29uLXNsbToxMjM0 was found"}}
172.20.0.25 - - [09/Feb/2018:11:25:27 +0000] "GET /api/v2/micro-services HTTP/1.1" 400 104 0.3620
D, [2018-02-09T11:25:27.503523 #1] DEBUG -- GtkApi::KpiManagerService#update_metric: entered with {:job=>"sonata", :instance=>"gtkapi", :metric_type=>"counter", :name=>"service_metadata_queries", :docstring=>"how many service metadata queries by uuid have been made", :base_labels=>{:result=>"Unauthorized", :uuid=>"", :elapsed_time=>"6.5584e-05", :method=>"GET", :module=>"services", :time_stamp=>2018-02-09 11:25:27 UTC}}
D, [2018-02-09T11:25:27.503617 #1] DEBUG -- GtkApi::KpiManagerService#update_metric: url = http://sp.int3.sonata-nfv.eu:5400
D, [2018-02-09T11:25:27.503758 #1] DEBUG -- GtkApi::ManagerService#putCurb: entered with url=http://sp.int3.sonata-nfv.eu:5400/kpis, body={"job":"sonata","instance":"gtkapi","metric_type":"counter","name":"service_metadata_queries","docstring":"how many service metadata queries by uuid have been made","base_labels":{"result":"Unauthorized","uuid":"","elapsed_time":"6.5584e-05","method":"GET","module":"services","time_stamp":"2018-02-09 11:25:27 UTC"}}
D, [2018-02-09T11:25:27.603447 #1] DEBUG -- GtkApi::ManagerService#putCurb: response body=
D, [2018-02-09T11:25:27.603531 #1] DEBUG -- GtkApi::ManagerService#putCurb: status 201, parsed_response=[]
E, [2018-02-09T11:25:27.603586 #1] ERROR -- GtkApi::KpiManagerService#update_metric: response={:status=>201, :count=>0, :items=>[], :message=>"OK"}
E, [2018-02-09T11:25:27.603678 #1] ERROR -- GtkApi:: GET /api/v2/services/:uuid: leaving with {"error":{"code":401,"message":"Unauthorized: missing authorization header"}}
172.20.0.25 - - [09/Feb/2018:11:25:27 +0000] "GET /api/v2/services/7a16e87c-0d0c-4379-8dd1-ddb1e035688e HTTP/1.1" 401 77 0.1932

[tsoenen]

Hi @jbonnet @dang03 @felipevicens ,

Since this issue occurs once in a while (see this mornings demo during the call), we need a fix or a workaround to be in a good shape to demo the pilots during the review.

Have we made any progress in locating the source of the issue?

[dang03]

Hello @tsoenen,
I'm investigating this issue and haven't been able to reproduce it.
If this happens again, I need to know more information about the status of the User Management.
Logs can be accessed through http://xx.xx.sonata-nfv.eu:5600/admin/log
It is also important to state if the User Management was recently deployed or if it was already running for some time.

I'll keep checking.

[dang03]

Hi,
The code for the micro-services login process has been checked from GK API to User Manager component, with no issues found on the code.

I achieved to reproduce the error for one scenario. Apparently the problem is that the SLM micro-service is no longer registered in the Keycloak framework, when it is attempting to login to the platform.

This issue is probably due to a workflow problem related to Jenkins jobs (the GK or UM being re-deployed).

Keycloak manages the accounts and credentials. When bad credentials are provided for an existent account it returns "Invalid client secret".
If the account does not exists, it returns "INVALID_CREDENTIALS: Invalid client credentials"

However, the GK API does not make distinctions and returns "No micro-service with basic authentication c29uLXNsbToyMzQ= was found".

I haven't been able to reproduce this error for any other scenarios.