Bug 2170926 - The "hammer discovery provision" command reboots the system even if "--build true" has not been passed
Summary: The "hammer discovery provision" command reboots the system even if "--build ...
Keywords:
Status: NEW
Alias: None
Product: Red Hat Satellite
Classification: Red Hat
Component: Discovery Plugin
Version: 6.13.0
Hardware: All
OS: All
low
medium
Target Milestone: Unspecified
Assignee: satellite6-bugs
QA Contact: Shweta Singh
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2023-02-17 17:31 UTC by Sayan Das
Modified: 2023-08-03 17:35 UTC (History)
2 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)

Description Sayan Das 2023-02-17 17:31:22 UTC
Description of problem:

After discovering a system using iPXE, The execution of "hammer discovery provision" command against that discovered profile will reboot the system even if we haven't set the "build" option to true 


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

Tested in Satellite 6.13 latest snap

rubygem-hammer_cli_foreman_discovery-1.1.0-1.el8sat.noarch
satellite-6.13.0-6.el8sat.noarch


How reproducible:
Always

Steps to Reproduce:
1. Setup a Satellite 6.13 for iPXE based Discovery ( in libvirt )
2. Setup related subnet\domains\hostgroups\repositories etc as needed.
3. Discover a blank system and wait for it to get discovered
4. Use hammer command to provision that deployed system with and without "--build true"

Actual results:

ON Step 4:, 

With "--build true" system reboots and completes the build just fine.

Without "--build true" The system still reboots ( unexpectedly ) and fails to build ( as expected ). 

# hammer discovery provision --name mac525400fea371 --hostgroup-id 1 --organization-id 1 --location-id 2 --new-name rhel79 --subnet-id 1 --pxe-loader 'iPXE Embedded' 
Host created


# hammer host info --name rhel79.lab.example.com | grep "Build Status:"
    Build Status:  Installed

Logs:


==> /var/log/foreman/production.log <==
2023-02-17T22:38:30 [I|app|4b5ce814] Started PUT "/api/v2/discovered_hosts/7" for 192.168.124.2 at 2023-02-17 22:38:30 +0530
2023-02-17T22:38:30 [I|app|4b5ce814] Processing by Api::V2::DiscoveredHostsController#update as JSON
2023-02-17T22:38:30 [I|app|4b5ce814]   Parameters: {"location_id"=>2, "organization_id"=>1, "discovered_host"=>{"name"=>"rhel79", "subnet_id"=>1, "hostgroup_id"=>1, "pxe_loader"=>"iPXE Embedded", "host_parameters_attributes"=>{}}, "apiv"=>"v2", "id"=>"7"}
2023-02-17T22:38:30 [I|app|4b5ce814] Authorized user admin(Admin User)

==> /var/log/foreman-proxy/proxy.log <==
2023-02-17T22:38:30 4b5ce814 [I] Started GET /tftp/serverName 
2023-02-17T22:38:30 4b5ce814 [I] Finished GET /tftp/serverName with 200 (0.8 ms)
2023-02-17T22:38:31 4b5ce814 [I] Started GET /tftp/serverName 
2023-02-17T22:38:31 4b5ce814 [I] Finished GET /tftp/serverName with 200 (0.85 ms)

==> /var/log/messages <==
Feb 17 22:38:30 satellite613 smart-proxy[12516]: 192.168.124.2 - - [17/Feb/2023:22:38:30 IST] "GET /tftp/serverName HTTP/1.1" 200 45
Feb 17 22:38:30 satellite613 smart-proxy[12516]: - -> /tftp/serverName
Feb 17 22:38:31 satellite613 smart-proxy[12516]: 192.168.124.2 - - [17/Feb/2023:22:38:31 IST] "GET /tftp/serverName HTTP/1.1" 200 45
Feb 17 22:38:31 satellite613 smart-proxy[12516]: - -> /tftp/serverName

==> /var/log/foreman-proxy/proxy.log <==
2023-02-17T22:38:31 4b5ce814 [I] Started GET /dhcp/192.168.124.0/mac/52:54:00:fe:a3:71 
2023-02-17T22:38:31 4b5ce814 [I] Finished GET /dhcp/192.168.124.0/mac/52:54:00:fe:a3:71 with 200 (1.85 ms)
2023-02-17T22:38:31 4b5ce814 [I] Started GET /dhcp/192.168.124.0/ip/192.168.124.20 
2023-02-17T22:38:31 4b5ce814 [I] Finished GET /dhcp/192.168.124.0/ip/192.168.124.20 with 200 (0.76 ms)

==> /var/log/messages <==
Feb 17 22:38:31 satellite613 smart-proxy[12516]: 192.168.124.2 - - [17/Feb/2023:22:38:31 IST] "GET /dhcp/192.168.124.0/mac/52:54:00:fe:a3:71 HTTP/1.1" 200 332
Feb 17 22:38:31 satellite613 smart-proxy[12516]: - -> /dhcp/192.168.124.0/mac/52:54:00:fe:a3:71
Feb 17 22:38:31 satellite613 smart-proxy[12516]: 192.168.124.2 - - [17/Feb/2023:22:38:31 IST] "GET /dhcp/192.168.124.0/ip/192.168.124.20 HTTP/1.1" 200 334
Feb 17 22:38:31 satellite613 smart-proxy[12516]: - -> /dhcp/192.168.124.0/ip/192.168.124.20

==> /var/log/foreman/production.log <==
2023-02-17T22:38:31 [I|app|4b5ce814] Create DHCP reservation rhel79.lab.example.com for rhel79.lab.example.com-52:54:00:fe:a3:71/192.168.124.20

==> /var/log/foreman-proxy/proxy.log <==
2023-02-17T22:38:31 4b5ce814 [I] Started POST /dhcp/192.168.124.0 
2023-02-17T22:38:31 4b5ce814 [I] Next-server option not IPv4, trying to resolve 'satellite613.lab.example.com'
2023-02-17T22:38:31 4b5ce814 [I] Finished POST /dhcp/192.168.124.0 with 200 (24.55 ms)

==> /var/log/foreman/production.log <==
2023-02-17T22:38:31 [I|app|4b5ce814] Add DNS A record for rhel79.lab.example.com/192.168.124.20

==> /var/log/foreman-proxy/proxy.log <==
2023-02-17T22:38:31 4b5ce814 [I] Started POST /dns/ 
2023-02-17T22:38:31 4b5ce814 [I] Finished POST /dns/ with 200 (14.63 ms)

==> /var/log/foreman/production.log <==
2023-02-17T22:38:31 [I|app|4b5ce814] Add DNS PTR record for 192.168.124.20/rhel79.lab.example.com

==> /var/log/foreman-proxy/proxy.log <==
2023-02-17T22:38:31 4b5ce814 [I] Started POST /dns/ 
2023-02-17T22:38:31 4b5ce814 [I] Finished POST /dns/ with 200 (13.63 ms)

==> /var/log/foreman/production.log <==
2023-02-17T22:38:31 [I|app|4b5ce814] Deploying TFTP PXELinux configuration for rhel79.lab.example.com

==> /var/log/foreman-proxy/proxy.log <==
2023-02-17T22:38:31 4b5ce814 [I] Started POST /tftp/PXELinux/52:54:00:fe:a3:71 
2023-02-17T22:38:31 4b5ce814 [I] Finished POST /tftp/PXELinux/52:54:00:fe:a3:71 with 200 (0.81 ms)

==> /var/log/foreman/production.log <==
2023-02-17T22:38:31 [I|app|4b5ce814] Deploying TFTP PXEGrub2 configuration for rhel79.lab.example.com

==> /var/log/foreman-proxy/proxy.log <==
2023-02-17T22:38:31 4b5ce814 [I] Started POST /tftp/PXEGrub2/52:54:00:fe:a3:71 
2023-02-17T22:38:31 4b5ce814 [I] Finished POST /tftp/PXEGrub2/52:54:00:fe:a3:71 with 200 (1.96 ms)

==> /var/log/messages <==
Feb 17 22:38:31 satellite613 smart-proxy[12516]: 192.168.124.2 - - [17/Feb/2023:22:38:31 IST] "POST /dhcp/192.168.124.0 HTTP/1.1" 200 0
Feb 17 22:38:31 satellite613 smart-proxy[12516]: - -> /dhcp/192.168.124.0
Feb 17 22:38:31 satellite613 named[992]: client @0x7f377c0a1b90 127.0.0.1#47311/key rndc-key: updating zone 'lab.example.com/IN': adding an RR at 'rhel79.lab.example.com' A 192.168.124.20
Feb 17 22:38:31 satellite613 smart-proxy[12516]: 192.168.124.2 - - [17/Feb/2023:22:38:31 IST] "POST /dns/ HTTP/1.1" 200 0
Feb 17 22:38:31 satellite613 smart-proxy[12516]: - -> /dns/
Feb 17 22:38:31 satellite613 named[992]: client @0x7f377c0a1b90 127.0.0.1#42451/key rndc-key: updating zone '124.168.192.in-addr.arpa/IN': adding an RR at '20.124.168.192.in-addr.arpa' PTR rhel79.lab.example.com.
Feb 17 22:38:31 satellite613 smart-proxy[12516]: 192.168.124.2 - - [17/Feb/2023:22:38:31 IST] "POST /dns/ HTTP/1.1" 200 0
Feb 17 22:38:31 satellite613 smart-proxy[12516]: - -> /dns/
Feb 17 22:38:31 satellite613 smart-proxy[12516]: 192.168.124.2 - - [17/Feb/2023:22:38:31 IST] "POST /tftp/PXELinux/52:54:00:fe:a3:71 HTTP/1.1" 200 0
Feb 17 22:38:31 satellite613 smart-proxy[12516]: - -> /tftp/PXELinux/52:54:00:fe:a3:71
Feb 17 22:38:31 satellite613 smart-proxy[12516]: 192.168.124.2 - - [17/Feb/2023:22:38:31 IST] "POST /tftp/PXEGrub2/52:54:00:fe:a3:71 HTTP/1.1" 200 0
Feb 17 22:38:31 satellite613 smart-proxy[12516]: - -> /tftp/PXEGrub2/52:54:00:fe:a3:71

==> /var/log/foreman/production.log <==
2023-02-17T22:38:31 [I|app|4b5ce814] Deploying TFTP PXEGrub configuration for rhel79.lab.example.com

==> /var/log/foreman-proxy/proxy.log <==
2023-02-17T22:38:31 4b5ce814 [I] Started POST /tftp/PXEGrub/52:54:00:fe:a3:71 
2023-02-17T22:38:31 4b5ce814 [I] Finished POST /tftp/PXEGrub/52:54:00:fe:a3:71 with 200 (1.25 ms)

==> /var/log/foreman/production.log <==
2023-02-17T22:38:31 [I|app|4b5ce814] Deploying TFTP iPXE configuration for rhel79.lab.example.com

==> /var/log/foreman-proxy/proxy.log <==
2023-02-17T22:38:31 4b5ce814 [I] Started POST /tftp/iPXE/52:54:00:fe:a3:71 
2023-02-17T22:38:31 4b5ce814 [I] Finished POST /tftp/iPXE/52:54:00:fe:a3:71 with 200 (1.11 ms)

==> /var/log/foreman/production.log <==
2023-02-17T22:38:31 [I|app|4b5ce814] Processed 7 tasks from queue 'Host::Managed Main', completed 7/7
2023-02-17T22:38:31 [I|aud|4b5ce814] Host::Base (7) update event on name mac525400fea371, rhel79.lab.example.com
2023-02-17T22:38:31 [I|aud|4b5ce814] Host::Base (7) update event on architecture_id , 1
2023-02-17T22:38:31 [I|aud|4b5ce814] Host::Base (7) update event on operatingsystem_id , 2
2023-02-17T22:38:31 [I|aud|4b5ce814] Host::Base (7) update event on ptable_id , 138
2023-02-17T22:38:31 [I|aud|4b5ce814] Host::Base (7) update event on hostgroup_id , 1
2023-02-17T22:38:31 [I|aud|4b5ce814] Host::Base (7) update event on managed false, true
2023-02-17T22:38:31 [I|aud|4b5ce814] Host::Base (7) update event on grub_pass , 
2023-02-17T22:38:31 [I|aud|4b5ce814] Host::Base (7) update event on openscap_proxy_id , 1
2023-02-17T22:38:31 [I|aud|4b5ce814] Host::Base (7) update event on pxe_loader , iPXE Embedded
2023-02-17T22:38:31 [I|aud|4b5ce814] Nic::Managed (7) update event on name mac525400fea371, rhel79.lab.example.com
2023-02-17T22:38:31 [I|aud|4b5ce814] Nic::Managed (7) update event on subnet_id 2, 1
2023-02-17T22:38:31 [I|aud|4b5ce814] Nic::Managed (7) update event on domain_id , 1
2023-02-17T22:38:31 [I|aud|4b5ce814] Katello::Host::ContentFacet (6) create event on host_id 7
2023-02-17T22:38:31 [I|aud|4b5ce814] Katello::Host::ContentFacet (6) create event on uuid 
2023-02-17T22:38:31 [I|aud|4b5ce814] Katello::Host::ContentFacet (6) create event on content_view_id 2
2023-02-17T22:38:31 [I|aud|4b5ce814] Katello::Host::ContentFacet (6) create event on lifecycle_environment_id 1
2023-02-17T22:38:31 [I|aud|4b5ce814] Katello::Host::ContentFacet (6) create event on kickstart_repository_id 14
2023-02-17T22:38:31 [I|aud|4b5ce814] Katello::Host::ContentFacet (6) create event on content_source_id 1
2023-02-17T22:38:31 [I|aud|4b5ce814] Katello::Host::ContentFacet (6) create event on installable_security_errata_count 0
2023-02-17T22:38:31 [I|aud|4b5ce814] Katello::Host::ContentFacet (6) create event on installable_enhancement_errata_count 0
2023-02-17T22:38:31 [I|aud|4b5ce814] Katello::Host::ContentFacet (6) create event on installable_bugfix_errata_count 0
2023-02-17T22:38:31 [I|aud|4b5ce814] Katello::Host::ContentFacet (6) create event on applicable_rpm_count 0
2023-02-17T22:38:31 [I|aud|4b5ce814] Katello::Host::ContentFacet (6) create event on upgradable_rpm_count 0
2023-02-17T22:38:31 [I|aud|4b5ce814] Katello::Host::ContentFacet (6) create event on applicable_module_stream_count 0
2023-02-17T22:38:31 [I|aud|4b5ce814] Katello::Host::ContentFacet (6) create event on upgradable_module_stream_count 0
2023-02-17T22:38:31 [I|aud|4b5ce814] Katello::Host::ContentFacet (6) create event on applicable_deb_count 0
2023-02-17T22:38:31 [I|aud|4b5ce814] Katello::Host::ContentFacet (6) create event on upgradable_deb_count 0

==> /var/log/foreman-proxy/proxy.log <==
2023-02-17T22:38:31 e04a2b18 [I] Started PUT /discovery/192.168.124.20/power/reboot 
2023-02-17T22:38:31 e04a2b18 [I] Finished PUT /discovery/192.168.124.20/power/reboot with 200 (51.84 ms)

==> /var/log/messages <==
Feb 17 22:38:31 satellite613 smart-proxy[12516]: 192.168.124.2 - - [17/Feb/2023:22:38:31 IST] "POST /tftp/PXEGrub/52:54:00:fe:a3:71 HTTP/1.1" 200 0
Feb 17 22:38:31 satellite613 smart-proxy[12516]: - -> /tftp/PXEGrub/52:54:00:fe:a3:71
Feb 17 22:38:31 satellite613 smart-proxy[12516]: 192.168.124.2 - - [17/Feb/2023:22:38:31 IST] "POST /tftp/iPXE/52:54:00:fe:a3:71 HTTP/1.1" 200 0
Feb 17 22:38:31 satellite613 smart-proxy[12516]: - -> /tftp/iPXE/52:54:00:fe:a3:71
Feb 17 22:38:31 satellite613 smart-proxy[12516]: 192.168.124.2 - - [17/Feb/2023:22:38:31 IST] "PUT /discovery/192.168.124.20/power/reboot HTTP/1.1" 200 15
Feb 17 22:38:31 satellite613 smart-proxy[12516]: - -> /discovery/192.168.124.20/power/reboot

==> /var/log/foreman/production.log <==
2023-02-17T22:38:31 [I|app|4b5ce814] Processed 1 tasks from queue 'Host::Managed Post', completed 1/1
2023-02-17T22:38:31 [I|app|4b5ce814] ForemanWebhooks::EventSubscriber: host_updated.event.foreman event received
2023-02-17T22:38:31 [I|app|4b5ce814]   Rendered /usr/share/gems/gems/foreman_discovery-22.0.2/app/views/api/v2/discovered_hosts/update.json.rabl (Duration: 5.0ms | Allocations: 6588)
2023-02-17T22:38:31 [I|app|4b5ce814] Completed 200 OK in 1305ms (Views: 5.7ms | ActiveRecord: 68.1ms | Allocations: 200976)

==> /var/log/httpd/foreman-ssl_access_ssl.log <==
192.168.124.2 - - [17/Feb/2023:22:38:30 +0530] "PUT /api/v2/discovered_hosts/7 HTTP/1.1" 200 40 "-" "rest-client/2.1.0 (linux x86_64) ruby/2.7.6p219"



Expected results:

The system should not reboot if "--build true" has not been passed or it should be marked as a mandatory option to be passed. 


Additional info:

Comment 1 Sayan Das 2023-02-17 17:33:12 UTC
I do have this setting enabled 

# hammer settings info --name discovery_reboot
Id:            discovery_reboot
Name:          discovery_reboot
Description:   Automatically reboot or kexec discovered host during provisioning
Category:      Discovery
Settings type: boolean
Value:         true


But I would consider the term "provisioning" as passing "--build true"

Comment 2 Leos Stejskal 2023-02-21 12:14:07 UTC
Hi,
Setting flag --build to true will only initiate hooks and callbacks when host is set to build,
AFAIK --build flag doesn't have any effect on rebooting the system.

> Without "--build true" The system still reboots ( unexpectedly ) and fails to build ( as expected ). 

This is correct behavior, if you set discovery_reboot to false it should not happen.

Comment 3 Sayan Das 2023-02-21 12:27:28 UTC
I assumed This might not be an expected behavior as If just the host entry is created but The host has not been put into build mode, The Reboot should not occur.

As I personally consider rebooting the system as part of the Build process only. 

If we still feel that, This is something that is expected behavior and no further improvements can be \ required to be done about it, I am okay to close this bug as "NOTABUG" or else I am also good to have it proposed as RFE ( if that makes any sense ).


Note You need to log in before you can comment on or make changes to this bug.