Problem:
When we have more servers from one provision doing auto discovery Foreman got stucked. In logs I can see a lot of messages like:
2021-03-05T18:39:00 [I|app|411b38ab] Locking discovered host 3c:ec:ef:22:fb:9f in subnet internal provisioning subnet SGP via pxegrub
_discovery template
2021-03-05T18:39:00 [W|app|411b38ab] Could not find a provider for mac-3cecef22fb9f. Providers returned {"MediumProviders::Default"=>
["Operating system was not set for host 'mac-3cecef22fb9f'", " medium was not set for host 'mac-3cecef22fb9f'", "Invalid medium '' fo
r ''", "Invalid architecture '' for ''"]}
2021-03-05T18:39:00 [I|app|2dcdce32] Locking discovered host 3c:ec:ef:21:e1:15 in subnet internal provisioning subnet SGP via templa
te
2021-03-05T18:39:00 [W|app|2dcdce32] Template '' provided by setting 'discovery_ipxe_lock_template' does not exist, not locking
2021-03-05T18:39:00 [I|app|411b38ab] Locking discovered host 3c:ec:ef:22:fb:9f in subnet internal provisioning subnet SGP via templa
te
2021-03-05T18:39:00 [W|app|411b38ab] Template '' provided by setting 'discovery_ipxe_lock_template' does not exist, not locking
2021-03-05T18:39:01 [I|app|2dcdce32] Match found for host mac-3cecef21e115 (12532) rule SGP (30)
2021-03-05T18:39:01 [W|app|2dcdce32] Could not find a provider for mac-3cecef21e115. Providers returned {"MediumProviders::Default"=>
["Operating system was not set for host 'mac-3cecef21e115'", " medium was not set for host 'mac-3cecef21e115'", "Invalid medium '' fo
r ''", "Invalid architecture '' for ''"]}
2021-03-05T18:39:01 [I|app|411b38ab] Match found for host mac-3cecef22fb9f (12568) rule SGP (30)
2021-03-05T18:39:01 [W|app|411b38ab] Could not find a provider for mac-3cecef22fb9f. Providers returned {"MediumProviders::Default"=>
["Operating system was not set for host 'mac-3cecef22fb9f'", " medium was not set for host 'mac-3cecef22fb9f'", "Invalid medium '' fo
r ''", "Invalid architecture '' for ''"]}
2021-03-05T18:39:15 [W|app|f1d170ed] Not queueing Host::Managed: ["Name has already been taken"]
2021-03-05T18:39:15 [W|app|f1d170ed] Not queueing Host::Managed: ["Name has already been taken"]
2021-03-05T18:39:15 [W|app|f1d170ed] Not queueing Host::Managed: ["Name has already been taken"]
2021-03-05T18:39:15 [W|app|f1d170ed] Not queueing Discovery reboot: Name has already been taken
2021-03-05T18:39:15 [E|app|f1d170ed] Auto provisioning failed: Name has already been taken
Expected outcome:
That new servers are autoprovision. And if there is no luck it does not effect whole foreman instance, which doesn’t respond over web GUI or even to hammer commands.
Foreman and Proxy versions:
Master - 2.2.2
Proxies - 2.2.3
Foreman and Proxy plugin versions:
master foreman_discovery - 16.1.2
proxy discovery - 1.0.3
Distribution and version:
Debian 10
Other relevant data:
| /usr/share/foreman/app/controllers/api/base_controller.rb:147:in `process_resource_error'
| /usr/share/foreman/app/controllers/api/base_controller.rb:167:in `process_response'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/foreman_discovery-16.1.2/app/controllers/api/v2/discovered_hosts_controller.rb:110:in `f
acts'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_actio
n'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/abstract_controller/base.rb:195:in `process_action'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_controller/metal/rendering.rb:30:in `process_action'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:112:in `block in run_callbacks'
| /usr/share/foreman/app/controllers/api/v2/base_controller.rb:181:in `disable_json_root'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
| /usr/share/foreman/app/controllers/concerns/foreman/controller/timezone.rb:10:in `set_timezone'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
| /usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
| /usr/share/foreman/app/controllers/concerns/foreman/controller/topbar_sweeper.rb:12:in `set_topbar_sweeper_controller'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/audited-4.9.0/lib/audited/sweeper.rb:14:in `around'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/audited-4.9.0/lib/audited/sweeper.rb:14:in `around'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:139:in `run_callbacks'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/abstract_controller/callbacks.rb:41:in `process_action'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_controller/metal/rescue.rb:22:in `process_action'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_controller/metal/instrumentation.rb:33:in `block in process_action'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.4/lib/active_support/notifications.rb:180:in `block in instrument'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.4/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.4/lib/active_support/notifications.rb:180:in `instrument'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_controller/metal/params_wrapper.rb:245:in `process_action'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-6.0.3.4/lib/active_record/railties/controller_runtime.rb:27:in `process_action'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/abstract_controller/base.rb:136:in `process'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionview-6.0.3.4/lib/action_view/rendering.rb:39:in `process'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_controller/metal.rb:190:in `dispatch'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_controller/metal.rb:254:in `dispatch'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/routing/route_set.rb:33:in `serve'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/routing/mapper.rb:18:in `block in <class:Constraints>'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/routing/mapper.rb:48:in `serve'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/journey/router.rb:49:in `block in serve'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/journey/router.rb:32:in `each'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/journey/router.rb:32:in `serve'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/routing/route_set.rb:834:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-dsl-2.3.0/lib/apipie_dsl/static_dispatcher.rb:67:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.18/lib/apipie/static_dispatcher.rb:66:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.18/lib/apipie/extractor/recorder.rb:137:in `call'
| /usr/share/foreman/lib/foreman/middleware/telemetry.rb:10:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.18/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
| /usr/share/foreman/lib/foreman/middleware/catch_json_parse_errors.rb:9:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/conditional_get.rb:40:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
| /usr/share/foreman/lib/foreman/middleware/logging_context_session.rb:22:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/cookies.rb:648:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:101:in `run_callbacks'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/actionable_exceptions.rb:18:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/debug_exceptions.rb:32:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/railties-6.0.3.4/lib/rails/rack/logger.rb:37:in `call_app'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/railties-6.0.3.4/lib/rails/rack/logger.rb:28:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/sprockets-rails-3.2.2/lib/sprockets/rails/quiet_assets.rb:13:in `call'
| /usr/share/foreman/lib/foreman/middleware/logging_context_request.rb:11:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/request_id.rb:27:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.4/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/executor.rb:14:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/static.rb:126:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/host_authorization.rb:76:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/secure_headers-6.3.1/lib/secure_headers/middleware.rb:11:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/railties-6.0.3.4/lib/rails/engine.rb:527:in `call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/railties-6.0.3.4/lib/rails/railtie.rb:190:in `public_send'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/railties-6.0.3.4/lib/rails/railtie.rb:190:in `method_missing'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/urlmap.rb:74:in `block in call'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `each'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `call'
| /usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:107:in `process_request'
| /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:157:in `accept_and_process_next_request'
| /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:110:in `main_loop'
| /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler.rb:416:in `block (3 levels) in start_threads'
| /usr/lib/ruby/vendor_ruby/phusion_passenger/utils.rb:113:in `block in create_thread_and_abort_on_exception'
| /usr/share/foreman/vendor/ruby/2.5.0/gems/logging-2.3.0/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2021-03-05T18:39:15 [I|app|f1d170ed] Completed 422 Unprocessable Entity in 60241ms (Views: 0.2ms | ActiveRecord: 9547.6ms | Allocations: 29898076)
2021-03-05T18:39:15 [I|app|4ece9351] Started POST "/api/v2/discovered_hosts/facts" for 89.187.162.3 at 2021-03-05 18:39:15 +0000
2021-03-05T18:39:15 [I|app|4ece9351] Processing by Api::V2::DiscoveredHostsController#facts as JSON
2021-03-05T18:39:15 [I|app|4ece9351] Parameters: {"facts"=>"[FILTERED]", "apiv"=>"v2", "discovered_host"=>{"facts"=>"[FILTERED]"}}
2021-03-05T18:39:15 [W|app|4ece9351] One or more existing managed hosts found: mac-3cecef21e2cb.10gbps.io/3c:ec:ef:21:e2:cb
2021-03-05T18:39:15 [I|app|4ece9351] Import facts for 'mac-3cecef21e2cb' completed. Added: 0, Updated: 0, Deleted 0 facts
2021-03-05T18:39:15 [I|app|4ece9351] Detected IPv4 subnet: internal provisioning subnet SGP with taxonomy ["Default Organization", "d
p_test"]/["Default Location"]
2021-03-05T18:39:15 [I|app|4ece9351] Assigned location: Default Location
2021-03-05T18:39:15 [I|app|4ece9351] Assigned organization: Default Organization
2021-03-05T18:39:16 [I|app|4ece9351] Locking discovered host 3c:ec:ef:21:e2:cb in subnet internal provisioning subnet SGP via pxegrub
2_discovery template
2021-03-05T18:39:16 [W|app|4ece9351] Could not find a provider for mac-3cecef21e2cb. Providers returned {"MediumProviders::Default"=>
["Operating system was not set for host 'mac-3cecef21e2cb'", " medium was not set for host 'mac-3cecef21e2cb'", "Invalid medium '' fo
r ''", "Invalid architecture '' for ''"]}
2021-03-05T18:39:16 [I|app|4ece9351] Locking discovered host 3c:ec:ef:21:e2:cb in subnet internal provisioning subnet SGP via PXELinu
x default discovery template
2021-03-05T18:39:16 [W|app|4ece9351] Could not find a provider for mac-3cecef21e2cb. Providers returned {"MediumProviders::Default"=>
["Operating system was not set for host 'mac-3cecef21e2cb'", " medium was not set for host 'mac-3cecef21e2cb'", "Invalid medium '' fo
r ''", "Invalid architecture '' for ''"]}
On proxy there are frequently repeating logs like:
021-03-05T18:39:16 4ece9351 [I] Started POST /tftp/PXEGrub2/3c:ec:ef:21:e2:cb
2021-03-05T18:39:16 4ece9351 [I] Finished POST /tftp/PXEGrub2/3c:ec:ef:21:e2:cb with 200 (0.88 ms)
2021-03-05T18:39:17 4ece9351 [I] Started POST /tftp/PXELinux/3c:ec:ef:21:e2:cb
2021-03-05T18:39:17 4ece9351 [I] Finished POST /tftp/PXELinux/3c:ec:ef:21:e2:cb with 200 (0.98 ms)
2021-03-05T18:39:18 4ece9351 [I] Started POST /tftp/PXEGrub/3c:ec:ef:21:e2:cb
2021-03-05T18:39:18 4ece9351 [I] Finished POST /tftp/PXEGrub/3c:ec:ef:21:e2:cb with 200 (0.87 ms)```