Benchmarking Katello using host registration

ekohl · May 10, 2023, 11:59am

Yesterday I spent some time to figure out how reliable Foreman’s host registration worked, together with Katello. This is because we’ve had reports that under high load this error showed up:

2023-05-09T22:19:30 [E|kat|95de4547] could not obtain a connection from the pool within 5.000 seconds (waited 5.001 seconds); all pooled connections were in use
2023-05-09T22:19:30 [E|kat|95de4547] Lost database connection. Attempting reconnect.

My approach was to use forklift to start up a centos8-stream-katello-nightly VM, configured with 8 GB RAM and 4 CPU cores. Then I wrote up a short script to spawn a container. It’s available in GitHub - ekohl/cat-bench but it’s short enough to inline here:

FROM quay.io/centos/centos:stream9
ENV LANG en_US.utf8
USER root
CMD [ "/sbin/init" ]
RUN dnf install systemd subscription-manager -y

Note that I don’t clean the DNF cache on purpose. The registration performs dnf install subscription-manager or dnf upgrade subscription-manager. Having the cache means every single container doesn’t need to reach out to the mirrors, saving a lot of time (and bandwidth).

A single run then takes about 21 seconds on my machine and results in the following log:

2023-05-09T16:51:01 [I|app|871e606f] Started POST "/api/registration_commands" for 192.168.122.83 at 2023-05-09 16:51:01 +0000
2023-05-09T16:51:01 [I|app|871e606f] Processing by Api::V2::RegistrationCommandsController#create as JSON
2023-05-09T16:51:01 [I|app|871e606f]   Parameters: {"registration_command"=>{"activation_keys"=>["test"], "insecure"=>true}, "apiv"=>"v2"}
2023-05-09T16:51:01 [I|app|871e606f] Authorized user admin(Admin User)
2023-05-09T16:51:01 [I|app|871e606f] Completed 200 OK in 174ms (Views: 0.1ms | ActiveRecord: 57.3ms | Allocations: 8574)
2023-05-09T16:51:01 [I|app|4022fa2f] Started GET "/register?activation_keys=test" for 192.168.122.83 at 2023-05-09 16:51:01 +0000
2023-05-09T16:51:01 [I|app|4022fa2f] Processing by Api::V2::RegistrationController#global as */*
2023-05-09T16:51:01 [I|app|4022fa2f]   Parameters: {"activation_keys"=>"test"}
2023-05-09T16:51:01 [I|app|4022fa2f] Authorized user admin(Admin User)
2023-05-09T16:51:01 [I|app|4022fa2f]   Rendered text template (Duration: 0.0ms | Allocations: 1)
2023-05-09T16:51:01 [I|app|4022fa2f] Completed 200 OK in 99ms (Views: 0.3ms | ActiveRecord: 50.1ms | Allocations: 45212)
2023-05-09T16:51:03 [I|app|e3bd5b9b] Started GET "/rhsm/" for 192.168.122.83 at 2023-05-09 16:51:03 +0000
2023-05-09T16:51:03 [I|app|e3bd5b9b] Processing by Katello::Api::V2::RootController#rhsm_resource_list as JSON
2023-05-09T16:51:03 [I|app|e3bd5b9b]   Parameters: {"root"=>{}}
2023-05-09T16:51:03 [I|app|e3bd5b9b] Completed 200 OK in 11ms (Views: 0.5ms | ActiveRecord: 9.1ms | Allocations: 1471)
2023-05-09T16:51:06 [I|app|0b8301dc] Started POST "/rhsm/consumers?owner=Default_Organization&activation_keys=test" for 192.168.122.83 at 2023-05-09 16:51:06 +0000
2023-05-09T16:51:06 [I|app|0b8301dc] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_activate as JSON
2023-05-09T16:51:06 [I|app|0b8301dc]   Parameters: {"type"=>"system", "name"=>"0cf98b93f01b", "facts"=>"[FILTERED]", "contentTags"=>[], "role"=>"", "addOns"=>[], "usage"=>"", "serviceLevel"=>"", "owner"=>"Default_Organization", "activation_keys"=>"test"}
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on mac 
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on ip 
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on type Nic::Managed
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on name 0cf98b93f01b
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on host_id 5
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on subnet_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on domain_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on attrs {}
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on provider 
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on username 
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on password [redacted]
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on virtual false
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on link true
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on identifier 
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on tag 
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on attached_to 
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on managed true
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on mode balance-rr
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on attached_devices 
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on bond_options 
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on primary true
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on provision true
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on compute_attributes {}
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on execution true
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on ip6 
2023-05-09T16:51:07 [I|aud|0b8301dc] Nic::Managed (5) create event on subnet6_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on name 0cf98b93f01b
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on root_pass 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on architecture_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on operatingsystem_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on ptable_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on medium_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on build false
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on comment 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on disk 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on installed_at 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on model_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on hostgroup_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on owner_id 1
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on owner_type User
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on enabled true
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on puppet_ca_proxy_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on managed false
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on use_image 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on image_file 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on uuid 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on compute_resource_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on puppet_proxy_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on certname 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on image_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on organization_id 1
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on location_id 2
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on otp 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on realm_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on compute_profile_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on provision_method 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on grub_pass 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on pxe_loader 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on initiated_at 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on build_errors 
2023-05-09T16:51:07 [I|aud|0b8301dc] Host::Base (5) create event on creator_id 1
2023-05-09T16:51:07 [I|app|0b8301dc] generating new uuid
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::ContentFacet (4) create event on host_id 5
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::ContentFacet (4) create event on uuid 4ba3205f-ac69-46f4-8ac7-27614873825f
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::ContentFacet (4) create event on kickstart_repository_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::ContentFacet (4) create event on content_source_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::ContentFacet (4) create event on installable_security_errata_count 0
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::ContentFacet (4) create event on installable_enhancement_errata_count 0
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::ContentFacet (4) create event on installable_bugfix_errata_count 0
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::ContentFacet (4) create event on applicable_rpm_count 0
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::ContentFacet (4) create event on upgradable_rpm_count 0
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::ContentFacet (4) create event on applicable_module_stream_count 0
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::ContentFacet (4) create event on upgradable_module_stream_count 0
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::ContentFacet (4) create event on applicable_deb_count 0
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::ContentFacet (4) create event on upgradable_deb_count 0
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::SubscriptionFacet (4) create event on host_id 5
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::SubscriptionFacet (4) create event on uuid 4ba3205f-ac69-46f4-8ac7-27614873825f
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::SubscriptionFacet (4) create event on service_level 
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::SubscriptionFacet (4) create event on release_version 
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::SubscriptionFacet (4) create event on autoheal false
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::SubscriptionFacet (4) create event on registered_at 2023-05-09 16:39:21 UTC
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::SubscriptionFacet (4) create event on registered_through 
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::SubscriptionFacet (4) create event on user_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::SubscriptionFacet (4) create event on hypervisor false
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::SubscriptionFacet (4) create event on hypervisor_host_id 
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::SubscriptionFacet (4) create event on purpose_usage 
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::SubscriptionFacet (4) create event on purpose_role 
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::SubscriptionFacet (4) create event on dmi_uuid 
2023-05-09T16:51:07 [I|aud|0b8301dc] Katello::Host::SubscriptionFacet (4) create event on pool_ids []
2023-05-09T16:51:07 [I|kat|1b74fa07] candlepin event handled success=true subject=compliance.created entity_id=4ba3205f-ac69-46f4-8ac7-27614873825f duration=8.44
2023-05-09T16:51:07 [I|kat|1b74fa07] candlepin event handled success=true subject=system_purpose_compliance.created entity_id=4ba3205f-ac69-46f4-8ac7-27614873825f duration=2.19
2023-05-09T16:51:07 [I|app|0b8301dc] Import facts for '0cf98b93f01b' completed. Added: 110, Updated: 0, Deleted 0 facts
2023-05-09T16:51:08 [I|aud|0b8301dc] Nic::Managed (5) update event on mac , 72:7f:26:13:1a:20
2023-05-09T16:51:08 [I|aud|0b8301dc] Nic::Managed (5) update event on identifier , eth0
2023-05-09T16:51:09 [I|aud|0b8301dc] Host::Base (5) update event on architecture_id , 1
2023-05-09T16:51:09 [I|aud|0b8301dc] Host::Base (5) update event on operatingsystem_id , 2
2023-05-09T16:51:09 [I|aud|0b8301dc] Katello::Host::SubscriptionFacet (4) update event on autoheal false, true
2023-05-09T16:51:09 [I|aud|0b8301dc] Katello::Host::SubscriptionFacet (4) update event on registered_at 2023-05-09 16:39:21 UTC, 2023-05-09 16:51:07 UTC
2023-05-09T16:51:09 [I|aud|0b8301dc] Katello::Host::SubscriptionFacet (4) update event on registered_through , centos8-stream-katello-nightly.guus.example.com
2023-05-09T16:51:09 [I|app|0b8301dc] Completed 200 OK in 2375ms (Views: 1.2ms | ActiveRecord: 252.7ms | Allocations: 259256)
2023-05-09T16:51:09 [I|app|4d67399f] Started GET "/rhsm/status" for 192.168.122.83 at 2023-05-09 16:51:09 +0000
2023-05-09T16:51:09 [I|app|4d67399f] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2023-05-09T16:51:09 [I|app|4d67399f] Completed 200 OK in 32ms (Views: 0.3ms | ActiveRecord: 9.3ms | Allocations: 4517)
2023-05-09T16:51:13 [I|app|8bc5d2ef] Started GET "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f/certificates/serials" for 192.168.122.83 at 2023-05-09 16:51:13 +0000
2023-05-09T16:51:13 [I|app|8bc5d2ef] Processing by Katello::Api::Rhsm::CandlepinProxiesController#serials as JSON
2023-05-09T16:51:13 [I|app|8bc5d2ef]   Parameters: {"id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:13 [I|app|8bc5d2ef] Completed 200 OK in 78ms (Views: 0.2ms | ActiveRecord: 27.9ms | Allocations: 5661)
2023-05-09T16:51:13 [I|app|16afd159] Started GET "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f/certificates?serials=8375639447987900061" for 192.168.122.83 at 2023-05-09 16:51:13 +0000
2023-05-09T16:51:13 [I|app|16afd159] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2023-05-09T16:51:13 [I|app|16afd159]   Parameters: {"serials"=>"8375639447987900061", "id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:13 [I|app|16afd159] Completed 200 OK in 45ms (Views: 0.1ms | ActiveRecord: 9.3ms | Allocations: 4719)
2023-05-09T16:51:13 [I|app|33b04def] Started GET "/rhsm/status" for 192.168.122.83 at 2023-05-09 16:51:13 +0000
2023-05-09T16:51:13 [I|app|33b04def] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2023-05-09T16:51:13 [I|app|33b04def] Completed 200 OK in 28ms (Views: 0.2ms | ActiveRecord: 9.8ms | Allocations: 4541)
2023-05-09T16:51:13 [I|app|1cc2df40] Started GET "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f/accessible_content" for 192.168.122.83 at 2023-05-09 16:51:13 +0000
2023-05-09T16:51:13 [I|app|1cc2df40] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2023-05-09T16:51:13 [I|app|1cc2df40]   Parameters: {"id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:13 [I|app|1cc2df40] Completed 200 OK in 47ms (Views: 0.1ms | ActiveRecord: 17.9ms | Allocations: 4622)
2023-05-09T16:51:13 [I|app|44f35cf3] Started GET "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f/content_overrides" for 192.168.122.83 at 2023-05-09 16:51:13 +0000
2023-05-09T16:51:13 [I|app|44f35cf3] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2023-05-09T16:51:13 [I|app|44f35cf3]   Parameters: {"id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:13 [I|app|44f35cf3] Completed 200 OK in 31ms (Views: 0.2ms | ActiveRecord: 9.2ms | Allocations: 4625)
2023-05-09T16:51:14 [I|app|6a44db20] Started GET "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f/compliance" for 192.168.122.83 at 2023-05-09 16:51:14 +0000
2023-05-09T16:51:14 [I|app|6a44db20] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2023-05-09T16:51:14 [I|app|6a44db20]   Parameters: {"id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:14 [I|app|6a44db20] Completed 200 OK in 41ms (Views: 0.1ms | ActiveRecord: 9.5ms | Allocations: 4631)
2023-05-09T16:51:14 [I|app|943d2565] Started GET "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f/compliance" for 192.168.122.83 at 2023-05-09 16:51:14 +0000
2023-05-09T16:51:14 [I|app|943d2565] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2023-05-09T16:51:14 [I|app|943d2565]   Parameters: {"id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:14 [I|app|943d2565] Completed 200 OK in 33ms (Views: 0.1ms | ActiveRecord: 9.6ms | Allocations: 4637)
2023-05-09T16:51:14 [I|app|cd98175b] Started GET "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f/compliance" for 192.168.122.83 at 2023-05-09 16:51:14 +0000
2023-05-09T16:51:14 [I|app|cd98175b] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2023-05-09T16:51:14 [I|app|cd98175b]   Parameters: {"id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:14 [I|app|cd98175b] Completed 200 OK in 49ms (Views: 0.2ms | ActiveRecord: 17.5ms | Allocations: 4624)
2023-05-09T16:51:14 [I|app|a9ab8838] Started GET "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f/compliance" for 192.168.122.83 at 2023-05-09 16:51:14 +0000
2023-05-09T16:51:14 [I|app|a9ab8838] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2023-05-09T16:51:14 [I|app|a9ab8838]   Parameters: {"id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:14 [I|app|a9ab8838] Completed 200 OK in 33ms (Views: 0.2ms | ActiveRecord: 9.5ms | Allocations: 4649)
2023-05-09T16:51:14 [I|app|3f641e01] Started GET "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f/owner" for 192.168.122.83 at 2023-05-09 16:51:14 +0000
2023-05-09T16:51:14 [I|app|3f641e01] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2023-05-09T16:51:14 [I|app|3f641e01]   Parameters: {"id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:14 [I|app|3f641e01] Completed 200 OK in 40ms (Views: 0.2ms | ActiveRecord: 17.6ms | Allocations: 4627)
2023-05-09T16:51:14 [I|app|b0078eca] Started GET "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f" for 192.168.122.83 at 2023-05-09 16:51:14 +0000
2023-05-09T16:51:14 [I|app|b0078eca] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_show as JSON
2023-05-09T16:51:14 [I|app|b0078eca]   Parameters: {"id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:15 [I|app|b0078eca] Completed 200 OK in 39ms (Views: 0.9ms | ActiveRecord: 9.7ms | Allocations: 7673)
2023-05-09T16:51:15 [I|app|714f0697] Started GET "/rhsm/status" for 192.168.122.83 at 2023-05-09 16:51:15 +0000
2023-05-09T16:51:15 [I|app|714f0697] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2023-05-09T16:51:15 [I|app|714f0697] Completed 200 OK in 33ms (Views: 0.4ms | ActiveRecord: 9.8ms | Allocations: 4529)
2023-05-09T16:51:15 [I|app|f4997891] Started POST "/register" for 192.168.122.83 at 2023-05-09 16:51:15 +0000
2023-05-09T16:51:15 [I|app|f4997891] Processing by Api::V2::RegistrationController#host as */*
2023-05-09T16:51:15 [I|app|f4997891]   Parameters: {"uuid"=>"4ba3205f-ac69-46f4-8ac7-27614873825f", "host"=>{"organization_id"=>"1", "location_id"=>"2"}}
2023-05-09T16:51:15 [I|app|f4997891] Authorized user admin(Admin User)
2023-05-09T16:51:15 [I|app|f4997891] Processed 1 tasks from queue 'Host::Managed Main', completed 1/1
2023-05-09T16:51:15 [I|aud|f4997891] Host::Base (5) update event on build false, true
2023-05-09T16:51:15 [I|aud|f4997891] Host::Base (5) update event on initiated_at , 2023-05-09 16:51:15 UTC
2023-05-09T16:51:15 [W|app|f4997891] Could not find a provider for 0cf98b93f01b. Providers returned {"Katello::ManagedContentMediumProvider"=>["Kickstart repository was not set for host '0cf98b93f01b'", "Content source was not set for host '0cf98b93f01b'"], "MediumProviders::Default"=>["CentOS_Stream 9 medium was not set for host '0cf98b93f01b'", "Invalid medium '' for 'CentOS_Stream 9'"]}
2023-05-09T16:51:15 [W|app|f4997891] Could not find a provider for 0cf98b93f01b. Providers returned {"Katello::ManagedContentMediumProvider"=>["Kickstart repository was not set for host '0cf98b93f01b'", "Content source was not set for host '0cf98b93f01b'"], "MediumProviders::Default"=>["CentOS_Stream 9 medium was not set for host '0cf98b93f01b'", "Invalid medium '' for 'CentOS_Stream 9'"]}
2023-05-09T16:51:15 [I|app|f4997891]   Rendered text template (Duration: 0.0ms | Allocations: 1)
2023-05-09T16:51:15 [I|app|f4997891] Completed 200 OK in 145ms (Views: 0.3ms | ActiveRecord: 57.1ms | Allocations: 68559)
2023-05-09T16:51:15 [I|app|89689fc7] Started GET "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f/certificates/serials" for 192.168.122.83 at 2023-05-09 16:51:15 +0000
2023-05-09T16:51:15 [I|app|89689fc7] Processing by Katello::Api::Rhsm::CandlepinProxiesController#serials as JSON
2023-05-09T16:51:15 [I|app|89689fc7]   Parameters: {"id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:15 [I|app|89689fc7] Completed 200 OK in 43ms (Views: 0.2ms | ActiveRecord: 18.5ms | Allocations: 5677)
2023-05-09T16:51:15 [I|app|03ee4c30] Started GET "/rhsm/status" for 192.168.122.83 at 2023-05-09 16:51:15 +0000
2023-05-09T16:51:15 [I|app|03ee4c30] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2023-05-09T16:51:15 [I|app|03ee4c30] Completed 200 OK in 31ms (Views: 0.4ms | ActiveRecord: 9.0ms | Allocations: 4532)
2023-05-09T16:51:15 [I|app|4389aa89] Started GET "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f/accessible_content" for 192.168.122.83 at 2023-05-09 16:51:15 +0000
2023-05-09T16:51:15 [I|app|4389aa89] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2023-05-09T16:51:15 [I|app|4389aa89]   Parameters: {"id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:15 [I|app|4389aa89] Completed 304 Not Modified in 51ms (Views: 0.1ms | ActiveRecord: 17.5ms | Allocations: 4544)
2023-05-09T16:51:15 [I|app|658d2e06] Started GET "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f/compliance" for 192.168.122.83 at 2023-05-09 16:51:15 +0000
2023-05-09T16:51:15 [I|app|658d2e06] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2023-05-09T16:51:15 [I|app|658d2e06]   Parameters: {"id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:15 [I|app|658d2e06] Completed 200 OK in 38ms (Views: 0.2ms | ActiveRecord: 9.7ms | Allocations: 4626)
2023-05-09T16:51:16 [I|app|7df44b64] Started GET "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f/owner" for 192.168.122.83 at 2023-05-09 16:51:16 +0000
2023-05-09T16:51:16 [I|app|7df44b64] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2023-05-09T16:51:16 [I|app|7df44b64]   Parameters: {"id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:16 [I|app|7df44b64] Completed 200 OK in 39ms (Views: 0.1ms | ActiveRecord: 9.9ms | Allocations: 4633)
2023-05-09T16:51:16 [I|app|05c64389] Started GET "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f/compliance" for 192.168.122.83 at 2023-05-09 16:51:16 +0000
2023-05-09T16:51:16 [I|app|05c64389] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2023-05-09T16:51:16 [I|app|05c64389]   Parameters: {"id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:16 [I|app|05c64389] Completed 200 OK in 40ms (Views: 0.1ms | ActiveRecord: 17.6ms | Allocations: 4626)
2023-05-09T16:51:16 [I|app|4a47bf2d] Started GET "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f/compliance" for 192.168.122.83 at 2023-05-09 16:51:16 +0000
2023-05-09T16:51:16 [I|app|4a47bf2d] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2023-05-09T16:51:16 [I|app|4a47bf2d]   Parameters: {"id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:16 [I|app|4a47bf2d] Completed 200 OK in 47ms (Views: 0.2ms | ActiveRecord: 17.9ms | Allocations: 4633)
2023-05-09T16:51:16 [I|app|4d2ead18] Started GET "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f/compliance" for 192.168.122.83 at 2023-05-09 16:51:16 +0000
2023-05-09T16:51:16 [I|app|4d2ead18] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2023-05-09T16:51:16 [I|app|4d2ead18]   Parameters: {"id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:16 [I|app|4d2ead18] Completed 200 OK in 38ms (Views: 0.1ms | ActiveRecord: 9.8ms | Allocations: 4627)
2023-05-09T16:51:16 [I|app|050d9e5b] Started GET "/unattended/built?token=18aa6966-b4ad-455a-a5e8-828f52387a03" for 192.168.122.83 at 2023-05-09 16:51:16 +0000
2023-05-09T16:51:16 [I|app|050d9e5b] Processing by UnattendedController#built as TEXT
2023-05-09T16:51:16 [I|app|050d9e5b]   Parameters: {"token"=>"18aa6966-b4ad-455a-a5e8-828f52387a03"}
2023-05-09T16:51:16 [I|app|050d9e5b] unattended: 0cf98b93f01b is built!
2023-05-09T16:51:16 [I|app|050d9e5b] Processed 1 tasks from queue 'Host::Managed Main', completed 1/1
2023-05-09T16:51:16 [I|aud|050d9e5b] Host::Base (5) update event on build true, false
2023-05-09T16:51:16 [I|aud|050d9e5b] Host::Base (5) update event on installed_at , 2023-05-09 16:51:16 UTC
2023-05-09T16:51:16 [I|app|050d9e5b] Completed 201 Created in 99ms (ActiveRecord: 48.1ms | Allocations: 25077)
2023-05-09T16:51:20 [I|app|97292076] Started PUT "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f" for 192.168.122.83 at 2023-05-09 16:51:20 +0000
2023-05-09T16:51:20 [I|app|97292076] Processing by Katello::Api::Rhsm::CandlepinProxiesController#facts as JSON
2023-05-09T16:51:20 [I|app|97292076]   Parameters: {"facts"=>"[FILTERED]", "id"=>"4ba3205f-ac69-46f4-8ac7-27614873825f"}
2023-05-09T16:51:21 [I|app|97292076] Import facts for '0cf98b93f01b' completed. Added: 110, Updated: 0, Deleted 0 facts
2023-05-09T16:51:21 [I|app|97292076] Completed 200 OK in 865ms (Views: 0.2ms | ActiveRecord: 120.5ms | Allocations: 140673)

The slowest requests are:

2023-05-09T16:51:01 [I|app|4022fa2f] Started GET "/register?activation_keys=test" for 192.168.122.83 at 2023-05-09 16:51:01 +0000
2023-05-09T16:51:01 [I|app|4022fa2f] Completed 200 OK in 99ms (Views: 0.3ms | ActiveRecord: 50.1ms | Allocations: 45212)
2023-05-09T16:51:06 [I|app|0b8301dc] Started POST "/rhsm/consumers?owner=Default_Organization&activation_keys=test" for 192.168.122.83 at 2023-05-09 16:51:06 +0000
2023-05-09T16:51:09 [I|app|0b8301dc] Completed 200 OK in 2375ms (Views: 1.2ms | ActiveRecord: 252.7ms | Allocations: 259256)
2023-05-09T16:51:15 [I|app|f4997891] Started POST "/register" for 192.168.122.83 at 2023-05-09 16:51:15 +0000
2023-05-09T16:51:15 [I|app|f4997891] Completed 200 OK in 145ms (Views: 0.3ms | ActiveRecord: 57.1ms | Allocations: 68559)
2023-05-09T16:51:16 [I|app|050d9e5b] Started GET "/unattended/built?token=18aa6966-b4ad-455a-a5e8-828f52387a03" for 192.168.122.83 at 2023-05-09 16:51:16 +0000
2023-05-09T16:51:16 [I|app|050d9e5b] Completed 201 Created in 99ms (ActiveRecord: 48.1ms | Allocations: 25077)
2023-05-09T16:51:20 [I|app|97292076] Started PUT "/rhsm/consumers/4ba3205f-ac69-46f4-8ac7-27614873825f" for 192.168.122.83 at 2023-05-09 16:51:20 +0000
2023-05-09T16:51:21 [I|app|97292076] Completed 200 OK in 865ms (Views: 0.2ms | ActiveRecord: 120.5ms | Allocations: 140673)

It would be interesting to see what happens exactly, but one thing to note is that I see 4 audit logs for each registration:

One to create the host
One to set the architecture and OS
One to set Build to true + Initiated at
One to set Build to false + Installed at

So perhaps the number of DB updates can be reduced by more efficient ordering. It also looked like fact uploads took a long time, which is known to be slow.

It got more interesting when I started to run things in parallel. With 20 concurrent jobs I didn’t see errors, but with 30 I did. This appeared to coincide with the moment when a Puma worker built up a queue (so all workers were busy), as monitored via watch foreman-puma-status.

For now I’m going to let this rest a bit again and focus on release work, but perhaps it’s an inspiration for others.

ehelms · May 10, 2023, 1:43pm

A quick question, did your setup have Puma 5 or the recent update to Puma 6?

ekohl · May 10, 2023, 1:58pm

I didn’t check, but I’m pretty sure this was with Puma 6. We have seen that performs better, so could also explain a lower error rate.

Dirk · May 10, 2023, 2:43pm

This makes me wonder and think if something gets wrong could it happen with some error in the third step that the fourth will not take place, so a system ends in build mode after registration and potentially gets reinstalled? This would match the error my colleague @aghannam showed me and as it is a Satellite installation on this customer should have reported to Red Hat support.

ekohl · May 10, 2023, 3:08pm

Those are valid points. I even wondered if it should register a managed host by default, or make it unmanaged by default.

Checking about the build mode is interesting: it can also triggers TFTP and DHCP entry writes. While it wasn’t the focus of my initial tests, these are the things you find when you start playing with them.

Dirk · May 11, 2023, 7:24am

In the mentioned environment is also the combination of VMware as Compute Resource and Bootdisk as Installation method used, so also the bootdisk seems to be created and uploaded in this case. If someone is going to investigate further, I hope my colleague can add more details as he has access to the environment.

aghannam · May 11, 2023, 11:42am

Hi everybody,

thanks @Dirk, for tagging me here.

As Dirk mentioned, we are provisioning hosts using VMware and kickstart templates.

We are using global registration template to register hosts to foreman/satellite. We have two satellites 6.10.7 = foreman 2.5 and 6.11.5.2 = foreman 3.1

There is two different behavior when we register a host to its management satellite. That mean the host is already registered and managed from this satellite, but we force the registration.

On foreman 3.1/ satellite 6.11.5.2:

When we re-register a host using curl command which is generated through global registration template, the build parameter will be changed from false to true. We can see this change per API calls before and after registration start. So the host will be rebuilt during registration.
Is this wanted? When yes why? What is the goal to rebuild a host while registration? When this not wanted and this is a strange behavior, then I can supply you with more information about this case.

On foreman 2.5/ satellite 6.10.7:
We can re-register a host too many times and build will not take a place. The build parameter still always false.

To figure out if the templates on foreman 3.1 cause this host building issue, we used exactly the same Linux host_init_config default and Global Registration templates from foreman 2.5 on foreman 3.1, and the host still goes to build mode during registration.

ekohl · May 15, 2023, 10:59am

@evgeni created Bug #36393: global registration should not create hosts as "managed" or "to be built" - Foreman for this.