Discovered hosts have no provisioning token on initial build

lzap · November 2, 2020, 2:24pm

What is your token expiration set in Administer - Settings - Provisioning again? This really looks like it expires.

ehazan · November 2, 2020, 3:51pm

Removed the host from foreman, rebooted it to discovery more and provisioned it again.
Still have the same issue, I can see a token on the error message from the host but it’s not the same as I see on the UI
Our token expiration is 360

lzap · November 2, 2020, 4:13pm

Wait, do you have TFTP smart proxy associated with your proxy? If it’s not, the token on the TFTP server might be some leftover no longer valid. Pastebin the transaction from production.log when the host is being provisioned - in debug mode with all loggers enabled (except audit/sql). The last paste does have many loggers disabled so it is not very useful. Also it is a mix of requests, I am only interested in the particular one (use grep please).

stiege · November 4, 2020, 11:08am

Hi @lzap,

I’ve been working with @ehazan on this issue.

I think this should indicate we do have the tftp smart proxy configured from the server

You asked us to increase our logging but we’re already on debug with nothing disabled.

I re-ran a build while running a tcpdump and watching the tftp directory. From the smart proxy side everything looks fine:

When the host was deleted from the server the tftp files were successfully cleaned
When the machine is rebooted it correctly enters discovery.
When “build” is clicked via the GUI everything seems fine from the POV from the smart proxy. New files are created. However when looking at the template instantiation on the server, the token is different to what was posted to the smart proxy. I’m unsure if this necessarily means something has gone wrong. In this case, the token on the smart-proxy was c97b7384-0736-4dc5-b346-384d75c0102a while the server template preview view showed 6bdbfacb-300d-422c-b986-a85acd50c5c5.
The problem is finally hit when the host calls to the proxy with the token and the proxy indicates an internal server error. I note from reading other threads this is normally seen as an indication of a stale token; hopefully we’re showing enough evidence to show that doesn’t seem to be the case here.

Failed to proxy /provision for {"token"=>"c97b7384-0736-4dc5-b346-384d75c0102a", "splat"=>[], "captures"=>["provision"], "kind"=>"provision"}: Error retrieving unattended/provision for {"token"=>"c97b7384-0736-4dc5-b346-384d75c0102a", :url=>"http://<smartproxy>.com:8440"} from <server>.com: Net::HTTPNotFound

My main questions would be:

Is it an issue that the token in the template view on the server differs from what the smart-proxy and host are being provided with?
How can we increase logging further on the server? Current settings are:

# Log settings for the current environment can be adjusted by adding them
# here. For example, if you want to increase the log level.
:logging:
  :level: debug
  :production:
    :type: file
    :layout: pattern

# Individual logging types can be toggled on/off here
:loggers:

This seems to be the part of the production.log on the server side that captures the failure:

2020-11-03T10:20:42 [I|app|925449af] Started GET "/unattended/provision?token=c97b7384-0736-4dc5-b346-384d75c0102a&url=http%3A%2F%2F<smartproxy>.com%3A8440" for <smartproxy>.com at 2020-11-03 10:20:42 -0500
2020-11-03T10:20:42 [I|app|925449af] Processing by UnattendedController#host_template as TEXT
2020-11-03T10:20:42 [I|app|925449af]   Parameters: {"token"=>"c97b7384-0736-4dc5-b346-384d75c0102a", "url"=>"http://<smartproxy>.com:8440", "kind"=>"provision", "unattended"=>{}}
2020-11-03T10:20:42 [D|app|925449af] Cache read: settings/unattended_url
2020-11-03T10:20:42 [D|app|925449af] Cache fetch_hit: settings/unattended_url
2020-11-03T10:20:42 [D|app|925449af] Cache read: settings/remote_addr
2020-11-03T10:20:42 [D|app|925449af] Cache fetch_hit: settings/remote_addr
2020-11-03T10:20:42 [E|app|925449af] unattended: unable to find a host that matches the request from 10.124.237.172
2020-11-03T10:20:42 [I|app|925449af]   Rendering text template
2020-11-03T10:20:42 [I|app|925449af]   Rendered text template (0.1ms)
2020-11-03T10:20:42 [I|app|925449af] Completed 404 Not Found in 24ms (Views: 1.1ms | ActiveRecord: 4.6ms)
2020-11-03T10:20:42 [D|app|925449af] Cache write: _session_id:083397b72853550198e6c226fcb5723d ({:expires_in=>86400})

I had some accompanying images for the post that showed the evidence from the packet capture, however as a new user on the forum I’m unable to post more than one.

lzap · November 4, 2020, 12:38pm

Yes, once token is generated and TFTP/PXE files are deployed, it must not change otherwise provisioning will not match them.

Can you list all plugins you have installed and all Foreman Hooks, if you happen to have any? This looks like some 3rd party triggers build or something.

The level is DEBUG which is correct, I thought that :loggers: section down below is not set but it’s okay. Anyway, you showed me log when host tries to get template (and it fails with 404), this is too late. I need to see the transaction when a host gets provisioned (discovery provisioning). Please only grep this HTTP PATCH request.

The result (404) is just a consequence of the fact that token gets lost and is replaced with a new one.

stiege · November 4, 2020, 3:22pm

I’ll need to confirm with the team what all our hooks/plugins are. I think we’re fairly minimal but will confirm later.

In terms of logs on the server:

Host being removed after I deleted via the GUI (this matches up with the pcap I’ve got):

2020-11-03T10:09:25 [D|app|e17486ae] Task 'Delete TFTP PXELinux config for lxtst-ob-074.bloomberg.com' *completed*
2020-11-03T10:09:25 [D|app|e17486ae] Task 'Delete TFTP PXEGrub2 config for lxtst-ob-074.bloomberg.com' *completed*
2020-11-03T10:09:25 [D|app|e17486ae] Task 'Delete TFTP PXEGrub config for lxtst-ob-074.bloomberg.com' *completed*
2020-11-03T10:09:25 [D|app|e17486ae] Task 'Delete TFTP iPXE config for <old-host-name>.com' *completed*

Debug destroy events such as:

2020-11-03T10:09:25 [I|aud|e17486ae] Host::Base (7459) destroy event on pxe_loader Grub2 UEFI
2020-11-03T10:09:25 [I|aud|e17486ae] Host::Base (7459) destroy event on initiated_at 
2020-11-03T10:09:25 [I|aud|e17486ae] Host::Base (7459) destroy event on build_errors 
2020-11-03T10:09:25 [D|not|e17486ae] Notification event: Hosts::Destroy - checking for notifications
2020-11-03T10:09:25 [D|not|e17486ae] Removing all notifications for host: <old-host-name>.bloomberg.com

I believe this is the section you’re after:

2020-11-03T10:15:18 [I|app|86e1bec4] Started POST "/api/v2/discovered_hosts/facts" for 10.124.245.64 at 2020-11-03 10:15:18 -0500
2020-11-03T10:15:18 [I|app|86e1bec4] Processing by Api::V2::DiscoveredHostsController#facts as JSON
2020-11-03T10:15:18 [I|app|86e1bec4]   Parameters: {"facts"=>"[FILTERED]", "apiv"=>"v2", "discovered_host"=>{"facts"=>"[FILTERED]"}}

… (skip Nic::Managed (8256) create event type messages)

2020-11-03T10:15:21 [I|app|86e1bec4] Import facts for 'host-70106fa9dda0' completed. Added: 298, Updated: 0, Deleted 0 facts

… (skip interface facts and cache messages)

2020-11-03T10:15:22 [D|app|86e1bec4] Body: {"id":7460,"name":"host-70106fa9dda0","last_compile":null,"last_report":"2020-11-03T15:15:18.633Z","updated_at":"2020-11-
03T15:15:22.420Z","created_at":"2020-11-03T15:15:18.526Z","root_pass":null,"architecture_id":null,"operatingsystem_id":null,"environment_id":null,"ptable_id":null,"
medium_id":null,"build":false,"comment":null,"disk":null,"installed_at":null,"model_id":2,"hostgroup_id":null,"owner_id":1,"owner_type":"User","enabled":true,"puppe
t_ca_proxy_id":null,"managed":false,"use_image":null,"image_file":null,"uuid":null,"compute_resource_id":null,"puppet_proxy_id":null,"certname":null,"image_id":null
,"organization_id":3,"location_id":2,"otp":null,"realm_id":null,"compute_profile_id":null,"provision_method":null,"grub_pass":"","discovery_rule_id":null,"global_st
atus":0,"lookup_value_matcher":null,"pxe_loader":null,"initiated_at":null,"build_errors":null}
2020-11-03T10:15:22 [I|app|86e1bec4] Completed 201 Created in 4387ms (Views: 2.4ms | ActiveRecord: 1795.5ms)

… (skip cache and a few rendering messages)

2020-11-03T10:15:44 [D|app|8cbc48fd] Body: {"notifications":[{"id":709,"seen":false,"level":"info","text":"One or more hosts have been discovered","created_at":"2020-11-03T15:15:22.506Z","group":"Hosts","actions":{"links":[{"href":"/discovered_hosts","title":"Details"}]}}]}
2020-11-03T10:15:44 [I|app|8cbc48fd] Completed 200 OK in 67ms (Views: 0.2ms | ActiveRecord: 23.2ms)
2020-11-03T10:15:44 [D|app|8cbc48fd] Cache write: _session_id:2aaf5154720f0530bab08633a272cc10 ({:expires_in=>86400})
2020-11-03T10:15:46 [I|app|f7d27fee] Started GET "/discovered_hosts/host-70106fa9dda0" for 10.124.245.64 at 2020-11-03 10:15:46 -0500
2020-11-03T10:15:46 [D|app|f7d27fee] Cache read: _session_id:2aaf5154720f0530bab08633a272cc10
2020-11-03T10:15:46 [I|app|f7d27fee] Processing by DiscoveredHostsController#show as HTML
2020-11-03T10:15:46 [I|app|f7d27fee]   Parameters: {"id"=>"host-70106fa9dda0"}

… skip cache messages

2020-11-03T10:15:46 [W|app|f7d27fee] unable to detect breadcrumb title name in for discovered_hosts, defaulting to name
2020-11-03T10:15:46 [D|app|f7d27fee] <NameError> Could not find resource class for resource discovered_host
        /usr/share/foreman/app/controllers/concerns/find_common.rb:31:in `resource_class'
        /usr/share/foreman/app/services/breadcrumbs_options.rb:23:in `resource_class'
        /usr/share/foreman/app/services/breadcrumbs_options.rb:68:in `model_name_field'
        /usr/share/foreman/app/services/breadcrumbs_options.rb:81:in `resource'
        /usr/share/foreman/app/services/breadcrumbs_options.rb:16:in `bar_props'
        /usr/share/foreman/app/helpers/layout_helper.rb:83:in `mount_breadcrumbs'
...
        /opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
        /opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/request_id.rb:27:in `call'
        /opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.6/lib/rack/method_override.rb:22:in `call'
        /opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.6/lib/rack/runtime.rb:22:in `call'
        /opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
        /opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
        /opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
        /opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.6/lib/rack/sendfile.rb:111:in `call'
        /opt/theforeman/tfm/root/usr/share/gems/gems/secure_headers-6.3.0/lib/secure_headers/middleware.rb:11:in `call'
        /opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/engine.rb:524:in `call'
        /opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/railtie.rb:190:in `public_send'
        /opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/railtie.rb:190:in `method_missing'
        /opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.6/lib/rack/urlmap.rb:68:in `block in call'
        /opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.6/lib/rack/urlmap.rb:53:in `each'
        /opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.6/lib/rack/urlmap.rb:53:in `call'
        /usr/share/passenger/phusion_passenger/rack/thread_handler_extension.rb:74:in `process_request'
        /usr/share/passenger/phusion_passenger/request_handler/thread_handler.rb:141:in `accept_and_process_next_request'
        /usr/share/passenger/phusion_passenger/request_handler/thread_handler.rb:109:in `main_loop'
        /usr/share/passenger/phusion_passenger/request_handler.rb:455:in `block (3 levels) in start_threads'
        /opt/theforeman/tfm/root/usr/share/gems/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2020-11-03T10:15:46 [I|app|f7d27fee]   Rendered layouts/_application_content.html.erb (3.9ms)
2020-11-03T10:15:46 [I|app|f7d27fee]   Rendering layouts/base.html.erb
2020-11-03T10:15:46 [D|app|f7d27fee] Cache read: views/tabs_and_title_records-23 ({:skip_digest=>true})
2020-11-03T10:15:46 [D|app|f7d27fee] Cache read: settings/lab_features
2020-11-03T10:15:46 [D|app|f7d27fee] Cache fetch_hit: settings/lab_features
2020-11-03T10:15:46 [D|app|f7d27fee] Cache read: settings/entries_per_page
2020-11-03T10:15:46 [D|app|f7d27fee] Cache fetch_hit: settings/entries_per_page
2020-11-03T10:15:46 [D|app|f7d27fee] Cache write: views/tabs_and_title_records-23 ({:skip_digest=>true})
2020-11-03T10:15:46 [I|app|f7d27fee]   Rendered layouts/base.html.erb (95.9ms)
2020-11-03T10:15:46 [I|app|f7d27fee] Completed 200 OK in 580ms (Views: 278.6ms | ActiveRecord: 93.0ms)

… (cache messages)

I thought maybe this was odd, with the host discovery message appearing twice here. The one at 10:16:05 looks to occur concurrently with me clicking the build button (quick_submit=Create+Host); 10 seconds or so in between which is probably me seeing the host appear in discovered hosts and then clicking the button. This also occurs above at 10:15:44, so 3 times in total (all of which I believe are for the same host).

2020-11-03T10:15:54 [I|app|0da65968] Started GET "/notification_recipients" for 10.124.245.64 at 2020-11-03 10:15:54 -0500
2020-11-03T10:15:54 [D|app|0da65968] Cache read: _session_id:2aaf5154720f0530bab08633a272cc10
2020-11-03T10:15:54 [I|app|0da65968] Processing by NotificationRecipientsController#index as JSON
2020-11-03T10:15:54 [D|app|0da65968] Cache delete: views/tabs_and_title_records-23
2020-11-03T10:15:54 [D|tax|0da65968] Current location set to Default Location
2020-11-03T10:15:54 [D|tax|0da65968] Current organization set to none
2020-11-03T10:15:54 [D|app|0da65968] Cache read: notification-23
2020-11-03T10:15:54 [D|not|0da65968] Cache Hit: notification, reading cache for notification-23
2020-11-03T10:15:54 [D|app|0da65968] Body: {"notifications":[{"id":709,"seen":false,"level":"info","text":"One or more hosts have been discovered","created_at":"202
0-11-03T15:15:22.506Z","group":"Hosts","actions":{"links":[{"href":"/discovered_hosts","title":"Details"}]}}]}
2020-11-03T10:15:54 [I|app|0da65968] Completed 200 OK in 53ms (Views: 0.2ms | ActiveRecord: 18.0ms)
2020-11-03T10:15:54 [D|app|0da65968] Cache write: _session_id:2aaf5154720f0530bab08633a272cc10 ({:expires_in=>86400})
2020-11-03T10:16:05 [I|app|cbbc739e] Started GET "/notification_recipients" for 10.124.245.64 at 2020-11-03 10:16:05 -0500
2020-11-03T10:16:05 [D|app|cbbc739e] Cache read: _session_id:2aaf5154720f0530bab08633a272cc10
2020-11-03T10:16:05 [I|app|cbbc739e] Processing by NotificationRecipientsController#index as JSON
2020-11-03T10:16:05 [D|app|cbbc739e] Cache delete: views/tabs_and_title_records-23
2020-11-03T10:16:05 [D|tax|cbbc739e] Current location set to Default Location
2020-11-03T10:16:05 [D|tax|cbbc739e] Current organization set to none
2020-11-03T10:16:05 [D|app|cbbc739e] Cache read: notification-23
2020-11-03T10:16:05 [D|not|cbbc739e] Cache Hit: notification, reading cache for notification-23
2020-11-03T10:16:05 [D|app|cbbc739e] Body: {"notifications":[{"id":709,"seen":false,"level":"info","text":"One or more hosts have been discovered","created_at":"2020-11-03T15:15:22.506Z","group":"Hosts","actions":{"links":[{"href":"/discovered_hosts","title":"Details"}]}}]}
2020-11-03T10:16:05 [I|app|cbbc739e] Completed 200 OK in 54ms (Views: 0.2ms | ActiveRecord: 18.0ms)
2020-11-03T10:16:05 [D|app|cbbc739e] Cache write: _session_id:2aaf5154720f0530bab08633a272cc10 ({:expires_in=>86400})
2020-11-03T10:16:05 [I|app|5f90a961] Started GET "/discovered_hosts/host-70106fa9dda0/edit?utf8=%E2%9C%93&host%5Bhostgroup_id%5D=33&host%5Borganization_id%5D=3&host%5Blocation_id%5D=2&quick_submit=Create+Host" for 10.124.245.64 at 2020-11-03 10:16:05 -0500
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: _session_id:2aaf5154720f0530bab08633a272cc10
2020-11-03T10:16:05 [I|app|5f90a961] Processing by DiscoveredHostsController#edit as HTML
2020-11-03T10:16:05 [I|app|5f90a961]   Parameters: {"utf8"=>"✓", "host"=>{"hostgroup_id"=>"33", "organization_id"=>"3", "location_id"=>"2"}, "quick_submit"=>"Create Host", "id"=>"host-70106fa9dda0"}

From there we get onto the creation of boot files and config which I understand isn’t interesting:

2020-11-03T10:16:06 [D|app|5f90a961] Enqueued task 'Deploy TFTP PXELinux config for host-70106fa9dda0.bloomberg.com' to 'Host::Managed Main' queue
2020-11-03T10:16:06 [D|app|5f90a961] Enqueued task 'Deploy TFTP PXEGrub2 config for host-70106fa9dda0.bloomberg.com' to 'Host::Managed Main' queue
2020-11-03T10:16:06 [D|app|5f90a961] Enqueued task 'Deploy TFTP PXEGrub config for host-70106fa9dda0.bloomberg.com' to 'Host::Managed Main' queue
2020-11-03T10:16:06 [D|app|5f90a961] Enqueued task 'Deploy TFTP iPXE config for host-70106fa9dda0.bloomberg.com' to 'Host::Managed Main' queue
2020-11-03T10:16:06 [D|app|5f90a961] Enqueued task 'Fetch TFTP boot files for host-70106fa9dda0.bloomberg.com' to 'Host::Managed Main' queue

lzap · November 5, 2020, 9:44am

No, I said HTTP PATCH not POST. This is when a host gets discovered, that’s all fine. When you click on Provision, then there should be PATCH HTTP call that actually turns Discovered host into Managed host. A lot is going on in our orchestration stack, including generating the token. That’s what I am interested in.

Discovered hosts send their facts over and over again, by default the interval is 15 minutes, this is configurable.

stiege · November 5, 2020, 9:52am

Yeah, so I don’t believe there was a PATCH relating to the process or at least I’m struggling to find it. Sorry I should have mentioned.

As you can see, this one occurs much later, you said it should occur before the other information I posted.

/root # grep PATCH production.log-20201103 
/root # grep PATCH production.log-20201104 
2020-11-03T11:12:55 [I|app|822afcbf] Started PATCH "/smart_proxies/2-fmspx1-bdns-bloomberg-com" for 10.124.237.172 at 2020-11-03 11:12:55 -0500

lzap · November 5, 2020, 9:57am

It should be there, the moment you click on quick_submit. Grep that, that’s the request I am interested in.

stiege · November 5, 2020, 10:06am

I thought that was above (see the quick_submit in there):

2020-11-03T10:16:05 [I|app|5f90a961] Started GET "/discovered_hosts/host-70106fa9dda0/edit?utf8=%E2%9C%93&host%5Bhostgroup_id%5D=33&host%5Borganization_id%5D=3&host%5Blocation_id%5D=2&quick_submit=Create+Host" for 10.124.245.64 at 2020-11-03 10:16:05 -0500
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: _session_id:2aaf5154720f0530bab08633a272cc10
2020-11-03T10:16:05 [I|app|5f90a961] Processing by DiscoveredHostsController#edit as HTML
2020-11-03T10:16:05 [I|app|5f90a961]   Parameters: {"utf8"=>"✓", "host"=>{"hostgroup_id"=>"33", "organization_id"=>"3", "location_id"=>"2"}, "quick_submit"=>"Create Host", "id"=>"host-70106fa9dda0"}

But as you say, it’s not a PATCH. If grep doesn’t find any other PATCHs then I’m not sure I follow your logic for believing it must be in there.

Here’s the whole quick_submit section again with cache messages:

2020-11-03T10:16:05 [D|app|cbbc739e] Body: {"notifications":[{"id":709,"seen":false,"level":"info","text":"One or more hosts have been discovered","created_at":"2020-11-03T15:15:22.506Z","group":"Hosts","actions":{"links":[{"href":"/discovered_hosts","title":"Details"}]}}]}
2020-11-03T10:16:05 [I|app|cbbc739e] Completed 200 OK in 54ms (Views: 0.2ms | ActiveRecord: 18.0ms)
2020-11-03T10:16:05 [D|app|cbbc739e] Cache write: _session_id:2aaf5154720f0530bab08633a272cc10 ({:expires_in=>86400})
2020-11-03T10:16:05 [I|app|5f90a961] Started GET "/discovered_hosts/host-70106fa9dda0/edit?utf8=%E2%9C%93&host%5Bhostgroup_id%5D=33&host%5Borganization_id%5D=3&host%5Blocation_id%5D=2&quick_submit=Create+Host" for 10.124.245.64 at 2020-11-03 10:16:05 -0500
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: _session_id:2aaf5154720f0530bab08633a272cc10
2020-11-03T10:16:05 [I|app|5f90a961] Processing by DiscoveredHostsController#edit as HTML
2020-11-03T10:16:05 [I|app|5f90a961]   Parameters: {"utf8"=>"✓", "host"=>{"hostgroup_id"=>"33", "organization_id"=>"3", "location_id"=>"2"}, "quick_submit"=>"Create Host", "id"=>"host-70106fa9dda0"}
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/authorize_login_delegation
2020-11-03T10:16:05 [D|app|5f90a961] Cache fetch_hit: settings/authorize_login_delegation
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/authorize_login_delegation
2020-11-03T10:16:05 [D|app|5f90a961] Cache fetch_hit: settings/authorize_login_delegation
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/idle_timeout
2020-11-03T10:16:05 [D|app|5f90a961] Cache fetch_hit: settings/idle_timeout
2020-11-03T10:16:05 [D|app|5f90a961] Cache delete: views/tabs_and_title_records-23
2020-11-03T10:16:05 [D|tax|5f90a961] Current location set to Default Location
2020-11-03T10:16:05 [D|tax|5f90a961] Current organization set to none
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/append_domain_name_for_hosts
2020-11-03T10:16:05 [D|app|5f90a961] Cache fetch_hit: settings/append_domain_name_for_hosts
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/append_domain_name_for_hosts
2020-11-03T10:16:05 [D|app|5f90a961] Cache fetch_hit: settings/append_domain_name_for_hosts
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/append_domain_name_for_hosts
2020-11-03T10:16:05 [D|app|5f90a961] Cache fetch_hit: settings/append_domain_name_for_hosts
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/bmc_credentials_accessible
2020-11-03T10:16:05 [D|app|5f90a961] Cache fetch_hit: settings/bmc_credentials_accessible
2020-11-03T10:16:05 [D|tax|5f90a961] Current organization set to none
2020-11-03T10:16:05 [D|tax|5f90a961] Current location set to none
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/discovery_clean_facts
2020-11-03T10:16:05 [D|app|5f90a961] Cache generate: settings/discovery_clean_facts
2020-11-03T10:16:05 [D|app|5f90a961] Cache write: settings/discovery_clean_facts
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/token_duration
2020-11-03T10:16:05 [D|app|5f90a961] Cache fetch_hit: settings/token_duration
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/token_duration
2020-11-03T10:16:05 [D|app|5f90a961] Cache fetch_hit: settings/token_duration
2020-11-03T10:16:05 [D|app|5f90a961] Not suggesting IP Address for 10.122.75.128/26 as IPAM is disabled
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/append_domain_name_for_hosts
2020-11-03T10:16:05 [D|app|5f90a961] Cache fetch_hit: settings/append_domain_name_for_hosts
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/append_domain_name_for_hosts
2020-11-03T10:16:05 [D|app|5f90a961] Cache fetch_hit: settings/append_domain_name_for_hosts
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/append_domain_name_for_hosts
2020-11-03T10:16:05 [D|app|5f90a961] Cache fetch_hit: settings/append_domain_name_for_hosts
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/append_domain_name_for_hosts
2020-11-03T10:16:05 [D|app|5f90a961] Cache fetch_hit: settings/append_domain_name_for_hosts
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/token_duration
2020-11-03T10:16:05 [D|app|5f90a961] Cache fetch_hit: settings/token_duration
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/token_duration
2020-11-03T10:16:05 [D|app|5f90a961] Cache fetch_hit: settings/token_duration
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/token_duration
2020-11-03T10:16:05 [D|app|5f90a961] Cache fetch_hit: settings/token_duration
2020-11-03T10:16:05 [D|app|5f90a961] Cache read: settings/token_duration
2020-11-03T10:16:05 [D|app|5f90a961] Cache fetch_hit: settings/token_duration
2020-11-03T10:16:05 [D|tax|5f90a961] Current organization set to <org>
2020-11-03T10:16:05 [D|tax|5f90a961] Current location set to Default Location
2020-11-03T10:16:06 [D|tax|5f90a961] Current location set to none
2020-11-03T10:16:06 [D|tax|5f90a961] Current organization set to none
2020-11-03T10:16:06 [D|app|5f90a961] Enqueued task 'Deploy TFTP PXELinux config for host-70106fa9dda0.bloomberg.com' to 'Host::Managed Main' queue
2020-11-03T10:16:06 [D|app|5f90a961] Enqueued task 'Deploy TFTP PXEGrub2 config for host-70106fa9dda0.bloomberg.com' to 'Host::Managed Main' queue
2020-11-03T10:16:06 [D|app|5f90a961] Enqueued task 'Deploy TFTP PXEGrub config for host-70106fa9dda0.bloomberg.com' to 'Host::Managed Main' queue
2020-11-03T10:16:06 [D|app|5f90a961] Enqueued task 'Deploy TFTP iPXE config for host-70106fa9dda0.bloomberg.com' to 'Host::Managed Main' queue
2020-11-03T10:16:06 [D|app|5f90a961] Enqueued task 'Fetch TFTP boot files for host-70106fa9dda0.bloomberg.com' to 'Host::Managed Main' queue

fmsrv1-rr-084 /root # grep quick_submit production.log-20201103 
fmsrv1-rr-084 /root # grep quick_submit production.log-20201104 
2020-11-03T10:16:05 [I|app|5f90a961] Started GET "/discovered_hosts/host-70106fa9dda0/edit?utf8=%E2%9C%93&host%5Bhostgroup_id%5D=33&host%5Borganization_id%5D=3&host%5Blocation_id%5D=2&quick_submit=Create+Host" for 10.124.245.64 at 2020-11-03 10:16:05 -0500
2020-11-03T10:16:05 [I|app|5f90a961]   Parameters: {"utf8"=>"✓", "host"=>{"hostgroup_id"=>"33", "organization_id"=>"3", "location_id"=>"2"}, "quick_submit"=>"Create Host", "id"=>"host-70106fa9dda0"}

lzap · November 6, 2020, 9:05am

Oh right the request is GET, this is a small bug, it should have been PATCH I haven’t realized this.

Anyway, here is a small debugging improvement, can you try again with this? Then show me this request again:

stiege · November 6, 2020, 11:57am

Looks like progress:

fmsrv1-rr-084 /root # grep 'Building token' /var/log/foreman/production.log
2020-11-06T06:18:15 [D|app|0b11240f] Building token starting with 841fd0 SHA256:7ae9470d7b6adfd4199af5a7b58e71c00a709ea56f5f20866abd92eb57433dd7
2020-11-06T06:18:17 [D|app|0b11240f] Building token starting with 21579a SHA256:8d980aedf553fb7ff22d5cc503f9b4df3402a7f9b730ee9aba2be551b6042824

2020-11-06T06:17:55 [D|app|41a7aa50] Body: {"notifications":[{"id":722,"seen":false,"level":"info","text":"One or more hosts have been discovered","created_at":"2020-11-06T11:16:46.185Z","group":"Hosts","actions":{"links":[{"href":"/discovered_hosts","title":"Details"}]}}]}
2020-11-06T06:17:55 [I|app|41a7aa50] Completed 200 OK in 53ms (Views: 0.3ms | ActiveRecord: 17.8ms)
2020-11-06T06:17:55 [D|app|41a7aa50] Cache write: _session_id:76ea8c3ac65cba9d00f31c49de1233ba ({:expires_in=>86400})
2020-11-06T06:18:15 [I|app|0b11240f] Started GET "/discovered_hosts/host-70106fa9dda0/edit?utf8=%E2%9C%93&host%5Bhostgroup_id%5D=33&host%5Borganization_id%5D=3&host%5Blocation_id%5D=2&quick_submit=Create+Host" for 10.124.245.64 at 2020-11-06 06:18:15 -0500
2020-11-06T06:18:15 [D|app|0b11240f] Cache read: _session_id:76ea8c3ac65cba9d00f31c49de1233ba
2020-11-06T06:18:15 [I|app|0b11240f] Processing by DiscoveredHostsController#edit as HTML
2020-11-06T06:18:15 [I|app|0b11240f]   Parameters: {"utf8"=>"✓", "host"=>{"hostgroup_id"=>"33", "organization_id"=>"3", "location_id"=>"2"}, "quick_submit"=>"Create Host", "id"=>"host-70106fa9dda0"}
2020-11-06T06:18:15 [D|app|0b11240f] Cache read: settings/authorize_login_delegation
2020-11-06T06:18:15 [D|app|0b11240f] Cache fetch_hit: settings/authorize_login_delegation
2020-11-06T06:18:15 [D|app|0b11240f] Cache read: settings/authorize_login_delegation
2020-11-06T06:18:15 [D|app|0b11240f] Cache fetch_hit: settings/authorize_login_delegation
2020-11-06T06:18:15 [D|app|0b11240f] Cache read: settings/idle_timeout
2020-11-06T06:18:15 [D|app|0b11240f] Cache fetch_hit: settings/idle_timeout
2020-11-06T06:18:15 [D|app|0b11240f] Cache delete: views/tabs_and_title_records-23
2020-11-06T06:18:15 [D|tax|0b11240f] Current location set to Default Location
2020-11-06T06:18:15 [D|tax|0b11240f] Current organization set to none
2020-11-06T06:18:15 [D|app|0b11240f] Cache read: settings/append_domain_name_for_hosts
2020-11-06T06:18:15 [D|app|0b11240f] Cache fetch_hit: settings/append_domain_name_for_hosts
2020-11-06T06:18:15 [D|app|0b11240f] Cache read: settings/append_domain_name_for_hosts
2020-11-06T06:18:15 [D|app|0b11240f] Cache fetch_hit: settings/append_domain_name_for_hosts
2020-11-06T06:18:15 [D|app|0b11240f] Cache read: settings/append_domain_name_for_hosts
2020-11-06T06:18:15 [D|app|0b11240f] Cache fetch_hit: settings/append_domain_name_for_hosts
2020-11-06T06:18:15 [D|app|0b11240f] Cache read: settings/bmc_credentials_accessible
2020-11-06T06:18:15 [D|app|0b11240f] Cache fetch_hit: settings/bmc_credentials_accessible
2020-11-06T06:18:15 [I|app|0f279ea3] Started GET "/notification_recipients" for 10.124.245.64 at 2020-11-06 06:18:15 -0500
2020-11-06T06:18:15 [D|app|0f279ea3] Cache read: _session_id:76ea8c3ac65cba9d00f31c49de1233ba
2020-11-06T06:18:15 [I|app|0f279ea3] Processing by NotificationRecipientsController#index as JSON
2020-11-06T06:18:15 [D|app|0f279ea3] Cache delete: views/tabs_and_title_records-23
2020-11-06T06:18:15 [D|tax|0f279ea3] Current location set to Default Location
2020-11-06T06:18:15 [D|tax|0f279ea3] Current organization set to none
2020-11-06T06:18:15 [D|app|0f279ea3] Cache read: notification-23
2020-11-06T06:18:15 [D|not|0f279ea3] Cache Hit: notification, reading cache for notification-23
2020-11-06T06:18:15 [D|app|0f279ea3] Body: {"notifications":[{"id":722,"seen":false,"level":"info","text":"One or more hosts have been discovered","created_at":"2020-11-06T11:16:46.185Z","group":"Hosts","actions":{"links":[{"href":"/discovered_hosts","title":"Details"}]}}]}
2020-11-06T06:18:15 [I|app|0f279ea3] Completed 200 OK in 53ms (Views: 0.3ms | ActiveRecord: 18.0ms)
2020-11-06T06:18:15 [D|app|0f279ea3] Cache write: _session_id:76ea8c3ac65cba9d00f31c49de1233ba ({:expires_in=>86400})
2020-11-06T06:18:15 [D|tax|0b11240f] Current organization set to none
2020-11-06T06:18:15 [D|tax|0b11240f] Current location set to none
2020-11-06T06:18:15 [D|app|0b11240f] Cache read: settings/discovery_clean_facts
2020-11-06T06:18:15 [D|app|0b11240f] Cache generate: settings/discovery_clean_facts
2020-11-06T06:18:15 [D|app|0b11240f] Cache write: settings/discovery_clean_facts
2020-11-06T06:18:15 [D|app|0b11240f] Cache read: settings/token_duration
2020-11-06T06:18:15 [D|app|0b11240f] Cache generate: settings/token_duration
2020-11-06T06:18:15 [D|app|0b11240f] Cache write: settings/token_duration
2020-11-06T06:18:15 [D|app|0b11240f] Cache read: settings/token_duration
2020-11-06T06:18:15 [D|app|0b11240f] Cache fetch_hit: settings/token_duration
2020-11-06T06:18:15 [D|app|0b11240f] Building token starting with 841fd0 SHA256:7ae9470d7b6adfd4199af5a7b58e71c00a709ea56f5f20866abd92eb57433dd7
2020-11-06T06:18:15 [D|app|0b11240f] Not suggesting IP Address for 10.122.75.128/26 as IPAM is disabled
2020-11-06T06:18:15 [D|app|0b11240f] Cache read: settings/append_domain_name_for_hosts
2020-11-06T06:18:15 [D|app|0b11240f] Cache fetch_hit: settings/append_domain_name_for_hosts
2020-11-06T06:18:15 [D|app|0b11240f] Cache read: settings/append_domain_name_for_hosts
2020-11-06T06:18:15 [D|app|0b11240f] Cache fetch_hit: settings/append_domain_name_for_hosts
2020-11-06T06:18:15 [D|app|0b11240f] Cache read: settings/append_domain_name_for_hosts
2020-11-06T06:18:15 [D|app|0b11240f] Cache fetch_hit: settings/append_domain_name_for_hosts
2020-11-06T06:18:15 [D|app|0b11240f] Cache read: settings/append_domain_name_for_hosts
2020-11-06T06:18:15 [D|app|0b11240f] Cache fetch_hit: settings/append_domain_name_for_hosts
2020-11-06T06:18:15 [D|app|0b11240f] Cache read: settings/token_duration
2020-11-06T06:18:15 [D|app|0b11240f] Cache fetch_hit: settings/token_duration
2020-11-06T06:18:15 [D|app|0b11240f] Cache read: settings/token_duration
2020-11-06T06:18:15 [D|app|0b11240f] Cache fetch_hit: settings/token_duration
2020-11-06T06:18:16 [D|app|0b11240f] Cache read: settings/token_duration
2020-11-06T06:18:16 [D|app|0b11240f] Cache fetch_hit: settings/token_duration
2020-11-06T06:18:16 [D|app|0b11240f] Cache read: settings/token_duration
2020-11-06T06:18:16 [D|app|0b11240f] Cache fetch_hit: settings/token_duration
2020-11-06T06:18:16 [D|tax|0b11240f] Current organization set to MSE
2020-11-06T06:18:16 [D|tax|0b11240f] Current location set to Default Location
2020-11-06T06:18:16 [D|tax|0b11240f] Current location set to none
2020-11-06T06:18:16 [D|tax|0b11240f] Current organization set to none
2020-11-06T06:18:16 [D|app|0b11240f] Enqueued task 'Deploy TFTP PXELinux config for host-70106fa9dda0.bloomberg.com' to 'Host::Managed Main' queue
2020-11-06T06:18:16 [D|app|0b11240f] Enqueued task 'Deploy TFTP PXEGrub2 config for host-70106fa9dda0.bloomberg.com' to 'Host::Managed Main' queue
2020-11-06T06:18:16 [D|app|0b11240f] Enqueued task 'Deploy TFTP PXEGrub config for host-70106fa9dda0.bloomberg.com' to 'Host::Managed Main' queue
2020-11-06T06:18:16 [D|app|0b11240f] Enqueued task 'Deploy TFTP iPXE config for host-70106fa9dda0.bloomberg.com' to 'Host::Managed Main' queue
2020-11-06T06:18:16 [D|app|0b11240f] Enqueued task 'Fetch TFTP boot files for host-70106fa9dda0.bloomberg.com' to 'Host::Managed Main' queue

...

2020-11-06T06:18:17 [I|app|0b11240f] Processed 5 tasks from queue 'Host::Managed Main', completed 5/5
2020-11-06T06:18:17 [D|app|0b11240f] Task 'Deploy TFTP PXELinux config for host-70106fa9dda0.bloomberg.com' *completed*
2020-11-06T06:18:17 [D|app|0b11240f] Task 'Deploy TFTP PXEGrub2 config for host-70106fa9dda0.bloomberg.com' *completed*
2020-11-06T06:18:17 [D|app|0b11240f] Task 'Deploy TFTP PXEGrub config for host-70106fa9dda0.bloomberg.com' *completed*
2020-11-06T06:18:17 [D|app|0b11240f] Task 'Deploy TFTP iPXE config for host-70106fa9dda0.bloomberg.com' *completed*
2020-11-06T06:18:17 [D|app|0b11240f] Task 'Fetch TFTP boot files for host-70106fa9dda0.bloomberg.com' *completed*
2020-11-06T06:18:17 [I|aud|0b11240f] Nic::Managed (8265) update event on name host-70106fa9dda0, host-70106fa9dda0.bloomberg.com
2020-11-06T06:18:17 [I|aud|0b11240f] Nic::Managed (8265) update event on domain_id , 2
2020-11-06T06:18:17 [D|app|0b11240f] Cache read: settings/append_domain_name_for_hosts
2020-11-06T06:18:17 [D|app|0b11240f] Cache fetch_hit: settings/append_domain_name_for_hosts
2020-11-06T06:18:17 [D|app|0b11240f] Cache read: settings/append_domain_name_for_hosts
2020-11-06T06:18:17 [D|app|0b11240f] Cache fetch_hit: settings/append_domain_name_for_hosts
2020-11-06T06:18:17 [D|app|0b11240f] Cache read: settings/host_owner
2020-11-06T06:18:17 [D|app|0b11240f] Cache generate: settings/host_owner
2020-11-06T06:18:17 [D|app|0b11240f] Cache write: settings/host_owner
2020-11-06T06:18:17 [D|app|0b11240f] Cache read: settings/token_duration
2020-11-06T06:18:17 [D|app|0b11240f] Cache fetch_hit: settings/token_duration
2020-11-06T06:18:17 [D|app|0b11240f] Cache read: settings/token_duration
2020-11-06T06:18:17 [D|app|0b11240f] Cache fetch_hit: settings/token_duration
2020-11-06T06:18:17 [D|app|0b11240f] Building token starting with 21579a SHA256:8d980aedf553fb7ff22d5cc503f9b4df3402a7f9b730ee9aba2be551b6042824

The token via /unattended/provision?hostname=host-70106fa9dda0.bloomberg.com is 21579af8-ab72-410a-978e-a008c1fd3e30.

To confirm, I deployed all updates to token.rb, I didn’t see any issues from doing this. my diff was:

--- a/templates/default/fmsrv/usr/share/foreman/app/models/concerns/hostext/token.rb
+++ b/templates/default/fmsrv/usr/share/foreman/app/models/concerns/hostext/token.rb
@@ -8,7 +8,7 @@ module Hostext
       scope :for_token, ->(token) { joins(:token).where(:tokens => { :value => token }).where("expires >= ?", Time.now.utc.to_s(:db)).select('hosts.*') }
       scope :for_token_when_built, ->(token) { joins(:token).where(:tokens => { :value => token }).select('hosts.*') }
 
-      after_validation :refresh_token_on_build
+      before_validation :refresh_token_on_build
     end
 
     # Sets and expire provisioning tokens
@@ -26,17 +26,23 @@ module Hostext
 
     def set_token
       return unless Setting[:token_duration] != 0
-      self.build_token(:value => Foreman.uuid,
-                       :expires => Time.now.utc + Setting[:token_duration].minutes)
+      value = Foreman.uuid
+      expires =  Time.now.utc + Setting[:token_duration].minutes
+      logger.debug do
+        # improve debugging options but avoid leaking the token via logs
+        sha = Digest::SHA256.hexdigest(value)
+        "Building token starting with #{value[0..5]} SHA256:#{sha}"
+      end
+      build_token(:value => value, :expires => expires)
     end
 
     def token_expired?
-      return false unless Setting[:token_duration] != 0 && self.token.present?
-      self.token.expires < Time.now.utc
+      return false unless Setting[:token_duration] != 0 && token.present?
+      token.expires < Time.now.utc
     end
 
     def expire_token
-      self.token.delete if self.token.present?
+      token.delete if token.present?
     end
   end
 end

stiege · November 6, 2020, 12:08pm

To confirm plugins:

If I understand correctly, our hooks would be here:

fmsrv1-rr-084 /root # ls -l /usr/share/foreman/config/hooks/
total 0

lzap · November 10, 2020, 3:34pm

Okay so obviously token is generated twice for some reason, put this into the set_token method to see stacktrace to find out what triggers this twice:

Rails.logger.warn caller.join.("\n")

I hope there is not a typo.

stiege · November 11, 2020, 1:26pm

Just a small typo in there, close enough!

Rails.logger.warn caller.join("\n")

# grep 'Building token' production.log -A 10
2020-11-11T08:17:19 [D|app|ec979309] Building token starting with 8ee1f7 SHA256:f04c66c6e08824b62f82f76194830488ecccae614444c870ec3e4b4766a27918
2020-11-11T08:17:19 [W|app|ec979309] /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_discovery-16.0.1/app/services/foreman_discovery/host_converter.rb:35:in `set_build_clean_facts'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_discovery-16.0.1/app/controllers/discovered_hosts_controller.rb:80:in `block in perform_update'
/usr/share/foreman/app/models/taxonomy.rb:61:in `block in no_taxonomy_scope'
/usr/share/foreman/app/models/taxonomy.rb:68:in `block (2 levels) in as_taxonomy'
/usr/share/foreman/app/models/concerns/foreman/thread_session.rb:195:in `as_location'
/usr/share/foreman/app/models/taxonomy.rb:67:in `block in as_taxonomy'
/usr/share/foreman/app/models/concerns/foreman/thread_session.rb:154:in `as_org'
/usr/share/foreman/app/models/taxonomy.rb:66:in `as_taxonomy'
/usr/share/foreman/app/models/taxonomy.rb:60:in `no_taxonomy_scope'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_discovery-16.0.1/app/controllers/discovered_hosts_controller.rb:79:in `perform_update'
--
2020-11-11T08:17:21 [D|app|ec979309] Building token starting with a38514 SHA256:654f86c55bb3c69bfc6cdfbc875fcdd4810b3853032bd6e98ad66da09fd871ca
2020-11-11T08:17:21 [W|app|ec979309] /usr/share/foreman/app/models/concerns/hostext/token.rb:23:in `refresh_token_on_build'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:426:in `block in make_lambda'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:198:in `block (2 levels) in halting'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:606:in `block (2 levels) in default_terminator'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:605:in `catch'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:605:in `block in default_terminator'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:199:in `block in halting'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:513:in `block in invoke_before'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:513:in `each'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:513:in `invoke_before'

So the foreman_discovery plugin is the issue? I think we required this, I’ll have to chase up what the thinking was but thanks for your help so far, I’d be interested in if you think there’s something obvious we’ve done wrong if you’re familiar with the plugin.

lzap · November 12, 2020, 9:54am

Yeah, I wrote this. I need to debug this locally, I don’t understand why it gets called in the first instance.

In the meantime, try to comment out host.build = true in host_converter.rb in the discovery plugin. This was added because some users were often trying ot provision without build flag. I thought it won’t hurt. Weird thing is this was added years ago and it works for most of us.

stiege · November 13, 2020, 5:01pm

So first we tried commenting out the host.build = true; I didn’t understand the outcome at all (3 tokens generated?). It might be worth us repeating:

fmsrv1-rr-084 /root # grep 'Building token' /var/log/foreman/production.log-20201113 -A 10
2020-11-12T13:22:15 [D|app|8236d2be] Building token starting with 5aee61 SHA256:46307459fc70de825c26b3eae85143333da3428bb5645697512754347b680c02
2020-11-12T13:22:15 [W|app|8236d2be] /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_discovery-16.0.1/app/services/foreman_discovery/host_converter.rb:35:in `set_build_clean_facts'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_discovery-16.0.1/app/services/foreman_discovery/host_converter.rb:17:in `to_managed'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_discovery-16.0.1/app/controllers/discovered_hosts_controller.rb:71:in `update'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/abstract_controller/base.rb:194:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/rendering.rb:30:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/foreman/controller/timezone.rb:10:in `set_timezone'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
--
2020-11-12T13:22:15 [D|app|8236d2be] Building token starting with 91a548 SHA256:89af165c99b4f902010109b8b1b536d91468a882a9582b194375531a78d966ea
2020-11-12T13:22:15 [W|app|8236d2be] /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_discovery-16.0.1/app/services/foreman_discovery/host_converter.rb:35:in `set_build_clean_facts'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_discovery-16.0.1/app/controllers/discovered_hosts_controller.rb:80:in `block in perform_update'
/usr/share/foreman/app/models/taxonomy.rb:61:in `block in no_taxonomy_scope'
/usr/share/foreman/app/models/taxonomy.rb:68:in `block (2 levels) in as_taxonomy'
/usr/share/foreman/app/models/concerns/foreman/thread_session.rb:195:in `as_location'
/usr/share/foreman/app/models/taxonomy.rb:67:in `block in as_taxonomy'
/usr/share/foreman/app/models/concerns/foreman/thread_session.rb:154:in `as_org'
/usr/share/foreman/app/models/taxonomy.rb:66:in `as_taxonomy'
/usr/share/foreman/app/models/taxonomy.rb:60:in `no_taxonomy_scope'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_discovery-16.0.1/app/controllers/discovered_hosts_controller.rb:79:in `perform_update'
--
2020-11-12T13:22:16 [D|app|8236d2be] Building token starting with 5cc62a SHA256:083efce6798517528855e61b6ced22391cff57221c2cbdad5b566bc05a615548
2020-11-12T13:22:16 [W|app|8236d2be] /usr/share/foreman/app/models/concerns/hostext/token.rb:23:in `refresh_token_on_build'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:426:in `block in make_lambda'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:198:in `block (2 levels) in halting'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:606:in `block (2 levels) in default_terminator'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:605:in `catch'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:605:in `block in default_terminator'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:199:in `block in halting'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:513:in `block in invoke_before'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:513:in `each'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:513:in `invoke_before'

I then uncommented that and instead commented out the host.set_token that occurs immediately after. This initially looked promising:

fmsrv1-rr-084 /root # grep 'Building token' /var/log/foreman/production.log
2020-11-13T10:19:47 [D|app|58934201] Building token starting with daf166 SHA256:6be975eef9b41db0f31bffcb45adb63eb337208696ba2cb4d64ca4fbe4a37110

However this led to no token present in the generated pxelinux file:

LABEL installer
  MENU LABEL MSE Kickstart PXELinux
  KERNEL http://bbrepo.bdns.bloomberg.com/pub/repos/rhel/rhel-server-7.6-x86_64//images/pxeboot/vmlinuz
  APPEND initrd=http://bbrepo.bdns.bloomberg.com/pub/repos/rhel/rhel-server-7.6-x86_64//images/pxeboot/initrd.img ks=http://fmspx1.bdns.bloomberg.com:8440/unattended/provision    BOOTIF=70:10:6f:a9:dd:a0
  IPAPPEND 2

I’m not sure if either/which of these is closer to working correctly. We could also try commenting out both lines but it doesn’t seem to me that would improve the situation.

I am a little suspicious of the comment near the top of host_converter.rb and just wanted to point it out. Of course I’m not familiar enough with the internals to figure if this is entirely relevant:

# Converts discovered host to managed host **without** uptading the database.

That’s as far as we got, cheers.

lzap · November 18, 2020, 10:10am

That comment actually reminded me something - the whole token generation is part of the before_validation callback which is actually called several times but the token should not be stored as it uses build_ method. So it gets generated multiple times but it’s only stored once the record is saved.

Did you try the enforce token patch? You only need to change this line here: https://github.com/theforeman/foreman_discovery/pull/514/files#diff-3a8c72d1844787742e90efa23835005076b9ca97c7e798557773f6916c8067dbR35

The rest (the helper script) you can ignore.

stiege · November 18, 2020, 10:43am

Yes, we’ve been running with host.set_token since

To confirm our current self.set_clean_build_facts:

  def self.set_build_clean_facts(host)
    # fact cleaning
    if Setting['discovery_clean_facts']
      # clean all facts except those starting with "discovery_"
      host.define_singleton_method(:clear_facts) do
          keep_ids = FactValue.where("host_id = #{host.id}").joins(:fact_name).where("fact_names.name like 'discovery_%'").pluck("fact_values.id")
          FactValue.where("host_id = #{host.id} and id not in (?)", keep_ids).delete_all
      end
    else
      # clean no facts (default behavior)
      host.define_singleton_method(:clear_facts) {}
    end
    # set build flag  and call set_token explicitly to force new one
    host.build = true
    host.set_token
  end

lzap · November 18, 2020, 10:58am

Ok so my patch cannot work, the record is not being saved at this stage. I don’t know why you see this while it works on my end, anyway drop all the changes (you can keep logging) and do this:

This is a different approach - it schedules an extra orchestration step which forces token regeneration. That should help.