Salt not removing key when provisioning server

Support
, , ,
1

Problem:
Whenever I build a server, salt key is not being deleted, so there are 2 keys, the old one, and a new denied key for the new build.
This was working fine on Foreman 2.5 + Katello 3.1

proxy.log says it deleted the key, but the hostname still shows up in salt-key -L, and after the server is provisioned, the hostname shows up twice.
Expected outcome:
Salt-master to delete salt-key when the server is built.

Foreman and Proxy versions:
Foreman 3.2
Katello 4.4

Foreman and Proxy plugin versions:
rubygem-smart_proxy_salt-4.0.0-1.fm3_2.el8.noarch
rubygem-foreman_salt-14.1.0-1.fm3_2.el8.noarch

Distribution and version:
Rocky Linux 8.5

Other relevant data:
proxy.log

2022-04-01T14:26:09 85c8e396 [I] Started GET /v2/features 
2022-04-01T14:26:09 85c8e396 [I] Finished GET /v2/features with 200 (191.73 ms)
2022-04-01T14:26:10 9cb7f64c [I] Started POST /tftp/PXELinux/00:50:56:96:c9:1a 
2022-04-01T14:26:10 9cb7f64c [I] Finished POST /tftp/PXELinux/00:50:56:96:c9:1a with 200 (2.13 ms)
2022-04-01T14:26:10 9cb7f64c [I] Started POST /tftp/PXEGrub2/00:50:56:96:c9:1a 
2022-04-01T14:26:10 9cb7f64c [I] Finished POST /tftp/PXEGrub2/00:50:56:96:c9:1a with 200 (6.83 ms)
2022-04-01T14:26:10 9cb7f64c [I] Started POST /tftp/PXEGrub/00:50:56:96:c9:1a 
2022-04-01T14:26:10 9cb7f64c [I] Finished POST /tftp/PXEGrub/00:50:56:96:c9:1a with 200 (8.6 ms)
2022-04-01T14:26:11 9cb7f64c [I] Started POST /tftp/iPXE/00:50:56:96:c9:1a 
2022-04-01T14:26:11 9cb7f64c [I] Finished POST /tftp/iPXE/00:50:56:96:c9:1a with 200 (0.89 ms)
2022-04-01T14:26:11 9cb7f64c [I] Started POST /tftp/fetch_boot_file 
2022-04-01T14:26:11 9cb7f64c [I] Finished POST /tftp/fetch_boot_file with 200 (2.58 ms)
2022-04-01T14:26:11 9cb7f64c [I] [444873] Started task /usr/bin/curl\ --silent\ --show-error\ --connect-timeout\ 10\ --retry\ 3\ --retry-delay\ 10\ --max-time\ 3600\ --remote-time\ --time-cond\ /var/lib/tftpboot/boot/rocky-linux-8-mMP1dhkpycZU-vmlinuz\ --write-out\ Task\ done,\ result:\ \%\{http_code\},\ size\ downloaded:\ \%\{size_download\}b,\ speed:\ \%\{speed_download\}b/s,\ time:\ \%\{time_total\}ms\ --output\ /var/lib/tftpboot/boot/rocky-linux-8-mMP1dhkpycZU-vmlinuz\ --location\ http://foreman/pulp/.../vmlinuz
2022-04-01T14:26:11 9cb7f64c [I] Started POST /tftp/fetch_boot_file 
2022-04-01T14:26:11 9cb7f64c [I] Finished POST /tftp/fetch_boot_file with 200 (8.43 ms)
2022-04-01T14:26:11 9cb7f64c [I] [444878] Started task /usr/bin/curl\ --silent\ --show-error\ --connect-timeout\ 10\ --retry\ 3\ --retry-delay\ 10\ --max-time\ 3600\ --remote-time\ --time-cond\ /var/lib/tftpboot/boot/rocky-linux-8-mMP1dhkpycZU-initrd.img\ --write-out\ Task\ done,\ result:\ \%\{http_code\},\ size\ downloaded:\ \%\{size_download\}b,\ speed:\ \%\{speed_download\}b/s,\ time:\ \%\{time_total\}ms\ --output\ /var/lib/tftpboot/boot/rocky-linux-8-mMP1dhkpycZU-initrd.img\ --location\ http://foreman/pulp/.../initrd.img
2022-04-01T14:26:11 9cb7f64c [I] Started DELETE /salt/autosign_key/b6444b6c5850044e68a6 
2022-04-01T14:26:11 9cb7f64c [I] Removed an entry from '/var/lib/foreman-proxy/salt/grains/autosign_key' successfully.
2022-04-01T14:26:11 9cb7f64c [I] Finished DELETE /salt/autosign_key/b6444b6c5850044e68a6 with 200 (1.76 ms)
2022-04-01T14:26:11 9cb7f64c [I] Started POST /salt/autosign_key/ecb418d33c7bed697f2d 
2022-04-01T14:26:11 9cb7f64c [I] Added an entry to '/var/lib/foreman-proxy/salt/grains/autosign_key' successfully.
2022-04-01T14:26:11 9cb7f64c [I] Finished POST /salt/autosign_key/ecb418d33c7bed697f2d with 200 (0.54 ms)
2

Hey @vtpo2021, thanks for your post.
When the salt-minion sends the first authentication request to the salt-master, the corresponding Smart Proxy initiates a request to Foreman which should delete the key from the autosign_key file.
It seems like the salt-minion authentication was identified successfully and Smart Proxy sends the delete request as well. Can you also provide the corresponding production.log? Maybe, there is some more information about the request and why the entry is not delete from autosign_key.

3

Here is the Production.log.
I have replace the client name to my_server on all these logs.

2022-04-04T09:06:42 [I|app|2b02b223] Started GET "/notification_recipients" for 10.116.1.26 at 2022-04-04 09:06:42 -0700
2022-04-04T09:06:42 [I|app|2b02b223] Processing by NotificationRecipientsController#index as JSON
2022-04-04T09:06:42 [I|app|2b02b223] Completed 200 OK in 6ms (Views: 0.1ms | ActiveRecord: 0.9ms | Allocations: 2126)
2022-04-04T09:06:43 [I|app|29d36b98] Started GET "/hosts/my_server/review_before_build" for 10.116.1.26 at 2022-04-04 09:06:43 -0700
2022-04-04T09:06:43 [I|app|29d36b98] Processing by HostsController#review_before_build as JSON
2022-04-04T09:06:43 [I|app|29d36b98]   Parameters: {"id"=>"my_server"}
2022-04-04T09:06:44 [I|app|29d36b98] Rendering Kickstart default PXELinux
2022-04-04T09:06:44 [I|app|29d36b98] Rendering Kickstart default PXEGrub
2022-04-04T09:06:44 [I|app|29d36b98] Rendering Kickstart default PXEGrub2
2022-04-04T09:06:44 [I|app|29d36b98] Rendering Kickstart default iPXE
2022-04-04T09:06:45 [I|app|29d36b98] Rendering Kickstart default
2022-04-04T09:06:47 [I|app|29d36b98] Derive Salt Grains from host_params and autosign_key
2022-04-04T09:06:47 [I|app|29d36b98] Rendering Kickstart default finish
2022-04-04T09:06:52 [I|app|29d36b98] Derive Salt Grains from host_params and autosign_key
2022-04-04T09:06:52 [I|app|29d36b98] Rendering Kickstart default user data
2022-04-04T09:06:52 [I|app|29d36b98] Derive Salt Grains from host_params and autosign_key
2022-04-04T09:06:52 [I|app|29d36b98] Rendering Linux host_init_config default
2022-04-04T09:06:52 [I|app|ee5f73ee] Started GET "/notification_recipients" for 10.116.1.26 at 2022-04-04 09:06:52 -0700
2022-04-04T09:06:52 [I|app|ee5f73ee] Processing by NotificationRecipientsController#index as JSON
2022-04-04T09:06:53 [I|app|ee5f73ee] Completed 200 OK in 30ms (Views: 0.1ms | ActiveRecord: 1.7ms | Allocations: 2126)
2022-04-04T09:06:53 [I|app|29d36b98] Completed 200 OK in 9196ms (Views: 0.1ms | ActiveRecord: 85.8ms | Allocations: 1927964)
2022-04-04T09:06:54 [I|app|2143b28e] Started PUT "/hosts/my_server/setBuild" for 10.116.1.26 at 2022-04-04 09:06:54 -0700
2022-04-04T09:06:54 [I|app|2143b28e] Processing by HostsController#setBuild as JSON
2022-04-04T09:06:54 [I|app|2143b28e]   Parameters: {"id"=>"my_server", "host"=>{}}
2022-04-04T09:06:55 [I|app|2143b28e] Deploying TFTP PXELinux configuration for my_server
2022-04-04T09:06:55 [I|app|2143b28e] Deploying TFTP PXEGrub2 configuration for my_server
2022-04-04T09:06:55 [I|app|2143b28e] Deploying TFTP PXEGrub configuration for my_server
2022-04-04T09:06:55 [I|app|2143b28e] Deploying TFTP iPXE configuration for my_server
2022-04-04T09:06:55 [I|app|2143b28e] Fetching required TFTP boot files for my_server
2022-04-04T09:06:55 [I|app|2143b28e] Processed 6 tasks from queue 'Host::Managed Main', completed 6/6
2022-04-04T09:06:55 [I|aud|2143b28e] Host::Base (2) update event on build false, true
2022-04-04T09:06:55 [I|aud|2143b28e] Host::Base (2) update event on initiated_at 2022-04-04 08:52:28 -0700, 2022-04-04 09:06:54 -0700
2022-04-04T09:06:55 [I|app|2143b28e] Remove salt autosign key for host my_server
2022-04-04T09:06:55 [I|app|2143b28e] Create salt autosign key for host my_server
2022-04-04T09:06:56 [I|aud|2143b28e] Host::Base (2) update event on salt_autosign_key f9785d3ae78d684ac6cb, 8d16bcf8165b1372cbdf
2022-04-04T09:06:56 [I|app|2143b28e] Completed 200 OK in 1163ms (Views: 0.1ms | ActiveRecord: 82.2ms | Allocations: 536542)
2022-04-04T09:06:56 [I|app|22a9007e] Started GET "/api/hosts/my_serveru" for 10.116.1.26 at 2022-04-04 09:06:56 -0700
2022-04-04T09:06:56 [I|app|22a9007e] Processing by Api::V2::HostsController#show as JSON
2022-04-04T09:06:56 [I|app|22a9007e]   Parameters: {"apiv"=>"v2", "id"=>"my_server"}
2022-04-04T09:06:56 [I|app|22a9007e]   Rendering api/v2/hosts/show.json.rabl
2022-04-04T09:06:56 [I|app|22a9007e]   Rendered api/v2/hosts/show.json.rabl (Duration: 77.9ms | Allocations: 38865)
2022-04-04T09:06:56 [I|app|22a9007e] Completed 200 OK in 94ms (Views: 63.4ms | ActiveRecord: 18.2ms | Allocations: 43149)
2022-04-04T09:07:39 [I|app|58e9be73] Started GET "/unattended/provision?token=a44b6f7e-1339-4214-a63d-d89128c0db67" for 10.18.0.60 at 2022-04-04 09:07:39 -0700
2022-04-04T09:07:39 [I|app|58e9be73] Processing by UnattendedController#host_template as TEXT
2022-04-04T09:07:39 [I|app|58e9be73]   Parameters: {"token"=>"a44b6f7e-1339-4214-a63d-d89128c0db67", "kind"=>"provision"}
2022-04-04T09:07:40 [I|app|58e9be73] Derive Salt Grains from host_params and autosign_key
2022-04-04T09:07:40 [I|app|58e9be73]   Rendering text template
2022-04-04T09:07:40 [I|app|58e9be73]   Rendered text template (Duration: 0.0ms | Allocations: 1)
2022-04-04T09:07:40 [I|app|58e9be73] Completed 200 OK in 1340ms (Views: 0.5ms | ActiveRecord: 17.6ms | Allocations: 634766)
2022-04-04T09:11:05 [I|app|ee120597] Started GET "/rhsm/consumers/64334ce7-a1d8-4250-a0eb-bd61e53c2d09/certificates/serials" for 10.18.0.63 at 2022-04-04 09:11:05 -0700
2022-04-04T09:11:05 [I|app|ee120597] Processing by Katello::Api::Rhsm::CandlepinProxiesController#serials as JSON
2022-04-04T09:11:05 [I|app|ee120597]   Parameters: {"id"=>"64334ce7-a1d8-4250-a0eb-bd61e53c2d09"}
2022-04-04T09:11:05 [I|app|ee120597] Completed 200 OK in 272ms (Views: 0.4ms | ActiveRecord: 4.2ms | Allocations: 4080)
2022-04-04T09:11:05 [I|app|6d609a85] Started GET "/rhsm/status" for 10.18.0.63 at 2022-04-04 09:11:05 -0700
2022-04-04T09:11:05 [I|app|6d609a85] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2022-04-04T09:11:05 [I|app|6d609a85] Completed 200 OK in 42ms (Views: 0.8ms | ActiveRecord: 2.5ms | Allocations: 2691)
2022-04-04T09:11:05 [I|app|ab15417a] Started GET "/rhsm/consumers/64334ce7-a1d8-4250-a0eb-bd61e53c2d09/content_overrides" for 10.18.0.63 at 2022-04-04 09:11:05 -0700
2022-04-04T09:11:05 [I|app|ab15417a] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2022-04-04T09:11:05 [I|app|ab15417a]   Parameters: {"id"=>"64334ce7-a1d8-4250-a0eb-bd61e53c2d09"}
2022-04-04T09:11:05 [I|app|ab15417a] Completed 200 OK in 37ms (Views: 0.2ms | ActiveRecord: 2.8ms | Allocations: 3185)
2022-04-04T09:11:35 [I|app|15331493] Started GET "/rhsm/consumers/1de0cfdb-6dc0-408f-9fac-7f001a0d1472/certificates/serials" for 10.14.1.42 at 2022-04-04 09:11:35 -0700
2022-04-04T09:11:35 [I|app|15331493] Processing by Katello::Api::Rhsm::CandlepinProxiesController#serials as JSON
2022-04-04T09:11:35 [I|app|15331493]   Parameters: {"id"=>"1de0cfdb-6dc0-408f-9fac-7f001a0d1472"}
2022-04-04T09:11:35 [I|app|15331493] Completed 200 OK in 95ms (Views: 0.3ms | ActiveRecord: 3.8ms | Allocations: 4076)
2022-04-04T09:11:35 [I|app|1c610809] Started GET "/rhsm/status" for 10.14.1.42 at 2022-04-04 09:11:35 -0700
2022-04-04T09:11:35 [I|app|1c610809] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2022-04-04T09:11:35 [I|app|1c610809] Completed 200 OK in 45ms (Views: 0.6ms | ActiveRecord: 3.1ms | Allocations: 2685)
2022-04-04T09:11:35 [I|app|67ba2e00] Started GET "/rhsm/consumers/1de0cfdb-6dc0-408f-9fac-7f001a0d1472/content_overrides" for 10.14.1.42 at 2022-04-04 09:11:35 -0700
2022-04-04T09:11:35 [I|app|67ba2e00] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2022-04-04T09:11:35 [I|app|67ba2e00]   Parameters: {"id"=>"1de0cfdb-6dc0-408f-9fac-7f001a0d1472"}
2022-04-04T09:11:35 [I|app|67ba2e00] Completed 200 OK in 24ms (Views: 0.1ms | ActiveRecord: 1.7ms | Allocations: 3209)
2022-04-04T09:13:13 [I|app|67983f91] Started POST "/rhsm/consumers?owner=xxx&activation_keys=Rocky%20Linux%208" for 10.18.0.60 at 2022-04-04 09:13:13 -0700
2022-04-04T09:13:13 [I|app|67983f91] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_activate as JSON
2022-04-04T09:13:13 [I|app|67983f91]   Parameters: {"type"=>"system", "name"=>"my_server", "facts"=>"[FILTERED]", "contentTags"=>[], "role"=>"", "addOns"=>[], "usage"=>"", "serviceLevel"=>"", "owner"=>"xxx", "activation_keys"=>"Rocky Linux 8"}
2022-04-04T09:13:14 [I|aud|41a56e07] Katello::Pool (3) update event on host_ids , 12, 4, 6, 9, 11, 10, 29, 5, 7, 13, 8
2022-04-04T09:13:14 [I|kat|41a56e07] candlepin event handled success=true subject=entitlement.deleted entity_id=4e3633f0efe4401aad481fb417c08140 duration=48.75
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (43) destroy event on host_id 2
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (43) destroy event on uuid fccf2e01-1cc9-467c-b676-a7cb28bedc42
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (43) destroy event on service_level
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (43) destroy event on release_version
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (43) destroy event on autoheal true
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (43) destroy event on registered_at 2022-04-04 15:59:30 UTC
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (43) destroy event on registered_through foreman
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (43) destroy event on user_id
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (43) destroy event on hypervisor false
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (43) destroy event on hypervisor_host_id
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (43) destroy event on purpose_usage
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (43) destroy event on purpose_role
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (43) destroy event on dmi_uuid BC4A1642-63A5-0F58-CDD4-DFC5D149769F
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (43) destroy event on pool_ids [4, 5, 2]
2022-04-04T09:13:14 [I|aud|41a56e07] Katello::Pool (5) update event on host_ids , 12, 4, 6, 9, 11, 10, 29, 5, 7, 13, 8
2022-04-04T09:13:14 [I|kat|41a56e07] candlepin event handled success=true subject=entitlement.deleted entity_id=55574b61c5df4635990a49d32d492722 duration=36.19
2022-04-04T09:13:14 [I|kat|41a56e07] candlepin event handled success=true subject=entitlement.deleted entity_id=65a9f6974ac3465ca19f2f668c171454 duration=2.09
2022-04-04T09:13:14 [I|kat|41a56e07] candlepin event handled success=true subject=entitlement.deleted entity_id=85d87ea013b548899910c2c2819f2f61 duration=2.15
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (1) update event on uuid fccf2e01-1cc9-467c-b676-a7cb28bedc42,
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (1) update event on uuid , 30629d57-079e-4271-99a5-e2b20936c0ef
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (44) create event on host_id 2
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (44) create event on uuid 30629d57-079e-4271-99a5-e2b20936c0ef
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (44) create event on service_level
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (44) create event on release_version
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (44) create event on autoheal false
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (44) create event on registered_at 2022-03-28 22:40:08 UTC
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (44) create event on registered_through
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (44) create event on user_id
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (44) create event on hypervisor false
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (44) create event on hypervisor_host_id
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (44) create event on purpose_usage
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (44) create event on purpose_role
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (44) create event on dmi_uuid BC4A1642-63A5-0F58-CDD4-DFC5D149769F
2022-04-04T09:13:14 [I|aud|67983f91] Host::Base (44) create event on pool_ids []
2022-04-04T09:13:15 [I|app|41a56e07] katello event handled success=true type=import_pool object_id=3 expired=false rescheduled=false duration=45.03
2022-04-04T09:13:15 [I|app|41a56e07] katello event handled success=true type=import_pool object_id=5 expired=false rescheduled=false duration=39.07
2022-04-04T09:13:15 [I|app|41a56e07] katello event handled success=true type=import_pool object_id=2 expired=false rescheduled=false duration=36.94
2022-04-04T09:13:15 [I|app|41a56e07] katello event handled success=true type=import_pool object_id=4 expired=false rescheduled=false duration=38.54
2022-04-04T09:13:16 [I|kat|41a56e07] candlepin event handled success=true subject=compliance.created entity_id=30629d57-079e-4271-99a5-e2b20936c0ef duration=21.38
2022-04-04T09:13:16 [I|kat|41a56e07] candlepin event handled success=true subject=system_purpose_compliance.created entity_id=30629d57-079e-4271-99a5-e2b20936c0ef duration=26.84
2022-04-04T09:13:16 [I|kat|41a56e07] candlepin event handled success=true subject=compliance.created entity_id=30629d57-079e-4271-99a5-e2b20936c0ef duration=12.07
2022-04-04T09:13:16 [I|kat|41a56e07] candlepin event handled success=true subject=system_purpose_compliance.created entity_id=30629d57-079e-4271-99a5-e2b20936c0ef duration=22.33
2022-04-04T09:13:16 [I|aud|41a56e07] Katello::Pool (5) update event on host_ids , 12, 4, 6, 9, 11, 10, 2, 29, 5, 7, 13, 8
2022-04-04T09:13:16 [I|kat|41a56e07] candlepin event handled success=true subject=entitlement.created entity_id=6867a1cec9c44764adc37929ed5688cc duration=51.19
2022-04-04T09:13:16 [I|aud|41a56e07] Katello::Pool (2) update event on host_ids , 12, 4, 6, 9, 11, 10, 2, 29, 5, 7, 13, 8
2022-04-04T09:13:16 [I|kat|41a56e07] candlepin event handled success=true subject=entitlement.created entity_id=fdcc77075aca496e9d8f3a595e10d45a duration=53.02
2022-04-04T09:13:16 [I|aud|67983f91] Host::Base (44) update event on autoheal false, true
2022-04-04T09:13:16 [I|aud|67983f91] Host::Base (44) update event on registered_at 2022-03-28 22:40:08 UTC, 2022-04-04 16:13:14 UTC
2022-04-04T09:13:16 [I|aud|41a56e07] Katello::Pool (3) update event on host_ids , 12, 4, 6, 9, 11, 10, 2, 29, 5, 7, 13, 8
2022-04-04T09:13:16 [I|kat|41a56e07] candlepin event handled success=true subject=entitlement.created entity_id=a9df821635c54e7dad97e3ccb66b4e0f duration=30.79
2022-04-04T09:13:16 [I|aud|41a56e07] Katello::Pool (4) update event on host_ids , 12, 4, 6, 9, 11, 10, 29, 2, 5, 7, 13, 8
2022-04-04T09:13:16 [I|kat|41a56e07] candlepin event handled success=true subject=entitlement.created entity_id=0c5d974fa94741f2ad05997121306b20 duration=21.21
2022-04-04T09:13:16 [I|aud|67983f91] Host::Base (44) update event on registered_through , foreman
2022-04-04T09:13:16 [I|kat|41a56e07] candlepin event handled success=true subject=compliance.created entity_id=30629d57-079e-4271-99a5-e2b20936c0ef duration=17.63
2022-04-04T09:13:16 [I|kat|41a56e07] candlepin event handled success=true subject=system_purpose_compliance.created entity_id=30629d57-079e-4271-99a5-e2b20936c0ef duration=20.18
2022-04-04T09:13:16 [I|app|67983f91] Completed 200 OK in 3141ms (Views: 4.1ms | ActiveRecord: 137.0ms | Allocations: 184231)
2022-04-04T09:13:16 [I|app|511c24a8] Started GET "/rhsm/" for 10.18.0.60 at 2022-04-04 09:13:16 -0700
2022-04-04T09:13:16 [I|app|511c24a8] Processing by Katello::Api::V2::RootController#rhsm_resource_list as JSON
2022-04-04T09:13:16 [I|app|511c24a8]   Parameters: {"root"=>{}}
2022-04-04T09:13:16 [I|app|511c24a8] Completed 200 OK in 4ms (Views: 0.7ms | ActiveRecord: 1.4ms | Allocations: 1818)
2022-04-04T09:13:16 [I|app|4d2a44b7] Started GET "/rhsm/status" for 10.18.0.60 at 2022-04-04 09:13:16 -0700
2022-04-04T09:13:16 [I|app|4d2a44b7] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2022-04-04T09:13:16 [I|app|4d2a44b7] Completed 200 OK in 38ms (Views: 0.3ms | ActiveRecord: 2.5ms | Allocations: 2673)
2022-04-04T09:13:17 [I|app|5d66c1a8] Started GET "/rhsm/consumers/30629d57-079e-4271-99a5-e2b20936c0ef/certificates/serials" for 10.18.0.60 at 2022-04-04 09:13:17 -0700
2022-04-04T09:13:17 [I|app|5d66c1a8] Processing by Katello::Api::Rhsm::CandlepinProxiesController#serials as JSON
2022-04-04T09:13:17 [I|app|5d66c1a8]   Parameters: {"id"=>"30629d57-079e-4271-99a5-e2b20936c0ef"}
2022-04-04T09:13:17 [I|app|5d66c1a8] Completed 200 OK in 39ms (Views: 0.3ms | ActiveRecord: 2.6ms | Allocations: 4058)
2022-04-04T09:13:17 [I|app|b388980b] Started GET "/rhsm/consumers/30629d57-079e-4271-99a5-e2b20936c0ef/certificates?serials=3070274408357977323,2708306087946241530,3312959873531159783,5073190861404184462" for 10.18.0.60 at 2022-04-04 09:13:17 -0700
2022-04-04T09:13:17 [I|app|b388980b] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2022-04-04T09:13:17 [I|app|b388980b]   Parameters: {"serials"=>"3070274408357977323,2708306087946241530,3312959873531159783,5073190861404184462", "id"=>"30629d57-079e-4271-99a5-e2b20936c0ef"}
2022-04-04T09:13:17 [I|app|b388980b] Completed 200 OK in 107ms (Views: 0.2ms | ActiveRecord: 28.8ms | Allocations: 6495)
2022-04-04T09:13:17 [I|app|918fd2dc] Started GET "/rhsm/status" for 10.18.0.60 at 2022-04-04 09:13:17 -0700
2022-04-04T09:13:17 [I|app|918fd2dc] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2022-04-04T09:13:17 [I|app|918fd2dc] Completed 200 OK in 26ms (Views: 0.6ms | ActiveRecord: 2.1ms | Allocations: 2680)
2022-04-04T09:13:17 [I|app|9e36f3f5] Started GET "/rhsm/" for 10.18.0.60 at 2022-04-04 09:13:17 -0700
2022-04-04T09:13:17 [I|app|9e36f3f5] Processing by Katello::Api::V2::RootController#rhsm_resource_list as JSON
2022-04-04T09:13:17 [I|app|9e36f3f5]   Parameters: {"root"=>{}}
2022-04-04T09:13:17 [I|app|9e36f3f5] Completed 200 OK in 6ms (Views: 0.8ms | ActiveRecord: 1.9ms | Allocations: 1818)
2022-04-04T09:13:17 [I|app|7adb15de] Started GET "/rhsm/consumers/30629d57-079e-4271-99a5-e2b20936c0ef/content_overrides" for 10.18.0.60 at 2022-04-04 09:13:17 -0700
2022-04-04T09:13:17 [I|app|7adb15de] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2022-04-04T09:13:17 [I|app|7adb15de]   Parameters: {"id"=>"30629d57-079e-4271-99a5-e2b20936c0ef"}
2022-04-04T09:13:17 [I|app|7adb15de] Completed 200 OK in 34ms (Views: 0.1ms | ActiveRecord: 3.2ms | Allocations: 3192)
2022-04-04T09:13:18 [I|app|41a56e07] katello event handled success=true type=import_pool object_id=5 expired=false rescheduled=false duration=46.24
2022-04-04T09:13:18 [I|app|41a56e07] katello event handled success=true type=import_pool object_id=2 expired=false rescheduled=false duration=38.5
2022-04-04T09:13:18 [I|app|41a56e07] katello event handled success=true type=import_pool object_id=3 expired=false rescheduled=false duration=45.14
2022-04-04T09:13:18 [I|app|41a56e07] katello event handled success=true type=import_pool object_id=4 expired=false rescheduled=false duration=47.28
2022-04-04T09:13:24 [I|app|f9266113] Started PUT "/rhsm/consumers/30629d57-079e-4271-99a5-e2b20936c0ef/profiles" for 10.18.0.60 at 2022-04-04 09:13:24 -0700
2022-04-04T09:13:24 [I|app|f9266113] Processing by Katello::Api::Rhsm::CandlepinDynflowProxyController#upload_profiles as JSON
2022-04-04T09:13:24 [I|app|f9266113]   Parameters: {"id"=>"30629d57-079e-4271-99a5-e2b20936c0ef"}
2022-04-04T09:13:25 [I|app|f9266113] Completed 200 OK in 945ms (Views: 3.6ms | ActiveRecord: 145.1ms | Allocations: 81537)
2022-04-04T09:13:25 [I|app|3d6fad84] Started GET "/rhsm/consumers/30629d57-079e-4271-99a5-e2b20936c0ef/compliance" for 10.18.0.60 at 2022-04-04 09:13:25 -0700
2022-04-04T09:13:25 [I|app|3d6fad84] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2022-04-04T09:13:25 [I|app|3d6fad84]   Parameters: {"id"=>"30629d57-079e-4271-99a5-e2b20936c0ef"}
2022-04-04T09:13:25 [I|app|3d6fad84] Completed 200 OK in 78ms (Views: 0.2ms | ActiveRecord: 1.5ms | Allocations: 3177)
2022-04-04T09:13:25 [I|kat|41a56e07] candlepin event handled success=true subject=compliance.created entity_id=30629d57-079e-4271-99a5-e2b20936c0ef duration=18.28
2022-04-04T09:13:25 [I|app|82f03cce] Started GET "/rhsm/consumers/30629d57-079e-4271-99a5-e2b20936c0ef/owner" for 10.18.0.60 at 2022-04-04 09:13:25 -0700
2022-04-04T09:13:25 [I|app|82f03cce] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2022-04-04T09:13:25 [I|app|82f03cce]   Parameters: {"id"=>"30629d57-079e-4271-99a5-e2b20936c0ef"}
2022-04-04T09:13:25 [I|app|82f03cce] Completed 200 OK in 25ms (Views: 0.1ms | ActiveRecord: 1.6ms | Allocations: 3187)
2022-04-04T09:13:25 [I|app|fea4a5db] Started GET "/rhsm/consumers/30629d57-079e-4271-99a5-e2b20936c0ef" for 10.18.0.60 at 2022-04-04 09:13:25 -0700
2022-04-04T09:13:25 [I|app|fea4a5db] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_show as JSON
2022-04-04T09:13:25 [I|app|fea4a5db]   Parameters: {"id"=>"30629d57-079e-4271-99a5-e2b20936c0ef"}
2022-04-04T09:13:25 [I|app|fea4a5db] Completed 200 OK in 72ms (Views: 13.0ms | ActiveRecord: 2.6ms | Allocations: 8662)
2022-04-04T09:13:26 [I|app|d8c33c6a] Started GET "/rhsm/consumers/30629d57-079e-4271-99a5-e2b20936c0ef/certificates/serials" for 10.18.0.60 at 2022-04-04 09:13:26 -0700
2022-04-04T09:13:26 [I|app|d8c33c6a] Processing by Katello::Api::Rhsm::CandlepinProxiesController#serials as JSON
2022-04-04T09:13:26 [I|app|d8c33c6a]   Parameters: {"id"=>"30629d57-079e-4271-99a5-e2b20936c0ef"}
2022-04-04T09:13:26 [I|app|d8c33c6a] Completed 200 OK in 44ms (Views: 0.3ms | ActiveRecord: 7.5ms | Allocations: 4112)
2022-04-04T09:13:26 [I|app|7a158505] Started GET "/rhsm/status" for 10.18.0.60 at 2022-04-04 09:13:26 -0700
2022-04-04T09:13:26 [I|app|7a158505] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2022-04-04T09:13:26 [I|app|7a158505] Completed 200 OK in 24ms (Views: 0.6ms | ActiveRecord: 2.8ms | Allocations: 2673)
2022-04-04T09:13:26 [I|app|7274a2a1] Started GET "/rhsm/consumers/30629d57-079e-4271-99a5-e2b20936c0ef/content_overrides" for 10.18.0.60 at 2022-04-04 09:13:26 -0700
2022-04-04T09:13:26 [I|app|7274a2a1] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2022-04-04T09:13:26 [I|app|7274a2a1]   Parameters: {"id"=>"30629d57-079e-4271-99a5-e2b20936c0ef"}
2022-04-04T09:13:26 [I|app|7274a2a1] Completed 200 OK in 85ms (Views: 0.3ms | ActiveRecord: 3.4ms | Allocations: 3191)
2022-04-04T09:13:27 [I|bac|41a56e07] Task {label: , execution_plan_id: 74a4b7e2-236e-4e9f-aa31-8cc56fc96a22} state changed: pending
2022-04-04T09:13:27 [I|bac|41a56e07] Task {label: Actions::Katello::Applicability::Hosts::BulkGenerate, id: e12d4c44-510e-4991-bc41-5ce414a8f5a7, execution_plan_id: 74a4b7e2-236e-4e9f-aa31-8cc56fc96a22} state changed: planning
2022-04-04T09:13:27 [I|bac|41a56e07] Task {label: Actions::Katello::Applicability::Hosts::BulkGenerate, id: e12d4c44-510e-4991-bc41-5ce414a8f5a7, execution_plan_id: 74a4b7e2-236e-4e9f-aa31-8cc56fc96a22} state changed: planned
2022-04-04T09:13:27 [I|app|41a56e07] katello event handled success=true type=generate_host_applicability object_id=0 expired=false rescheduled=false duration=89.27
2022-04-04T09:13:27 [I|bac|41a56e07] Task {label: Actions::Katello::Applicability::Hosts::BulkGenerate, id: e12d4c44-510e-4991-bc41-5ce414a8f5a7, execution_plan_id: 74a4b7e2-236e-4e9f-aa31-8cc56fc96a22} state changed: running
2022-04-04T09:13:27 [I|bac|41a56e07] Task {label: Actions::Katello::Applicability::Hosts::BulkGenerate, id: e12d4c44-510e-4991-bc41-5ce414a8f5a7, execution_plan_id: 74a4b7e2-236e-4e9f-aa31-8cc56fc96a22} state changed: stopped  result: success
2022-04-04T09:13:28 [I|app|352406e0] Started GET "/rhsm/consumers/30629d57-079e-4271-99a5-e2b20936c0ef/certificates/serials" for 10.18.0.60 at 2022-04-04 09:13:28 -0700
2022-04-04T09:13:28 [I|app|352406e0] Processing by Katello::Api::Rhsm::CandlepinProxiesController#serials as JSON
2022-04-04T09:13:28 [I|app|352406e0]   Parameters: {"id"=>"30629d57-079e-4271-99a5-e2b20936c0ef"}
2022-04-04T09:13:28 [I|app|352406e0] Completed 200 OK in 36ms (Views: 0.2ms | ActiveRecord: 2.3ms | Allocations: 4065)
2022-04-04T09:13:28 [I|app|2048d5cf] Started GET "/rhsm/status" for 10.18.0.60 at 2022-04-04 09:13:28 -0700
2022-04-04T09:13:28 [I|app|2048d5cf] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2022-04-04T09:13:28 [I|app|2048d5cf] Completed 200 OK in 26ms (Views: 0.2ms | ActiveRecord: 1.9ms | Allocations: 2666)
2022-04-04T09:13:28 [I|app|85937600] Started GET "/rhsm/consumers/30629d57-079e-4271-99a5-e2b20936c0ef/content_overrides" for 10.18.0.60 at 2022-04-04 09:13:28 -0700
2022-04-04T09:13:28 [I|app|85937600] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2022-04-04T09:13:28 [I|app|85937600]   Parameters: {"id"=>"30629d57-079e-4271-99a5-e2b20936c0ef"}
2022-04-04T09:13:28 [I|app|85937600] Completed 200 OK in 22ms (Views: 0.1ms | ActiveRecord: 1.2ms | Allocations: 3178)
2022-04-04T09:13:30 [I|app|c7ce3cff] Started GET "/rhsm/consumers/30629d57-079e-4271-99a5-e2b20936c0ef/certificates/serials" for 10.18.0.60 at 2022-04-04 09:13:30 -0700
2022-04-04T09:13:30 [I|app|c7ce3cff] Processing by Katello::Api::Rhsm::CandlepinProxiesController#serials as JSON
2022-04-04T09:13:30 [I|app|c7ce3cff]   Parameters: {"id"=>"30629d57-079e-4271-99a5-e2b20936c0ef"}
2022-04-04T09:13:30 [I|app|c7ce3cff] Completed 200 OK in 46ms (Views: 0.3ms | ActiveRecord: 3.1ms | Allocations: 4064)
2022-04-04T09:13:30 [I|app|37972e24] Started GET "/rhsm/status" for 10.18.0.60 at 2022-04-04 09:13:30 -0700
2022-04-04T09:13:30 [I|app|37972e24] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2022-04-04T09:13:30 [I|app|37972e24] Completed 200 OK in 61ms (Views: 0.6ms | ActiveRecord: 1.7ms | Allocations: 2673)
2022-04-04T09:13:30 [I|app|6af2ff55] Started GET "/rhsm/consumers/30629d57-079e-4271-99a5-e2b20936c0ef/content_overrides" for 10.18.0.60 at 2022-04-04 09:13:30 -0700
2022-04-04T09:13:30 [I|app|6af2ff55] Processing by Katello::Api::Rhsm::CandlepinProxiesController#get as JSON
2022-04-04T09:13:30 [I|app|6af2ff55]   Parameters: {"id"=>"30629d57-079e-4271-99a5-e2b20936c0ef"}
2022-04-04T09:13:30 [I|app|6af2ff55] Completed 200 OK in 32ms (Views: 0.3ms | ActiveRecord: 2.3ms | Allocations: 3178)
2022-04-04T09:13:34 [I|app|ba75302b] Started GET "/katello/api/v2/repositories/6/gpg_key_content" for 10.18.0.60 at 2022-04-04 09:13:34 -0700
2022-04-04T09:13:34 [I|app|ba75302b] Processing by Katello::Api::V2::RepositoriesController#gpg_key_content as */*
2022-04-04T09:13:34 [I|app|ba75302b]   Parameters: {"api_version"=>"v2", "id"=>"6"}
2022-04-04T09:13:34 [I|app|ba75302b]   Rendering text template
2022-04-04T09:13:34 [I|app|ba75302b]   Rendered text template (Duration: 0.0ms | Allocations: 1)
2022-04-04T09:13:34 [I|app|ba75302b] Completed 200 OK in 9ms (Views: 0.5ms | ActiveRecord: 3.1ms | Allocations: 1755)
2022-04-04T09:13:44 [I|app|1e4363a0] Started GET "/rhsm/status" for 10.18.0.60 at 2022-04-04 09:13:44 -0700
2022-04-04T09:13:44 [I|app|1e4363a0] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2022-04-04T09:13:44 [I|app|1e4363a0] Completed 200 OK in 40ms (Views: 0.2ms | ActiveRecord: 3.1ms | Allocations: 2661)
2022-04-04T09:13:44 [I|app|e81a84d2] Started PUT "/rhsm/consumers/30629d57-079e-4271-99a5-e2b20936c0ef/profiles" for 10.18.0.60 at 2022-04-04 09:13:44 -0700
2022-04-04T09:13:44 [I|app|e81a84d2] Processing by Katello::Api::Rhsm::CandlepinDynflowProxyController#upload_profiles as JSON
2022-04-04T09:13:44 [I|app|e81a84d2]   Parameters: {"id"=>"30629d57-079e-4271-99a5-e2b20936c0ef"}
2022-04-04T09:13:45 [I|app|e81a84d2] Completed 200 OK in 825ms (Views: 30.1ms | ActiveRecord: 42.9ms | Allocations: 73950)
2022-04-04T09:13:45 [I|bac|41a56e07] Task {label: , execution_plan_id: 03ffb152-6f9d-42d5-8f89-105182d4de2d} state changed: pending
2022-04-04T09:13:45 [I|bac|41a56e07] Task {label: Actions::Katello::Applicability::Hosts::BulkGenerate, id: 0740bc5a-5776-42ac-95ef-242918af1145, execution_plan_id: 03ffb152-6f9d-42d5-8f89-105182d4de2d} state changed: planning
2022-04-04T09:13:45 [I|bac|41a56e07] Task {label: Actions::Katello::Applicability::Hosts::BulkGenerate, id: 0740bc5a-5776-42ac-95ef-242918af1145, execution_plan_id: 03ffb152-6f9d-42d5-8f89-105182d4de2d} state changed: planned
2022-04-04T09:13:45 [I|app|41a56e07] katello event handled success=true type=generate_host_applicability object_id=0 expired=false rescheduled=false duration=61.21
2022-04-04T09:13:45 [I|bac|41a56e07] Task {label: Actions::Katello::Applicability::Hosts::BulkGenerate, id: 0740bc5a-5776-42ac-95ef-242918af1145, execution_plan_id: 03ffb152-6f9d-42d5-8f89-105182d4de2d} state changed: running
2022-04-04T09:13:45 [I|bac|41a56e07] Task {label: Actions::Katello::Applicability::Hosts::BulkGenerate, id: 0740bc5a-5776-42ac-95ef-242918af1145, execution_plan_id: 03ffb152-6f9d-42d5-8f89-105182d4de2d} state changed: stopped  result: success
2022-04-04T09:13:57 [I|app|81d72c01] Started POST "/unattended/built?token=a44b6f7e-1339-4214-a63d-d89128c0db67" for 10.18.0.60 at 2022-04-04 09:13:57 -0700
2022-04-04T09:13:57 [I|app|81d72c01] Processing by UnattendedController#built as TEXT
2022-04-04T09:13:57 [I|app|81d72c01]   Parameters: {"token"=>"a44b6f7e-1339-4214-a63d-d89128c0db67"}
2022-04-04T09:13:57 [I|app|81d72c01] unattended: my_server is built!
2022-04-04T09:13:57 [I|app|81d72c01] Deploying TFTP PXELinux configuration for my_server
2022-04-04T09:13:57 [I|app|81d72c01] Deploying TFTP PXEGrub2 configuration for my_server
2022-04-04T09:13:57 [I|app|81d72c01] Deploying TFTP PXEGrub configuration for my_server
2022-04-04T09:13:57 [I|app|81d72c01] Deploying TFTP iPXE configuration for my_server
2022-04-04T09:13:58 [I|kat|41a56e07] candlepin event handled success=true subject=system_purpose_compliance.created entity_id=30629d57-079e-4271-99a5-e2b20936c0ef duration=20.69
2022-04-04T09:13:58 [I|app|81d72c01] Processed 5 tasks from queue 'Host::Managed Main', completed 5/5
2022-04-04T09:13:58 [I|aud|81d72c01] Host::Base (2) update event on build true, false
2022-04-04T09:13:58 [I|aud|81d72c01] Host::Base (2) update event on installed_at 2022-04-04 16:00:25 UTC, 2022-04-04 16:13:57 UTC
2022-04-04T09:13:58 [I|app|81d72c01] Completed 201 Created in 817ms (ActiveRecord: 56.2ms | Allocations: 139557)

Log from client when the server is provision

Note: Forwarding request to 'systemctl enable salt-minion.service'.
Created symlink /etc/systemd/system/multi-user.target.wants/salt-minion.service -> /usr/lib/systemd/system/salt-minion.service.
[CRITICAL] The Salt Master has rejected this minion's public key!
To repair this issue, delete the public key for this minion on the Salt Master and restart this minion.
Or restart the Salt Master in open mode to clean out the keys. The Salt Minion will now exit.

anaconda.ks part where salt gets install

if [ -f /usr/bin/dnf ]; then
  dnf -y install salt-minion
else
  yum -t -y install salt-minion
fi

cat > /etc/salt/minion.d/minion.conf << EOF
master: foreman
log_level: warning

autosign_grains:
  - autosign_key

grains: {
  "autosign_key": "8d16bcf8165b1372cbdf"
}

EOF

echo my_server > /etc/salt/minion_id

/sbin/chkconfig --level 345 salt-minion on

/usr/bin/salt-call --no-color --grains >/dev/null
4

That part of the production.log pictures the provisioning and not the key removal. The request to remove the Salt key from autosign_key happens when the salt-minion was installed on the host. So, after the provisioning.
You can replicate this moment by unauthenticating the salt-minion from the salt-master by running salt-key -d <minion-key> on your master. If you restart the salt-minion daemon, it starts a new authentication request which should be accepted since the authorization key is still part of autosign_key as you described in your issue. If you have a look in your production.log, there should be an incoming request from the Smart Proxy to /salt_autosign_auth. Can you verify this?

5

I have been using the steps you have mentioned about deleting the minion key and restarting the salt-minion on the client.

I grep for salt_autosign_auth in my production.log and proxy.log and I did not see anything after the provision have been completed.

6

I applied this patch always remove salt key on master (#166) · theforeman/foreman_salt@12692d1 · GitHub
And it is now working properly. Auto deleting the key off of the master when I click build on a server.

1 Like
7

Thanks for your update! We’ll include the patch in the next Salt release.