Hi @himdel I finally found the token error in the log
MIQ(Api::RequestsController.log_request) API Request: {:requested_at=>"2021-03-01 17:43:24 UTC"
MIQ(Api::RequestsController.rescue in authenticate_with_system_token) Authentication Failed with System Token
MIQ(Api::RequestsController.rescue in authenticate_with_system_token) X-MIQ-Token: v2:{A7WSSelfFYB2O.....
MIQ(Api::RequestsController.rescue in authenticate_with_system_token) Error: Invalid timestamp 2021-03-01 17:42:47 UTC specified
it seems that the request was made 37 sec after the timestamp. when is this v2 token created and is there a way to increase how long it lasts for?
the token seems to come from the core repo, app/models/miq_region.rb api_system_auth_token
and the timeout is not 5 minutes, only 30 secons now...
app/controllers/api/base_controller/authentication.rb
6: SYSTEM_TOKEN_TTL = 30.seconds
136: raise "Invalid timestamp #{timestamp} specified" if SYSTEM_TOKEN_TTL.ago.utc > timestampI don't think there's a toggle to change it
So thanks for all the replies. The global region and remote region times are fully synced to the second. we see that time increase as the load on the remote region db increases. If the load average on the db is below 10 the the calls happen in around 15 seconds but when the load gets to 20 -30 we see the times go to 30 to 60 seconds. It is a black box to us as well as to what it is doing in this time.
[----] I, [2021-03-01T15:15:14.713011 #26355:3e09950] INFO -- : MIQ(Api::ServiceCatalogsController.log_request) Response: {:completed_at=>"2021-03-01 20:15:14 UTC", :size=>"1.580 KBytes", :time_taken=>"15.014 Seconds", :status=>200}
[----] I, [2021-03-01T13:49:01.386888 #26389:3d5016c] INFO -- : MIQ(Api::ServiceCatalogsController.log_request) Response: {:completed_at=>"2021-03-01 18:49:01 UTC", :size=>"0.123 KBytes", :time_taken=>"60.334 Seconds", :status=>500}
Just to provide some more data we updated the logs to show debug data and we are seeing a single vm retire task perform this query 1200 times with a different id each time. Is this expected behavior? In total we had over 70K lines for one retire.
Q-task_id([r5000000588240_vm_retire_task_5000000757649]) (85.3ms) SELECT "vms"."id" FROM "vms" WHERE (LOWER((SELECT "users"."userid" FROM "users" WHERE "users"."id" = "vms"."evm_owner_id")) = '**')
configure_server_settings.rb in the tools directory (I’ve only ever tried this on a VM appliance rather than podified though). There’s an example playbook that uses this here: https://github.com/pemcg/configure-for-migration-analytics/blob/master/tasks/configure-server-settings.yml
1 reply
curl --insecure -H "Content-type: application/json" -d '{
"action": "retire"
}' 'https://inframgmtinstall.apps.b-cp4mcm-23-1.cp.fyre.com/api/vms/702' --user "admin:smartvm"
{"success":true,"message":"VM id:702 name:'Lrh-rhcos-4.2' retiring","href":"https://inframgmtinstall.apps.b-cp4mcm-23-1.cp.fyre.com/api/vms/702"}%
I see the following in the logs.
production.log
[----] I, [2021-03-26T15:28:31.985878 #8133:2b093270cb58] INFO -- : Started POST "/api/vms/68" for 9.211.146.90 at 2021-03-26 15:28:31 -0400
[----] I, [2021-03-26T15:28:31.995340 #8133:2b093270cb58] INFO -- : Processing by Api::VmsController#update as JSON
[----] I, [2021-03-26T15:28:31.995492 #8133:2b093270cb58] INFO -- : Parameters: {"c_id"=>"68", "vm"=>{}}
[----] I, [2021-03-26T15:28:32.400886 #8133:2b093270cb58] INFO -- : Completed 200 OK in 405ms (Views: 0.2ms | ActiveRecord: 14.2ms | Allocations: 12025)evm.log
[----] I, [2021-03-26T15:28:32.397823 #8133:2b093270cb58] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::Vm#retire_now) Vm: retirement for [id:<68>, name:<Lrh-rhcos-4.2>] got updated while waiting to be unlocked and is now initializingI do not find any reference to this transaction in the automate log but I do not understand what I need to be looking for.
