Bug 1514607

Summary: "Invalid System Authentication Token specified" error when creating vm from template in global
Product: Red Hat CloudForms Management Engine Reporter: Alex Newman <anewman>
Component: ReplicationAssignee: abellott
Status: CLOSED CURRENTRELEASE QA Contact: Alex Newman <anewman>
Severity: high Docs Contact:
Priority: high    
Version: 5.9.0CC: abellott, anewman, cpelland, dluong, jhardy, ncarboni, ngupta, nzunigaf, obarenbo, simaishi
Target Milestone: GAKeywords: Reopened, TestOnly
Target Release: 5.9.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: 5.9.0.10 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1552267 (view as bug list) Environment:
Last Closed: 2018-06-22 12:40:54 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1552267    

Description Alex Newman 2017-11-17 21:20:20 UTC
Description of problem:
"Invalid System Authentication Token specified" error when creating vm from template

Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1. provision vm from template in global region
2.
3.

Actual results:
Error: "Invalid System Authentication Token specified"

Expected results:
VM gets created

Additional info:
Found using VMware 6.0
Appliance Version 5.9.0.9.20171115202245_7429f75

Comment 2 Gregg Tanzillo 2017-11-17 21:21:43 UTC
Alex, please verify that the v2_key is the same on the global and all the sub regions.

Comment 6 Nick Carboni 2017-11-20 20:35:21 UTC
This seems to have been caused by https://github.com/ManageIQ/manageiq-api/pull/178 which turned the system token used to authenticate against the remote region api into a one request use token.

In this case, we are authenticating (request 1) then querying the remote api for the "requests" collection and failing.

This chain of events can be seen in the following log snippet:

[----] I, [2017-11-20T14:42:12.718111 #13829:b69400]  INFO -- : MIQ(Api::ApiController.log_request_initiated)  
[----] I, [2017-11-20T14:42:12.718321 #13829:b69400]  INFO -- : MIQ(Api::ApiController.log_request) API Request:    {:requested_at=>"2017-11-20 19:42:12 UTC", :method=>"GET", :url=>"https://10.8.196.204/api/?attributes=authorization"}
[----] I, [2017-11-20T14:42:12.728422 #13829:b69400]  INFO -- : MIQ(Api::ApiController.log_request) System Auth:    {:x_miq_token=>"v2:{qP1t/nnGjS2bBo3y3rwWDammoicHfHSs/CTv58eysBcMjeMBtoJi/3R5ME22GXPSkeaZvNr+/vbs1xpoxs+c0gE19tN0tvYwmX0xaU5sbagseJta178sVeCXh474+KFcnZUjB++XatHYSj7hILK8bmrmLa96JKGXIdiqy9ftzlw=}", :server_guid=>"a7e0f798-c755-4440-a1c8-c8bc0f35d582", :userid=>"admin", :timestamp=>2017-11-20 19:42:12 UTC}
[----] I, [2017-11-20T14:42:12.728600 #13829:b69400]  INFO -- : MIQ(Api::ApiController.log_request) Authentication: {:type=>"system", :token=>nil, :x_miq_group=>nil, :user=>"admin"}
[----] I, [2017-11-20T14:42:12.730208 #13829:b69400]  INFO -- : MIQ(Api::ApiController.log_request) Authorization:  {:user=>"admin", :group=>"EvmGroup-super_administrator", :role=>"EvmRole-super_administrator", :tenant=>"My Company"}
[----] I, [2017-11-20T14:42:12.730773 #13829:b69400]  INFO -- : MIQ(Api::ApiController.log_request) Request:        {:method=>:get, :action=>"read", :fullpath=>"/api/?attributes=authorization", :url=>"https://10.8.196.204/api/?attributes=authorization", :base=>"https://10.8.196.204", :path=>"/api", :prefix=>"/api", :version=>"3.0.0", :api_prefix=>"https://10.8.196.204/api", :collection=>nil, :c_suffix=>nil, :collection_id=>nil, :subcollection=>nil, :subcollection_id=>nil}
[----] I, [2017-11-20T14:42:12.731297 #13829:b69400]  INFO -- : MIQ(Api::ApiController.log_request) Parameters:     {"attributes"=>"authorization", "action"=>"index", "controller"=>"api/api", "format"=>"json", "body"=>{}}
[----] I, [2017-11-20T14:42:12.826605 #13829:b69400]  INFO -- : MIQ(Api::ApiController.log_request) Response:       {:completed_at=>"2017-11-20 19:42:12 UTC", :size=>"166.056 KBytes", :time_taken=>"0.108 Seconds", :status=>200}
[----] I, [2017-11-20T14:42:12.863401 #13829:b697d4]  INFO -- : MIQ(Api::RequestsController.log_request_initiated)  
[----] I, [2017-11-20T14:42:12.863728 #13829:b697d4]  INFO -- : MIQ(Api::RequestsController.log_request) API Request:    {:requested_at=>"2017-11-20 19:42:12 UTC", :method=>"GET", :url=>"https://10.8.196.204/api/requests?expand=resources"}
[----] E, [2017-11-20T14:42:12.864600 #13829:b697d4] ERROR -- : MIQ(Api::RequestsController.rescue in authenticate_with_system_token) API Error
[----] E, [2017-11-20T14:42:12.864723 #13829:b697d4] ERROR -- : MIQ(Api::RequestsController.rescue in authenticate_with_system_token) Authentication Failed with System Token
[----] E, [2017-11-20T14:42:12.864811 #13829:b697d4] ERROR -- : MIQ(Api::RequestsController.rescue in authenticate_with_system_token) X-MIQ-Token: v2:{qP1t/nnGjS2bBo3y3rwWDammoicHfHSs/CTv58eysBcMjeMBtoJi/3R5ME22GXPSkeaZvNr+/vbs1xpoxs+c0gE19tN0tvYwmX0xaU5sbagseJta178sVeCXh474+KFcnZUjB++XatHYSj7hILK8bmrmLa96JKGXIdiqy9ftzlw=}
[----] E, [2017-11-20T14:42:12.864870 #13829:b697d4] ERROR -- : MIQ(Api::RequestsController.rescue in authenticate_with_system_token) Error: System Token was already used at 2017-11-20 14:42:12 -0500
[----] E, [2017-11-20T14:42:12.865153 #13829:b697d4] ERROR -- : MIQ(Api::RequestsController.api_error) API Error
[----] E, [2017-11-20T14:42:12.865240 #13829:b697d4] ERROR -- : MIQ(Api::RequestsController.api_error) Api::AuthenticationError: Invalid System Authentication Token specified
[----] I, [2017-11-20T14:42:12.866004 #13829:b697d4]  INFO -- : MIQ(Api::RequestsController.log_request) Response:       {:completed_at=>"2017-11-20 19:42:12 UTC", :size=>"0.126 KBytes", :time_taken=>"0.003 Seconds", :status=>401}

Assigning to Alberto.

Comment 7 Nick Carboni 2017-11-21 14:06:24 UTC
https://github.com/ManageIQ/manageiq-api/pull/219