Foreman 1.17 not creating PXE boot files on proxy

trinaryouroboros · May 17, 2018, 6:26pm

Problem:

When deploying a libvirt guest using Create Host from the Foreman UI, all processes and checks seem to pass, and eventually we get the host dashboard. We open the console, and it seems all the host gets is the default PXE menu found on the proxy:/var/lib/tftpboot/pxelinux.cfg/default

Expected outcome:

Normally, in 1.15 the Foreman proxy is told to create a PXE menu that includes things like the vmlinuz/initrd location, kickstart to pull, etc, in a file that looks like /var/lib/tftpboot/pxelinux.cfg/01-(Mac address of guest)

Then, the PXE boot on the guest would pick up that configuration from the proxy TFTP server.

Foreman and Proxy versions:

Using 1.17 on both (I’m trying my best to upgrade from 1.15)

Foreman and Proxy plugin versions:

Foreman master:
foreman_bootdisk 11.0.0
foreman_discovery 11.0.0
foreman_snapshot_management 1.3.0
foreman_templates 5.0.1
foreman_vmwareannotations 0.0.1

Foreman proxy:
rubygem-smart_proxy_discovery-1.0.4-1.el7.noarch
rubygem-smart_proxy_dhcp_infoblox-0.0.13-1.fm1_17.el7.noarch

Other relevant data:

I hate to say it, but there is just nothing relevant in the logs on either the Foreman master or proxy, the only thing I see is on the proxy it correctly reserves DNS, and downloads the associated initrd/vmlinuz images to the TFTP server, and, the guest correctly connects to the TFTP server in the logs, message just says it is booting default menu. There is no MAC file being created for the guest in pxelinux.cfg at all.

ThomasADavis · May 18, 2018, 9:23pm

I see this too. Wondering what is wrong… no errors, no mac pxelinux.cfg files.

ThomasADavis · May 18, 2018, 11:48pm

Well I figured out was wrong with mine…

In the Infrastructure/subnets, the subnet, under proxies, make sure you have a tftp proxy set.

trinaryouroboros · May 21, 2018, 1:46pm

rats, that’s not my problem, I have a tftp proxy set for the subnet

Gwmngilfen · May 21, 2018, 1:56pm

Since you’ve covered the basics already, I’m just going to spell out the steps I’d go through - sorry if this is overly-handholding

The host has a provisioning NIC flagged
The provisioning NIC has a subnet
The subnet has a TFTP proxy set
The proxy still has the TFTP feature (check with Refresh features in case of unexpected config changes).

If all that checks out then I’d at least expect Foreman to log that it’s creating the TFTP file.

trinaryouroboros · May 21, 2018, 2:52pm

So, yes, the host has a provisioning NIC checkmarked, the provisioning NIC has a subnet, the subnet has a TFTP proxy set (as mentioned earlier) and even after restarting proxy, and refreshing, it still shows TFTP feature is available.

After restarting smart proxy the following log entry confirms TFTP is successfully initialized:

I, [2018-05-21T14:27:21.800711 ]  INFO -- : Successfully initialized 'tftp'

The /var/lib/tftpboot directory had the following change done to it to be extra safe:

chown -R foreman-proxy:foreman-proxy /var/lib/tftpboot

I’m Dying to know what’s going on here, the only thing perhaps different we are doing with this is deploying the Foreman proxies using the Puppet Forge module for theforeman and smartproxy…

The following is the debug logs for the Foreman proxy during host creation:

I, [2018-05-21T14:27:21.885655 ]  INFO -- : WEBrick::HTTPServer#start: pid=10208 port=8443
I, [2018-05-21T14:27:21.885765 ]  INFO -- : Smart proxy has launched on 1 socket(s), waiting for requests
D, [2018-05-21T14:31:13.069231 ] DEBUG -- : accept: 10.6.6.21:48136
D, [2018-05-21T14:31:13.120877 ] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2018-05-21T14:31:13.133725 479a50ed] DEBUG -- : verifying remote client 10.6.6.21 against trusted_hosts ["stage-foreman01.dc02.example.net", "stage-foreman01.dc01.example.net", "dev-foreman01.dc02.example.net", "dev-foreman02.dc02.example.net", "dev-foreman03.dc02.example.net", "dev-foreman01.dc01.example.net", "dev-foreman02.dc01.example.net", "dev-foreman03.dc01.example.net"]
D, [2018-05-21T14:31:13.558622 479a50ed] DEBUG -- : Searching for free IP - pinging 10.9.6.125.
D, [2018-05-21T14:31:15.570009 479a50ed] DEBUG -- : Found free IP 10.9.6.125 out of a total of 250 free IPs.
I, [2018-05-21T14:31:15.572512 479a50ed]  INFO -- : 10.6.6.21 - - [21/May/2018:14:31:15 +0000] "GET /dhcp/10.9.6.0/unused_ip?from=10.9.6.2&to=10.9.6.252 HTTP/1.1" 200 21 2.4392

D, [2018-05-21T14:31:15.700221 ] DEBUG -- : close: 10.6.6.21:48136
D, [2018-05-21T14:32:44.116251 ] DEBUG -- : accept: 10.6.6.21:48148
D, [2018-05-21T14:32:44.192714 ] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2018-05-21T14:32:44.196190 479a50ed] DEBUG -- : verifying remote client 10.6.6.21 against trusted_hosts ["stage-foreman01.dc02.example.net", "stage-foreman01.dc01.example.net", "dev-foreman01.dc02.example.net", "dev-foreman02.dc02.example.net", "dev-foreman03.dc02.example.net", "dev-foreman01.dc01.example.net", "dev-foreman02.dc01.example.net", "dev-foreman03.dc01.example.net"]
I, [2018-05-21T14:32:44.196926 479a50ed]  INFO -- : 10.6.6.21 - - [21/May/2018:14:32:44 +0000] "GET /tftp/serverName HTTP/1.1" 200 17 0.0012

D, [2018-05-21T14:32:44.324459 ] DEBUG -- : close: 10.6.6.21:48148
D, [2018-05-21T14:32:44.520240 ] DEBUG -- : accept: 10.6.6.21:48150
D, [2018-05-21T14:32:44.568131 ] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2018-05-21T14:32:44.571851 479a50ed] DEBUG -- : verifying remote client 10.6.6.21 against trusted_hosts ["stage-foreman01.dc02.example.net", "stage-foreman01.dc01.example.net", "dev-foreman01.dc02.example.net", "dev-foreman02.dc02.example.net", "dev-foreman03.dc02.example.net", "dev-foreman01.dc01.example.net", "dev-foreman02.dc01.example.net", "dev-foreman03.dc01.example.net"]
D, [2018-05-21T14:32:44.743029 479a50ed] DEBUG -- : Added DHCP reservation for 10.9.6.125/52:54:00:e6:40:29
D, [2018-05-21T14:32:44.743221 479a50ed] DEBUG -- : Restarting grid.
I, [2018-05-21T14:32:45.095971 479a50ed]  INFO -- : 10.6.6.21 - - [21/May/2018:14:32:45 +0000] "POST /dhcp/10.9.6.0 HTTP/1.1" 200 - 0.5270

D, [2018-05-21T14:32:45.145374 ] DEBUG -- : close: 10.6.6.21:48150
D, [2018-05-21T14:32:45.374303 ] DEBUG -- : accept: 10.6.6.21:48152
D, [2018-05-21T14:32:45.422339 ] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2018-05-21T14:32:45.423641 479a50ed] DEBUG -- : verifying remote client 10.6.6.21 against trusted_hosts ["stage-foreman01.dc02.example.net", "stage-foreman01.dc01.example.net", "dev-foreman01.dc02.example.net", "dev-foreman02.dc02.example.net", "dev-foreman03.dc02.example.net", "dev-foreman01.dc01.example.net", "dev-foreman02.dc01.example.net", "dev-foreman03.dc01.example.net"]
D, [2018-05-21T14:32:45.425436 479a50ed] DEBUG -- : Starting task: /usr/bin/wget --timeout=10 --tries=3 --no-check-certificate -nv -c "http://artifactory-read.example.net/artifactory/centos/7/os/x86_64/images/pxeboot/vmlinuz" -O "/var/lib/tftpboot/boot/CentOS-7-x86_64-vmlinuz"
I, [2018-05-21T14:32:45.430696 479a50ed]  INFO -- : 10.6.6.21 - - [21/May/2018:14:32:45 +0000] "POST /tftp/fetch_boot_file HTTP/1.1" 200 - 0.0073

D, [2018-05-21T14:32:45.475764 ] DEBUG -- : close: 10.6.6.21:48152
D, [2018-05-21T14:32:45.607618 ] DEBUG -- : accept: 10.6.6.21:48154
D, [2018-05-21T14:32:45.655621 ] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2018-05-21T14:32:45.656765 479a50ed] DEBUG -- : verifying remote client 10.6.6.21 against trusted_hosts ["stage-foreman01.dc02.example.net", "stage-foreman01.dc01.example.net", "dev-foreman01.dc02.example.net", "dev-foreman02.dc02.example.net", "dev-foreman03.dc02.example.net", "dev-foreman01.dc01.example.net", "dev-foreman02.dc01.example.net", "dev-foreman03.dc01.example.net"]
D, [2018-05-21T14:32:45.657504 479a50ed] DEBUG -- : Starting task: /usr/bin/wget --timeout=10 --tries=3 --no-check-certificate -nv -c "http://artifactory-read.example.net/artifactory/centos/7/os/x86_64/images/pxeboot/initrd.img" -O "/var/lib/tftpboot/boot/CentOS-7-x86_64-initrd.img"
I, [2018-05-21T14:32:45.660519 479a50ed]  INFO -- : 10.6.6.21 - - [21/May/2018:14:32:45 +0000] "POST /tftp/fetch_boot_file HTTP/1.1" 200 - 0.0040

D, [2018-05-21T14:32:45.705403 ] DEBUG -- : close: 10.6.6.21:48154

The following is the debug logs for the Foreman master during host creation:

2018-05-21 14:32:25 2a2ab233 [app] [I]   Rendered tasks/_list.html.erb (0.8ms)
2018-05-21 14:32:25 2a2ab233 [app] [I] Completed 200 OK in 15ms (Views: 7.2ms | ActiveRecord: 0.6ms)
2018-05-21 14:32:28 26633d07 [app] [I] Started GET "/notification_recipients" for 10.10.10.144 at 2018-05-21 14:32:28 +0000
2018-05-21 14:32:28 26633d07 [app] [I] Processing by NotificationRecipientsController#index as JSON
2018-05-21 14:32:28 26633d07 [app] [I] Current user: admin (administrator)
2018-05-21 14:32:28 26633d07 [app] [D] Setting current user thread-local variable to admin
2018-05-21 14:32:28 26633d07 [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:28 26633d07 [notifications] [D] Cache Hit: notification, reading cache for notification-4
2018-05-21 14:32:28 26633d07 [app] [D] Body: {"notifications":[]}
2018-05-21 14:32:28 26633d07 [app] [I] Completed 200 OK in 7ms (Views: 0.2ms | ActiveRecord: 0.3ms)
2018-05-21 14:32:38 ac0d79f3 [app] [I] Started POST "/hosts" for 10.10.10.144 at 2018-05-21 14:32:38 +0000
2018-05-21 14:32:38 ac0d79f3 [app] [I] Processing by HostsController#create as */*
2018-05-21 14:32:38 ac0d79f3 [app] [I]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"[hidden]", "host"=>{"name"=>"dev-testvm315", "location_id"=>"2", "hostgroup_id"=>"4", "compute_resource_id"=>"3", "puppetclass_ids"=>[""], "managed"=>"true", "progress_report_id"=>"[FILTERED]", "type"=>"Host::Managed", "interfaces_attributes"=>{"0"=>{"_destroy"=>"0", "type"=>"Nic::Managed", "mac"=>"", "identifier"=>"", "name"=>"dev-testvm315", "domain_id"=>"2", "subnet_id"=>"3", "ip"=>"10.9.6.125", "ip6"=>"", "managed"=>"1", "primary"=>"1", "provision"=>"1", "virtual"=>"0", "tag"=>"", "attached_to"=>"", "compute_attributes"=>{"type"=>"bridge", "bridge"=>"br6", "model"=>"virtio"}}}, "compute_attributes"=>{"cpus"=>"2", "memory"=>"4294967296", "start"=>"1", "volumes_attributes"=>{"0"=>{"_delete"=>"", "pool_name"=>"default", "capacity"=>"12G", "allocation"=>"0G", "format_type"=>"raw"}}}, "architecture_id"=>"1", "operatingsystem_id"=>"1", "provision_method"=>"build", "build"=>"1", "medium_id"=>"9", "ptable_id"=>"198", "pxe_loader"=>"None", "disk"=>"", "root_pass"=>"[FILTERED]", "is_owned_by"=>"4-Users", "enabled"=>"1", "comment"=>"", "overwrite"=>"false"}, "capabilities"=>"build image new_volume", "provider"=>"Libvirt", "bare_metal_capabilities"=>"build"}
2018-05-21 14:32:38 ac0d79f3 [app] [I] Current user: admin (administrator)
2018-05-21 14:32:38 ac0d79f3 [app] [D] Setting current user thread-local variable to admin
2018-05-21 14:32:38 ac0d79f3 [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:38 ac0d79f3 [app] [D] Unpermitted parameters: :utf8, :authenticity_token, :capabilities, :provider, :bare_metal_capabilities, :locale
2018-05-21 14:32:38 ac0d79f3 [app] [D] Unpermitted parameters: :utf8, :authenticity_token, :capabilities, :provider, :bare_metal_capabilities, :locale
2018-05-21 14:32:38 ac0d79f3 [app] [D] Unpermitted parameters: :utf8, :authenticity_token, :capabilities, :provider, :bare_metal_capabilities, :locale
2018-05-21 14:32:38 ac0d79f3 [app] [D] Scheduling new DHCP reservations for dev-testvm315.dc02.example.net
2018-05-21 14:32:38 ac0d79f3 [app] [D] Enqueued task 'Create DHCP Settings for dev-testvm315.dc02.example.net' to 'Host::Managed Main' queue
2018-05-21 14:32:38 ac0d79f3 [app] [D] Enqueued task 'Deploy TFTP PXEGrub2 config for dev-testvm315.dc02.example.net' to 'Host::Managed Main' queue
2018-05-21 14:32:38 ac0d79f3 [app] [D] Enqueued task 'Deploy TFTP PXELinux config for dev-testvm315.dc02.example.net' to 'Host::Managed Main' queue
2018-05-21 14:32:38 ac0d79f3 [app] [D] Enqueued task 'Deploy TFTP PXEGrub config for dev-testvm315.dc02.example.net' to 'Host::Managed Main' queue
2018-05-21 14:32:38 ac0d79f3 [app] [D] Enqueued task 'Fetch TFTP boot files for dev-testvm315.dc02.example.net' to 'Host::Managed Main' queue
2018-05-21 14:32:38 a9a62302 [app] [I] Started GET "/notification_recipients" for 10.10.10.144 at 2018-05-21 14:32:38 +0000
2018-05-21 14:32:38 a9a62302 [app] [I] Processing by NotificationRecipientsController#index as JSON
2018-05-21 14:32:38 a9a62302 [app] [I] Current user: admin (administrator)
2018-05-21 14:32:38 a9a62302 [app] [D] Setting current user thread-local variable to admin
2018-05-21 14:32:38 a9a62302 [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:38 a9a62302 [notifications] [D] Cache Hit: notification, reading cache for notification-4
2018-05-21 14:32:38 a9a62302 [app] [D] Body: {"notifications":[]}
2018-05-21 14:32:38 a9a62302 [app] [I] Completed 200 OK in 6ms (Views: 0.2ms | ActiveRecord: 0.3ms)
2018-05-21 14:32:39 689bba9c [app] [I] Started GET "/tasks/be975a31-8a75-4ac2-9e34-9115a1d3be54" for 10.10.10.144 at 2018-05-21 14:32:39 +0000
2018-05-21 14:32:39 689bba9c [app] [I] Processing by TasksController#show as */*
2018-05-21 14:32:39 689bba9c [app] [I]   Parameters: {"id"=>"be975a31-8a75-4ac2-9e34-9115a1d3be54"}
2018-05-21 14:32:39 689bba9c [app] [I] Current user: admin (administrator)
2018-05-21 14:32:39 689bba9c [app] [D] Setting current user thread-local variable to admin
2018-05-21 14:32:40 689bba9c [app] [I]   Rendered tasks/_list.html.erb (0.2ms)
2018-05-21 14:32:40 689bba9c [app] [I] Completed 200 OK in 9ms (Views: 0.8ms | ActiveRecord: 0.8ms)
2018-05-21 14:32:41 ac0d79f3 [app] [D] Enqueued task 'Set up compute instance dev-testvm315.dc02.example.net' to 'Host::Managed Main' queue
2018-05-21 14:32:41 ac0d79f3 [app] [D] Enqueued task 'Query instance details for dev-testvm315.dc02.example.net' to 'Host::Managed Main' queue
2018-05-21 14:32:41 ac0d79f3 [app] [D] Enqueued task 'Power up compute instance dev-testvm315.dc02.example.net' to 'Host::Managed Main' queue
2018-05-21 14:32:41 22e6032c [app] [I] Started GET "/tasks/be975a31-8a75-4ac2-9e34-9115a1d3be54" for 10.10.10.144 at 2018-05-21 14:32:41 +0000
2018-05-21 14:32:41 22e6032c [app] [I] Processing by TasksController#show as */*
2018-05-21 14:32:41 22e6032c [app] [I]   Parameters: {"id"=>"be975a31-8a75-4ac2-9e34-9115a1d3be54"}
2018-05-21 14:32:41 22e6032c [app] [I] Current user: admin (administrator)
2018-05-21 14:32:41 22e6032c [app] [D] Setting current user thread-local variable to admin
2018-05-21 14:32:41 22e6032c [app] [I]   Rendered tasks/_list.html.erb (0.1ms)
2018-05-21 14:32:41 22e6032c [app] [I] Completed 200 OK in 8ms (Views: 0.7ms | ActiveRecord: 1.0ms)
2018-05-21 14:32:41 ac0d79f3 [app] [D] Processing task 'Set up compute instance dev-testvm315.dc02.example.net' from 'Host::Managed Main'
2018-05-21 14:32:41 ac0d79f3 [app] [I] Adding Compute instance for dev-testvm315.dc02.example.net
2018-05-21 14:32:43 9d80b7c2 [app] [I] Started GET "/tasks/be975a31-8a75-4ac2-9e34-9115a1d3be54" for 10.10.10.144 at 2018-05-21 14:32:43 +0000
2018-05-21 14:32:43 9d80b7c2 [app] [I] Processing by TasksController#show as */*
2018-05-21 14:32:43 9d80b7c2 [app] [I]   Parameters: {"id"=>"be975a31-8a75-4ac2-9e34-9115a1d3be54"}
2018-05-21 14:32:43 9d80b7c2 [app] [I] Current user: admin (administrator)
2018-05-21 14:32:43 9d80b7c2 [app] [D] Setting current user thread-local variable to admin
2018-05-21 14:32:43 9d80b7c2 [app] [I]   Rendered tasks/_list.html.erb (0.8ms)
2018-05-21 14:32:43 9d80b7c2 [app] [I] Completed 200 OK in 9ms (Views: 1.3ms | ActiveRecord: 1.0ms)
2018-05-21 14:32:43 ac0d79f3 [app] [D] Processing task 'Query instance details for dev-testvm315.dc02.example.net' from 'Host::Managed Main'
2018-05-21 14:32:43 ac0d79f3 [app] [D] Orchestration::Compute: Trying to match network interfaces from fog [  <Fog::Compute::Libvirt::Nic
 |     mac="52:54:00:e6:40:32",
 |     id=nil,
 |     type="bridge",
 |     network=nil,
 |     bridge="br6",
 |     model="virtio"
 |   >]
2018-05-21 14:32:43 ac0d79f3 [app] [D] Orchestration::Compute: nic #<Nic::Managed id: nil, mac: nil, ip: "10.9.6.125", type: "Nic::Managed", name: "dev-testvm315.dc02.example.net", host_id: nil, subnet_id: 3, domain_id: 2, attrs: {}, created_at: nil, updated_at: nil, provider: nil, username: nil, password: nil, virtual: false, link: true, identifier: "", tag: "", attached_to: "", managed: true, mode: "balance-rr", attached_devices: "", bond_options: "", primary: true, provision: true, compute_attributes: {"bridge"=>"br6", "model"=>"virtio", "type"=>"bridge"}, ip6: "", subnet6_id: nil> assigned to   <Fog::Compute::Libvirt::Nic
 |     mac="52:54:00:e6:40:32",
 |     id=nil,
 |     type="bridge",
 |     network=nil,
 |     bridge="br6",
 |     model="virtio"
 |   >
2018-05-21 14:32:43 ac0d79f3 [app] [D] Processing task 'Create DHCP Settings for dev-testvm315.dc02.example.net' from 'Host::Managed Main'
2018-05-21 14:32:44 ac0d79f3 [app] [I] Create DHCP reservation dev-testvm315.dc02.example.net for dev-testvm315.dc02.example.net-52:54:00:e6:40:32/10.9.6.125
2018-05-21 14:32:44 ac0d79f3 [app] [D] DHCP reservation on net 10.9.6.0 with attrs: {:hostname=>"dev-testvm315.dc02.example.net", :mac=>"52:54:00:e6:40:32", :ip=>"10.9.6.125", :network=>"10.9.6.0", :nextServer=>"10.6.6.74", :name=>"dev-testvm315.dc02.example.net", :related_macs=>[]}
2018-05-21 14:32:45 47279a86 [app] [I] Started GET "/tasks/be975a31-8a75-4ac2-9e34-9115a1d3be54" for 10.10.10.144 at 2018-05-21 14:32:45 +0000
2018-05-21 14:32:45 47279a86 [app] [I] Processing by TasksController#show as */*
2018-05-21 14:32:45 47279a86 [app] [I]   Parameters: {"id"=>"be975a31-8a75-4ac2-9e34-9115a1d3be54"}
2018-05-21 14:32:45 47279a86 [app] [I] Current user: admin (administrator)
2018-05-21 14:32:45 47279a86 [app] [D] Setting current user thread-local variable to admin
2018-05-21 14:32:45 47279a86 [app] [I]   Rendered tasks/_list.html.erb (0.5ms)
2018-05-21 14:32:45 47279a86 [app] [I] Completed 200 OK in 8ms (Views: 1.0ms | ActiveRecord: 0.6ms)
2018-05-21 14:32:45 ac0d79f3 [app] [D] Processing task 'Deploy TFTP PXEGrub2 config for dev-testvm315.dc02.example.net' from 'Host::Managed Main'
2018-05-21 14:32:45 ac0d79f3 [app] [D] Setting current organization thread-local variable to none
2018-05-21 14:32:45 ac0d79f3 [app] [D] Setting current location thread-local variable to dc02
2018-05-21 14:32:45 ac0d79f3 [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:45 ac0d79f3 [app] [D] Setting current organization thread-local variable to none
2018-05-21 14:32:45 ac0d79f3 [app] [I] Skipping TFTP PXEGrub2 configuration for dev-testvm315.dc02.example.net
2018-05-21 14:32:45 ac0d79f3 [app] [D] Processing task 'Deploy TFTP PXELinux config for dev-testvm315.dc02.example.net' from 'Host::Managed Main'
2018-05-21 14:32:45 ac0d79f3 [app] [D] Setting current organization thread-local variable to none
2018-05-21 14:32:45 ac0d79f3 [app] [D] Setting current location thread-local variable to dc02
2018-05-21 14:32:45 ac0d79f3 [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:45 ac0d79f3 [app] [D] Setting current organization thread-local variable to none
2018-05-21 14:32:45 ac0d79f3 [app] [I] Skipping TFTP PXELinux configuration for dev-testvm315.dc02.example.net
2018-05-21 14:32:45 ac0d79f3 [app] [D] Processing task 'Deploy TFTP PXEGrub config for dev-testvm315.dc02.example.net' from 'Host::Managed Main'
2018-05-21 14:32:45 ac0d79f3 [app] [D] Setting current organization thread-local variable to none
2018-05-21 14:32:45 ac0d79f3 [app] [D] Setting current location thread-local variable to dc02
2018-05-21 14:32:45 ac0d79f3 [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:45 ac0d79f3 [app] [D] Setting current organization thread-local variable to none
2018-05-21 14:32:45 ac0d79f3 [app] [I] Skipping TFTP PXEGrub configuration for dev-testvm315.dc02.example.net
2018-05-21 14:32:45 ac0d79f3 [app] [D] Processing task 'Fetch TFTP boot files for dev-testvm315.dc02.example.net' from 'Host::Managed Main'
2018-05-21 14:32:45 ac0d79f3 [app] [I] Fetching required TFTP boot files for dev-testvm315.dc02.example.net
2018-05-21 14:32:45 ac0d79f3 [app] [D] Processing task 'Power up compute instance dev-testvm315.dc02.example.net' from 'Host::Managed Main'
2018-05-21 14:32:45 ac0d79f3 [app] [I] Powering up Compute instance for dev-testvm315.dc02.example.net
2018-05-21 14:32:46 a608e22d [app] [I] Started GET "/tasks/be975a31-8a75-4ac2-9e34-9115a1d3be54" for 10.10.10.144 at 2018-05-21 14:32:46 +0000
2018-05-21 14:32:46 a608e22d [app] [I] Processing by TasksController#show as */*
2018-05-21 14:32:46 a608e22d [app] [I]   Parameters: {"id"=>"be975a31-8a75-4ac2-9e34-9115a1d3be54"}
2018-05-21 14:32:46 a608e22d [app] [I] Current user: admin (administrator)
2018-05-21 14:32:46 a608e22d [app] [D] Setting current user thread-local variable to admin
2018-05-21 14:32:46 a608e22d [app] [I]   Rendered tasks/_list.html.erb (0.6ms)
2018-05-21 14:32:46 a608e22d [app] [I] Completed 200 OK in 9ms (Views: 1.1ms | ActiveRecord: 0.7ms)
2018-05-21 14:32:47 ac0d79f3 [app] [I] Processed 8 tasks from queue 'Host::Managed Main', completed 8/8
2018-05-21 14:32:47 ac0d79f3 [app] [D] Task 'Set up compute instance dev-testvm315.dc02.example.net' *completed*
2018-05-21 14:32:47 ac0d79f3 [app] [D] Task 'Query instance details for dev-testvm315.dc02.example.net' *completed*
2018-05-21 14:32:47 ac0d79f3 [app] [D] Task 'Create DHCP Settings for dev-testvm315.dc02.example.net' *completed*
2018-05-21 14:32:47 ac0d79f3 [app] [D] Task 'Deploy TFTP PXEGrub2 config for dev-testvm315.dc02.example.net' *completed*
2018-05-21 14:32:47 ac0d79f3 [app] [D] Task 'Deploy TFTP PXELinux config for dev-testvm315.dc02.example.net' *completed*
2018-05-21 14:32:47 ac0d79f3 [app] [D] Task 'Deploy TFTP PXEGrub config for dev-testvm315.dc02.example.net' *completed*
2018-05-21 14:32:47 ac0d79f3 [app] [D] Task 'Fetch TFTP boot files for dev-testvm315.dc02.example.net' *completed*
2018-05-21 14:32:47 ac0d79f3 [app] [D] Task 'Power up compute instance dev-testvm315.dc02.example.net' *completed*
2018-05-21 14:32:47 ac0d79f3 [notifications] [D] Notification event: UINotifications::DestroyHost - checking for notifications
2018-05-21 14:32:47 ac0d79f3 [app] [D] custom hook after_build on dev-testvm315.dc02.example.net will be executed if defined.
2018-05-21 14:32:47 ac0d79f3 [app] [I] Redirected to https://dev-foreman02.dc01.example.net/hosts/dev-testvm315.dc02.example.net
2018-05-21 14:32:47 ac0d79f3 [app] [I] Completed 302 Found in 9059ms (ActiveRecord: 113.0ms)
2018-05-21 14:32:47 b926212e [app] [I] Started GET "/hosts/dev-testvm315.dc02.example.net" for 10.10.10.144 at 2018-05-21 14:32:47 +0000
2018-05-21 14:32:47 b926212e [app] [I] Processing by HostsController#show as */*
2018-05-21 14:32:47 b926212e [app] [I]   Parameters: {"id"=>"dev-testvm315.dc02.example.net"}
2018-05-21 14:32:47 b926212e [app] [I] Current user: admin (administrator)
2018-05-21 14:32:47 b926212e [app] [D] Setting current user thread-local variable to admin
2018-05-21 14:32:47 b926212e [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:47 b926212e [app] [D] Deface: 2 overrides found for 'hosts/show'
2018-05-21 14:32:47 b926212e [app] [D] Deface: 'add_host_snapshot_tab' matched 1 times with 'ul'
2018-05-21 14:32:47 b926212e [app] [I] Deface: [WARNING] No :original defined for 'add_host_snapshot_tab', you should change its definition to include:
 |  :original => 'f38c09102c4fadf4ed483c9b31c37c32d2483917' 
2018-05-21 14:32:47 b926212e [app] [D] Deface: 'add_host_snapshots_tab_content' matched 1 times with 'div#myTabContent'
2018-05-21 14:32:47 b926212e [app] [I] Deface: [WARNING] No :original defined for 'add_host_snapshots_tab_content', you should change its definition to include:
 |  :original => '83a7dbfe2fa09adf3b8d6fa1a6c468bc32398c94' 
2018-05-21 14:32:47 b926212e [app] [I]   Rendering hosts/show.html.erb within layouts/application
2018-05-21 14:32:47 b926212e [app] [I]   Rendered hosts/show.html.erb within layouts/application (46.6ms)
2018-05-21 14:32:47 b926212e [app] [I]   Rendered layouts/_application_content.html.erb (0.6ms)
2018-05-21 14:32:47 b926212e [app] [I]   Rendering layouts/base.html.erb
2018-05-21 14:32:47 b926212e [app] [I]   Rendered home/_location_dropdown.html.erb (2.6ms)
2018-05-21 14:32:47 b926212e [app] [I]   Rendered home/_org_switcher.html.erb (3.2ms)
2018-05-21 14:32:47 b926212e [app] [I]   Rendered home/_user_dropdown.html.erb (1.5ms)
2018-05-21 14:32:47 b926212e [app] [I]   Rendered home/_topbar.html.erb (5.7ms)
2018-05-21 14:32:47 b926212e [app] [I]   Rendered home/_vertical_menu.html.erb (2.1ms)
2018-05-21 14:32:47 b926212e [app] [I]   Rendered home/_vertical_menu.html.erb (2.8ms)
2018-05-21 14:32:47 b926212e [app] [I]   Rendered home/_vertical_menu.html.erb (2.6ms)
2018-05-21 14:32:47 b926212e [app] [I]   Rendered home/_vertical_menu.html.erb (2.1ms)
2018-05-21 14:32:47 b926212e [app] [I]   Rendered home/_vertical_menu.html.erb (2.3ms)
2018-05-21 14:32:47 b926212e [app] [I]   Rendered home/_vertical_taxonomies.html.erb (2.6ms)
2018-05-21 14:32:47 b926212e [app] [I]   Rendered home/_vertical_menu.html.erb (1.0ms)
2018-05-21 14:32:47 b926212e [app] [I]   Rendered home/_navbar.html.erb (18.5ms)
2018-05-21 14:32:47 b926212e [app] [I]   Rendered layouts/base.html.erb (27.6ms)
2018-05-21 14:32:47 b926212e [app] [I] Completed 200 OK in 124ms (Views: 72.4ms | ActiveRecord: 6.2ms)
2018-05-21 14:32:48 f0681783 [app] [I] Started GET "/hosts/dev-testvm315.dc02.example.net/overview" for 10.10.10.144 at 2018-05-21 14:32:48 +0000
2018-05-21 14:32:48 6fcf1abd [app] [I] Started GET "/hosts/dev-testvm315.dc02.example.net/templates" for 10.10.10.144 at 2018-05-21 14:32:48 +0000
2018-05-21 14:32:48 f0681783 [app] [I] Processing by HostsController#overview as HTML
2018-05-21 14:32:48 f0681783 [app] [I]   Parameters: {"id"=>"dev-testvm315.dc02.example.net"}
2018-05-21 14:32:48 6fcf1abd [app] [I] Processing by HostsController#templates as HTML
2018-05-21 14:32:48 6fcf1abd [app] [I]   Parameters: {"id"=>"dev-testvm315.dc02.example.net"}
2018-05-21 14:32:48 f0681783 [app] [I] Current user: admin (administrator)
2018-05-21 14:32:48 f0681783 [app] [D] Setting current user thread-local variable to admin
2018-05-21 14:32:48 6fcf1abd [app] [I] Current user: admin (administrator)
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current user thread-local variable to admin
2018-05-21 14:32:48 f0681783 [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:48 f0681783 [app] [I]   Rendered hosts/_overview.html.erb (31.1ms)
2018-05-21 14:32:48 f0681783 [app] [I] Completed 200 OK in 50ms (Views: 34.4ms | ActiveRecord: 3.8ms)
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current organization thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current location thread-local variable to dc02
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current organization thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current location thread-local variable to dc02
2018-05-21 14:32:48 e314bd6c [app] [I] Started GET "/hosts/dev-testvm315.dc02.example.net/nics" for 10.10.10.144 at 2018-05-21 14:32:48 +0000
2018-05-21 14:32:48 e314bd6c [app] [I] Processing by HostsController#nics as HTML
2018-05-21 14:32:48 e314bd6c [app] [I]   Parameters: {"id"=>"dev-testvm315.dc02.example.net"}
2018-05-21 14:32:48 e314bd6c [app] [I] Current user: admin (administrator)
2018-05-21 14:32:48 e314bd6c [app] [D] Setting current user thread-local variable to admin
2018-05-21 14:32:48 e314bd6c [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current organization thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current location thread-local variable to dc02
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current organization thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current location thread-local variable to dc02
2018-05-21 14:32:48 e314bd6c [app] [I]   Rendered hosts/_nics.html.erb (8.3ms)
2018-05-21 14:32:48 e314bd6c [app] [I] Completed 200 OK in 23ms (Views: 12.0ms | ActiveRecord: 3.1ms)
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current organization thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current location thread-local variable to dc02
2018-05-21 14:32:48 5bf2ada4 [app] [I] Started GET "/hosts/dev-testvm315.dc02.example.net/resources?range=7" for 10.10.10.144 at 2018-05-21 14:32:48 +0000
2018-05-21 14:32:48 5bf2ada4 [app] [I] Processing by HostsController#resources as HTML
2018-05-21 14:32:48 5bf2ada4 [app] [I]   Parameters: {"range"=>"7", "id"=>"dev-testvm315.dc02.example.net"}
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current organization thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current location thread-local variable to dc02
2018-05-21 14:32:48 5bf2ada4 [app] [I] Current user: admin (administrator)
2018-05-21 14:32:48 5bf2ada4 [app] [D] Setting current user thread-local variable to admin
2018-05-21 14:32:48 5bf2ada4 [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:48 5bf2ada4 [app] [I]   Rendered hosts/_resources.html.erb (2.7ms)
2018-05-21 14:32:48 5bf2ada4 [app] [I] Completed 200 OK in 12ms (Views: 5.2ms | ActiveRecord: 0.8ms)
2018-05-21 14:32:48 a95257e8 [app] [I] Started GET "/hosts/dev-testvm315.dc02.example.net/runtime?range=7" for 10.10.10.144 at 2018-05-21 14:32:48 +0000
2018-05-21 14:32:48 a95257e8 [app] [I] Processing by HostsController#runtime as HTML
2018-05-21 14:32:48 a95257e8 [app] [I]   Parameters: {"range"=>"7", "id"=>"dev-testvm315.dc02.example.net"}
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current organization thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current location thread-local variable to dc02
2018-05-21 14:32:48 a95257e8 [app] [I] Current user: admin (administrator)
2018-05-21 14:32:48 a95257e8 [app] [D] Setting current user thread-local variable to admin
2018-05-21 14:32:48 a95257e8 [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current organization thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current location thread-local variable to dc02
2018-05-21 14:32:48 a95257e8 [app] [I]   Rendered hosts/_runtime.html.erb (2.6ms)
2018-05-21 14:32:48 a95257e8 [app] [I] Completed 200 OK in 11ms (Views: 5.0ms | ActiveRecord: 0.8ms)
2018-05-21 14:32:48 845403da [app] [I] Started GET "/hosts/dev-testvm315.dc02.example.net/vm" for 10.10.10.144 at 2018-05-21 14:32:48 +0000
2018-05-21 14:32:48 845403da [app] [I] Processing by HostsController#vm as HTML
2018-05-21 14:32:48 845403da [app] [I]   Parameters: {"id"=>"dev-testvm315.dc02.example.net"}
2018-05-21 14:32:48 845403da [app] [I] Current user: admin (administrator)
2018-05-21 14:32:48 845403da [app] [D] Setting current user thread-local variable to admin
2018-05-21 14:32:48 845403da [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current organization thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current location thread-local variable to dc02
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [D] Setting current organization thread-local variable to none
2018-05-21 14:32:48 6fcf1abd [app] [I]   Rendered hosts/_templates.html.erb (17.6ms)
2018-05-21 14:32:48 6fcf1abd [app] [I] Completed 200 OK in 210ms (Views: 20.6ms | ActiveRecord: 19.1ms)
2018-05-21 14:32:49 4c679445 [app] [I] Started GET "/notification_recipients" for 10.10.10.144 at 2018-05-21 14:32:49 +0000
2018-05-21 14:32:49 4c679445 [app] [I] Processing by NotificationRecipientsController#index as JSON
2018-05-21 14:32:49 4c679445 [app] [I] Current user: admin (administrator)
2018-05-21 14:32:49 4c679445 [app] [D] Setting current user thread-local variable to admin
2018-05-21 14:32:49 4c679445 [app] [D] Setting current location thread-local variable to none
2018-05-21 14:32:49 4c679445 [notifications] [D] Cache Hit: notification, reading cache for notification-4
2018-05-21 14:32:49 4c679445 [app] [D] Body: {"notifications":[]}
2018-05-21 14:32:49 4c679445 [app] [I] Completed 200 OK in 6ms (Views: 0.2ms | ActiveRecord: 0.2ms)
2018-05-21 14:32:49 845403da [app] [I]   Rendered compute_resources_vms/show/_libvirt.html.erb (419.9ms)
2018-05-21 14:32:49 845403da [app] [I]   Rendered compute_resources_vms/_details.html.erb (429.2ms)
2018-05-21 14:32:49 845403da [app] [I] Completed 200 OK in 1047ms (Views: 436.2ms | ActiveRecord: 0.6ms)

Gwmngilfen · May 21, 2018, 8:33pm

oooh, so:

2018-05-21 14:32:38 ac0d79f3 [app] [D] Enqueued task 'Deploy TFTP PXEGrub2 config for dev-testvm315.dc02.example.net' to 'Host::Managed Main' queue
2018-05-21 14:32:38 ac0d79f3 [app] [D] Enqueued task 'Deploy TFTP PXELinux config for dev-testvm315.dc02.example.net' to 'Host::Managed Main' queue
2018-05-21 14:32:38 ac0d79f3 [app] [D] Enqueued task 'Deploy TFTP PXEGrub config for dev-testvm315.dc02.example.net' to 'Host::Managed Main' queue

Looks promising, and we see the DHCP and Wget logs surrounding it in the proxy logs. @ekohl / @iNecas does the PXE file get written via Dynflow now? Should we be looking in the task console to see what’s going on here?

lzap · May 22, 2018, 2:21pm

Beware, two things to mention.

Foreman 1.14+ now has three PXE loader types, depending on what you associate, you can get as many as 0-3 deploy steps. We used to raise error when PXELinux was missing, this now has changed and if will skip PXE template render step if there is nothing associated.

Our AR tasks had a little overhaul, logging was modified a bit and it’s ending up in the correct logger (app instead sql which was turned off by default). We also do not orchestrate tasks twice. This could misled you to thinking this has anything to do with dynflow.

Gwmngilfen · May 22, 2018, 2:24pm

Fair enough. So where would we look next for the files not being deployed? The proxy logs don’t show it even receiving the request, even though it does get the ones before and after it, so Dynflow was pretty much my last guess

lzap · May 22, 2018, 2:49pm

It is right there below:

2018-05-21 14:32:45 ac0d79f3 [app] [D] Processing task 'Deploy TFTP PXEGrub2 config for dev-testvm315.dc02.example.net' from 'Host::Managed Main'
2018-05-21 14:32:45 ac0d79f3 [app] [I] Skipping TFTP PXEGrub2 configuration for dev-testvm315.dc02.example.net

The “Skipping TFTP” message looks to appear when the template generates zero content (returns nil or false). Check the contents of your template. Maybe some errors?

Gwmngilfen · May 22, 2018, 2:51pm

D’oh, did not scroll down far enough, good catch. Would debug logs say more about why it’s skipping? @trinaryouroboros back to you I think

trinaryouroboros · May 22, 2018, 7:05pm

I think the clue was the fact I was using the Puppet Forge module, turns out we were behind:

mod 'theforeman/foreman', '8.1.1'
mod 'theforeman/foreman_proxy', '6.0.3'
mod 'theforeman/tftp', '3.0.2'

We upgraded these to:

mod 'theforeman-foreman', '9.0.1'
mod 'theforeman-foreman_proxy', '7.1.0'
mod 'theforeman-tftp', '4.0.0'

It works great now after deploying new version.

TFTP daemon doesn’t autostart for some reason but that’s our config management problem.

lzap · May 23, 2018, 3:04pm

TFTP daemon is managed by xinetd by default.