Re: Strange issues with new App Volumes Manager re...

Perttu · ‎12-31-2021

Hi guys,

We were replacing older Windows Server 2012 R2 App Volumes Manager servers with WS 2019 instances, while we hit an issue where a post installation registration task fails on the new servers. The App Volumes version is newest 2111 / 4.5.0.77.

And what is extraordinary here, that during the registration the unregistered server tries to communicate with a registered instance by talking plain HTTP to HTTPS port. I accidentally noticed this while capturing conversation to gain a better insight.

So, to amaze you, compare the following capture and corresponding log lines. I censored public IP address and domains. The most interesting line is in bold. capture

[2021-12-30 22:49:20 UTC] P8916R4 INFO Started POST "/cv_api/manager_services/register" for 127.0.0.1 at 2021-12-31 00:49:20 +0200
[2021-12-30 22:49:20 UTC] P8916R4 INFO Processing by CvApi::ManagerServicesController#register as JS
[2021-12-30 22:49:20 UTC] P8916R4 INFO Parameters: {"utf8"=>"✓", "data"=>{"secured_address"=>"vdi-appvol-old.ourdomain", "username"=>"adminUser", "password"=>"[FILTERED]", "domain"=>"OURDOMAIN", "cert_fingerprint"=>""}}
[2021-12-30 22:49:20 UTC] P8916R4 INFO Referred by https://vdi-appvol-new.ourdomain/register using Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.110 Safari/537.36
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG SQL: ActiveRecord::SessionStore::Session Load (1.2ms) EXEC sp_executesql N'SELECT [sessions].* FROM [sessions] WHERE [sessions].[session_id] = @0 ORDER BY [sessions].[id] ASC OFFSET 0 ROWS FETCH NEXT @1 ROWS ONLY', N'@0 nvarchar(255), @1 int', @0 = N'ac500424abd497cea8880bf161e19056', @1 = 1 [["session_id", nil], ["LIMIT", nil]]
[2021-12-30 22:49:20 UTC] P8916R4 INFO Unable to extract user from JWT token for user: No authorization header found
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG SQL: ManagerService Load (1.7ms) EXEC sp_executesql N'SELECT [manager_services].* FROM [manager_services] WHERE [manager_services].[guid] = @0 ORDER BY [manager_services].[id] ASC OFFSET 0 ROWS FETCH NEXT @1 ROWS ONLY', N'@0 nvarchar(36), @1 int', @0 = N'507fb5c1-9931-4f61-904e-c68b7ad0d398', @1 = 1 [["guid", nil], ["LIMIT", nil]]
[2021-12-30 22:49:20 UTC] P8916R4 INFO Connecting to AppVolumes Manager "adminUser@vdi-appvol-old.ourdomain:443" on "#<Thread:0x00000204c6edb210@puma server threadpool 001 C:/Program Files (x86)/CloudVolumes/Manager/vendor/bundle/ruby/2.7.0/gems/puma-5.5.2/lib/puma/thread_pool.rb:104 run>"
[2021-12-30 22:49:20 UTC] P8916R4 INFO Establishing verified SSL connection to AppVolumes Manager at "adminUser@vdi-appvol-old.ourdomain:443" using certificate authorities from file: "C:/Program Files (x86)/CloudVolumes/Manager/config/cacert.pem"
[2021-12-30 22:49:20 UTC] P8916R4 ERROR Failed to connect AppVolumes Manager server at "adminUser@vdi-appvol-old.ourdomain:443" with the following error: Bad Request
[2021-12-30 22:49:20 UTC] P8916R4 INFO Failed to connect Manager Instance "adminUser@vdi-appvol-old.ourdomain:443 with error: Bad Request "
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG Failed to connect Manager Service with guid "507fb5c1-9931-4f61-904e-c68b7ad0d398" to "adminUser@vdi-appvol-old.ourdomain:443"
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG Active database connections: 1
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG Total database connections: 1
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG Thread count: 8
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG Session loaded during this request? true 
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG Time spend garbage collecting this request: 0.0ms
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG Objects: {:TOTAL=>798892, :FREE=>124195, :T_OBJECT=>34001, :T_CLASS=>12348, :T_MODULE=>1971, :T_FLOAT=>12, :T_STRING=>182865, :T_REGEXP=>2995, :T_ARRAY=>122290, :T_HASH=>43431, :T_STRUCT=>1228, :T_BIGNUM=>4009, :T_FILE=>80, :T_DATA=>29728, :T_MATCH=>2428, :T_COMPLEX=>1, :T_RATIONAL=>142, :T_SYMBOL=>2587, :T_IMEMO=>227833, :T_ICLASS=>6748}
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG SQL: Svconfiguration Exists (1.2ms) EXEC sp_executesql N'SELECT 1 AS one FROM [svconfigurations] WHERE [svconfigurations].[id] = @0 AND [svconfigurations].[updated_at] = @1 ORDER BY [svconfigurations].[id] ASC OFFSET 0 ROWS FETCH NEXT @2 ROWS ONLY', N'@0 int, @1 datetime, @2 int', @0 = 1, @1 = '12-17-2021 10:48:46.576', @2 = 1 [["id", nil], ["updated_at", nil], ["LIMIT", nil]]
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG Cvo: Rejecting temporary adapters under "temporary#<Thread:0x00000204c6edb210@puma server threadpool 001 C:/Program Files (x86)/CloudVolumes/Manager/vendor/bundle/ruby/2.7.0/gems/puma-5.5.2/lib/puma/thread_pool.rb:104 run>" reserved from "#<Thread:0x00000204c6edb210@puma server threadpool 001 C:/Program Files (x86)/CloudVolumes/Manager/vendor/bundle/ruby/2.7.0/gems/puma-5.5.2/lib/puma/thread_pool.rb:104 run>"
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG Cvo: Cache Queue : Rejecting temporary adapter Factory -> @pools #pools: 0 -- @pools #items: 0 @inuse #pools: 0 -- @inuse #items: 0 Total Pools : 0 -- Total items : 0 
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG Cvo: Releasing 0 adapters from 0 pools reserved from "#<Thread:0x00000204c6edb210@puma server threadpool 001 C:/Program Files (x86)/CloudVolumes/Manager/vendor/bundle/ruby/2.7.0/gems/puma-5.5.2/lib/puma/thread_pool.rb:104 run>"
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG Cvo: There are now 0 pools with 0 total items
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG Cvo: Cache Queue : Releasing adapter Factory -> @pools #pools: 0 -- @pools #items: 0 @inuse #pools: 0 -- @inuse #items: 0 Total Pools : 0 -- Total items : 0 
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG LDAP: Rejecting temporary adapters under "temporary_#<Thread:0x00000204c6edb210@puma server threadpool 001 C:/Program Files (x86)/CloudVolumes/Manager/vendor/bundle/ruby/2.7.0/gems/puma-5.5.2/lib/puma/thread_pool.rb:104 run>" reserved from "#<Thread:0x00000204c6edb210@puma server threadpool 001 C:/Program Files (x86)/CloudVolumes/Manager/vendor/bundle/ruby/2.7.0/gems/puma-5.5.2/lib/puma/thread_pool.rb:104 run>"
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG Cvo: Cache Queue : Rejecting temporary adapter Factory -> @pools #pools: 0 -- @pools #items: 0 @inuse #pools: 0 -- @inuse #items: 0 Total Pools : 0 -- Total items : 0 
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG LDAP: Releasing 0 adapters from 0 pools reserved from "#<Thread:0x00000204c6edb210@puma server threadpool 001 C:/Program Files (x86)/CloudVolumes/Manager/vendor/bundle/ruby/2.7.0/gems/puma-5.5.2/lib/puma/thread_pool.rb:104 run>"
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG LDAP: There are now 0 pools with 0 total items
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG Cvo: Cache Queue : Releasing adapter thread Repository -> @pools #pools: 0 -- @pools #items: 0 @inuse #pools: 0 -- @inuse #items: 0 Total Pools : 0 -- Total items : 0 
[2021-12-30 22:49:20 UTC] P8916R4 INFO Completed 400 Bad Request in 224ms (Views: 0.3ms | ActiveRecord: 29.8ms)
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG SQL: ActiveRecord::SessionStore::Session Load (1.3ms) EXEC sp_executesql N'SELECT [sessions].* FROM [sessions] WHERE [sessions].[session_id] = @0 ORDER BY [sessions].[id] ASC OFFSET 0 ROWS FETCH NEXT @1 ROWS ONLY', N'@0 nvarchar(255), @1 int', @0 = N'ac500424abd497cea8880bf161e19056', @1 = 1 [["session_id", nil], ["LIMIT", nil]]
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG SQL: SQL (0.7ms) BEGIN TRANSACTION
[2021-12-30 22:49:20 UTC] P8916R4 DEBUG SQL: SQL (0.7ms) COMMIT TRANSACTION
[2021-12-30 22:49:20 UTC] P8916R4 INFO

Few notes: cacert.pem includes the CA Root Certificates, which have issued App Volumes Manager nginx-certificates. I've also tried without them. Issue was same with bit different log line.

This is also being investigated in SR 21288617812, but on tier 0. Hence I was hoping that somebody here would have a better understanding of how this software is built, and what is happening here. Something overrides the SSL layer completely and turns it off.

Whether related or not, the new Managers are also logging following errors:

[2021-12-28 18:41:07 UTC]       P444R9 DEBUG        SQL:   Settings::Setting Load (1.1ms)  EXEC sp_executesql N'SELECT  [settings].* FROM [settings] WHERE (settings.type IS NULL OR settings.type IN (N''Rbac::RbacSetting'',N''Settings::Feature'',N''MachineManagerSetting'',N''Settings::AdvancedSetting'',N''Settings::BotConfiguration'')) AND [settings].[key] = @0  ORDER BY [settings].[id] ASC OFFSET 0 ROWS FETCH NEXT @1 ROWS ONLY', N'@0 nvarchar(100), @1 int', @0 = N'encryption_version', @1 = 1  [["key", nil], ["LIMIT", nil]]
[2021-12-28 18:41:07 UTC]       P444R9 DEBUG        SQL:   ManagerService Load (1.0ms)  EXEC sp_executesql N'SELECT  [manager_services].* FROM [manager_services] WHERE [manager_services].[guid] = @0  ORDER BY [manager_services].[id] ASC OFFSET 0 ROWS FETCH NEXT @1 ROWS ONLY', N'@0 nvarchar(36), @1 int', @0 = N'1b4c8cec-78ef-469e-a128-6a19df047111', @1 = 1  [["guid", nil], ["LIMIT", nil]
[2021-12-28 18:41:07 UTC]       P444R9 ERROR App Volumes database security settings are not configured to use App Volumes private key files.

I inspected this settings.encryption_version DB row and it shows a value of 3. Whatever it really means, Google don't tell.

Happy new year for all you readers.

Perttu · ‎01-21-2022

Apparently this was a known issue and the fix is to allow http on the server against which the registration is done. Super thanks to this blogger, and I'm bit disappointed about the VMware quality here.

https://my-virt.alfadir.net/index.php/2022/01/07/app-volumes-4-5-error-failed-to-connect-manager-ser...

jpsilver · ‎02-16-2022

We came across this problem yesterday and the fix is to add the following to nginx.conf

listen 80;
listen [::]:80;

put these directly under

server {
server_name 0.0.0.0;

and then reboot the first AppVolumes Manager server

Then connect to the second AppVolumes manager and put in

<FQDN>:80

where FQDN is the fully qualified domain name.

and your login credentials and it will work.

tifc · ‎04-01-2022

This works for us as well today 😊

All

Strange issues with new App Volumes Manager registration.